Re: query logging of prepared statements

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