Re: query logging of prepared statements - Mailing list pgsql-hackers
From | Alvaro Herrera |
---|---|
Subject | Re: query logging of prepared statements |
Date | |
Msg-id | 20190404180704.GA31569@alvherre.pgsql Whole thread Raw |
In response to | Re: query logging of prepared statements (Justin Pryzby <pryzby@telsasoft.com>) |
Responses |
Re: query logging of prepared statements
Re: query logging of prepared statements |
List | pgsql-hackers |
On 2019-Mar-04, Justin Pryzby wrote: > Thanks for reviewing. I'm also interested in discussion about whether this > change is undesirable for someone else for some reason ? For me, the existing > output seems duplicative and "denormalized". :) Some digging turned up that the function you're removing was added by commit 893632be4e17. The commit message mentions output for testlibpq3, so I ran that against a patched server. With log_min_duration_statement=0 I get this, which looks good: 2019-04-04 14:59:15.529 -03 [31723] LOG: duration: 0.108 ms statement: SET search_path = testlibpq3 2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.303 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1 2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.231 ms bind <unnamed> 2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = 'joe''s place' 2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.016 ms execute <unnamed> 2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = 'joe''s place' 2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.096 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.053 ms bind <unnamed> 2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = '2' 2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.007 ms execute <unnamed> 2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = '2' An unpatched server emits this: 2019-04-04 15:03:01.176 -03 [1165] LOG: duration: 0.163 ms statement: SET search_path = testlibpq3 2019-04-04 15:03:01.176 -03 [1165] LOG: duration: 0.475 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1 2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.403 ms bind <unnamed>: SELECT * FROM test1 WHERE t = $1 2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = 'joe''s place' 2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.028 ms execute <unnamed>: SELECT * FROM test1 WHERE t = $1 2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = 'joe''s place' 2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.177 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.096 ms bind <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = '2' 2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.014 ms execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = '2' Note that with your patch we no longer get the statement in the "bind" and "execute" lines, which seems good; that was far too noisy. However, turning duration logging off and using log_statement=all, this is what I get: 2019-04-04 14:58:42.564 -03 [31685] LOG: statement: SET search_path = testlibpq3 2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed> 2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = 'joe''s place' 2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed> 2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = '2' which does not look good -- the statement is nowhere to be seen. The commit message quotes this as desirable output: LOG: statement: execute <unnamed>: SELECT * FROM test1 WHERE t = $1 DETAIL: parameters: $1 = 'joe''s place' LOG: statement: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 DETAIL: parameters: $1 = '2' which is approximately what I get with an unpatched server: 2019-04-04 15:04:25.718 -03 [1235] LOG: statement: SET search_path = testlibpq3 2019-04-04 15:04:25.719 -03 [1235] LOG: execute <unnamed>: SELECT * FROM test1 WHERE t = $1 2019-04-04 15:04:25.719 -03 [1235] DETAIL: parameters: $1 = 'joe''s place' 2019-04-04 15:04:25.720 -03 [1235] LOG: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 2019-04-04 15:04:25.720 -03 [1235] DETAIL: parameters: $1 = '2' So I think this needs a bit more work. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
pgsql-hackers by date: