From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: Arthur Zakirov <a.zakirov@postgrespro.ru>
Cc: pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Date: Thu, 4 Apr 2019 15:07:04 -0300
Message-ID: <20190404180704.GA31569@alvherre.pgsql> (raw)
In-Reply-To: <20190304183150.GK29584@telsasoft.com>
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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: alvherre@2ndquadrant.com, pryzby@telsasoft.com, a.zakirov@postgrespro.ru
Subject: Re: query logging of prepared statements
In-Reply-To: <20190404180704.GA31569@alvherre.pgsql>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox