Обсуждение: Re: query logging of prepared statements
Sigh, resending to -hackers for real. On Fri, Feb 08, 2019 at 07:29:53AM -0600, Justin Pryzby wrote: > A couple months ago, I implemented prepared statements for PyGreSQL. While > updating our application in advance of their release with that feature, I > noticed that our query logs were several times larger. Previously sent to -general (and quoted fully below), resending to -hackers with patch. https://www.postgresql.org/message-id/20190208132953.GF29720%40telsasoft.com https://www.postgresql.org/docs/current/runtime-config-logging.html I propose that the prepared statement associated with an EXECUTE should be included in log "DETAIL" only when log_error_verbosity=VERBOSE, for both SQL EXECUTE and PQexecPrepared (if at all). I'd like to be able to continue logging DETAIL (including bind parameters), so want like to avoid setting "TERSE" just to avoid redundant messages. (It occurs to me that the GUC should probably stick to its existing documented behavior rather than be extended, which suggests that the duplicitive portions of the logs should simply be removed, rather than conditionalized. Let me know what you think). With attached patch, I'm not sure if !*portal_name && !portal->prepStmtName would catch cases other than PQexecParams (?) Compare unpatched server to patched server to patched server with log_error_verbosity=verbose. |$ psql postgres -xtc "SET log_error_verbosity=default;SET log_statement='all'; SET client_min_messages=log" -c "PREPAREq AS SELECT 2" -c "EXECUTE q" |SET |LOG: statement: PREPARE q AS SELECT 2 |PREPARE |LOG: statement: EXECUTE q |DETAIL: prepare: PREPARE q AS SELECT 2 |?column? | 2 |$ PGHOST=/tmp PGPORT=5678 psql postgres -xtc "SET log_error_verbosity=default;SET log_statement='all'; SET client_min_messages=log"-c "PREPARE q AS SELECT 2" -c "EXECUTE q" |SET |LOG: statement: PREPARE q AS SELECT 2 |PREPARE |LOG: statement: EXECUTE q |?column? | 2 |$ PGHOST=/tmp PGPORT=5678 psql postgres -xtc "SET log_error_verbosity=verbose;SET log_statement='all'; SET client_min_messages=log"-c "PREPARE q AS SELECT 2" -c "EXECUTE q" |SET |LOG: statement: PREPARE q AS SELECT 2 |PREPARE |LOG: statement: EXECUTE q |DETAIL: prepare: PREPARE q AS SELECT 2 |?column? | 2 For PQexecPrepared library call: |$ xPGPORT=5678 xPGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres');d.query('SET client_min_messages=log; SET log_error_verbosity=default; SET log_statement=\"all\"'); d.query('SELECT1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])" |LOG: statement: SELECT 1; PREPARE q AS SELECT $1 |LOG: execute q: SELECT 1; PREPARE q AS SELECT $1 |DETAIL: parameters: $1 = '1' |LOG: execute <unnamed>: SELECT $1 |DETAIL: parameters: $1 = '2' |$ PGPORT=5678 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres');d.query('SET client_min_messages=log; SET log_error_verbosity=default; SET log_statement=\"all\"'); d.query('SELECT1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])" |LOG: statement: SELECT 1; PREPARE q AS SELECT $1 |LOG: execute q |DETAIL: parameters: $1 = '1' |LOG: execute <unnamed>: SELECT $1 |DETAIL: parameters: $1 = '2' |$ PGPORT=5678 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres');d.query('SET client_min_messages=log; SET log_error_verbosity=verbose; SET log_statement=\"all\"'); d.query('SELECT1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])" |LOG: statement: SELECT 1; PREPARE q AS SELECT $1 |LOG: execute q: SELECT 1; PREPARE q AS SELECT $1 |DETAIL: parameters: $1 = '1' |LOG: execute <unnamed>: SELECT $1 |DETAIL: parameters: $1 = '2' Also, I noticed that if the statement was prepared using SQL PREPARE (rather than PQprepare), and if it used simple query with multiple commands, they're all included in the log, like this when executed with PQexecPrepared: |LOG: execute q: SET log_error_verbosity=verbose; SET client_min_messages=log; PREPARE q AS SELECT $1 And looks like this for SQL EXECUTE: |[pryzbyj@telsasoft-db postgresql]$ psql postgres -txc "SET client_min_messages=log;SELECT 1;PREPARE q AS SELECT 2" -c "EXECUTEq" |PREPARE |LOG: statement: EXECUTE q |DETAIL: prepare: SET client_min_messages=log;SELECT 1;PREPARE q AS SELECT 2 |?column? | 2 On Fri, Feb 08, 2019 at 07:29:53AM -0600, Justin Pryzby wrote: > A couple months ago, I implemented prepared statements for PyGreSQL. While > updating our application in advance of their release with that feature, I > noticed that our query logs were several times larger. > > With non-prepared statements, we logged to CSV: > |message | SELECT 1 > > With SQL EXECUTE, we log: > |message | statement: EXECUTE sqlex(2); > |detail | prepare: prepare sqlex AS SELECT $1; > > With PQexecPrepared, we would log: > |message | execute qq: PREPARE qq AS SELECT $1 > |detail | parameters: $1 = '3' > > For comparison, with PQexecParams, the logs I see look like this (apparently > the "unnamed" prepared statement is used behind the scenes): > |message | execute <unnamed>: SELECT [...] > > It's not clear to me why it'd be desirable for the previous PREPARE to be > additionally logged during every execution, instead of just its name (in > "message") and params (in "detail"). (Actually, I had to triple check that it > wasn't somehow executing a prepared statement which itself created a prepared > statement...) > > For us, the performance benefit is to minimize the overhead (mostly in pygres) > of many INSERTs into append-only tables. It's not great that a feature > intended to improve performance is causing 2x more log volume to be written. > > Also, it seems odd that for SQL EXECUTE, the PREPARE is shown in "detail", but > for the library call, it's shown in "message". > > I found: > |commit bc24d5b97673c365f19be21f83acca3c184cf1a7 > |Author: Bruce Momjian <bruce@momjian.us> > |Date: Tue Aug 29 02:11:30 2006 +0000 > | > | Now bind displays prepare as detail, and execute displays prepare and > | optionally bind. I re-added the "statement:" label so people will > | understand why the line is being printed (it is log_*statement > | behavior). > | > | Use single quotes for bind values, instead of double quotes, and double > | literal single quotes in bind values (and document that). I also made > | use of the DETAIL line to have much cleaner output. > > and: > > |commit c8961bf1ce0b51019db31c5572dac18b664e02f1 > |Author: Bruce Momjian <bruce@momjian.us> > |Date: Fri Aug 4 18:53:46 2006 +0000 > | > | Improve logging of protocol-level prepared statements. > > Justin
Вложения
On Fri, Feb 15, 2019 at 08:57:04AM -0600, Justin Pryzby wrote: > I propose that the prepared statement associated with an EXECUTE should be > included in log "DETAIL" only when log_error_verbosity=VERBOSE, for both SQL > EXECUTE and PQexecPrepared (if at all). I'd like to be able to continue > logging DETAIL (including bind parameters), so want like to avoid setting > "TERSE" just to avoid redundant messages. (It occurs to me that the GUC should > probably stick to its existing documented behavior rather than be extended, > which suggests that the duplicitive portions of the logs should simply be > removed, rather than conditionalized. Let me know what you think). I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than making such logs conditional on log_error_verbosity=VERBOSE, since log_error_verbosity is documented to control whether these are output: DETAIL/HINT/QUERY/CONTEXT/SQLSTATE. For SQL EXECUTE, excluding "detail" seems reasonable (perhaps for log_error_verbosity<VERBOSE). But for PQexecPrepared, the v1 patch made log_error_verbosity also control the "message" output, which is outside the scope of its documented behavior. |message | execute qq: PREPARE qq AS SELECT $1 |detail | parameters: $1 = '3' https://www.postgresql.org/docs/current/runtime-config-logging.html |Controls the amount of detail written in the server log for each message that |is logged. Valid values are TERSE, DEFAULT, and VERBOSE, each adding more |fields to displayed messages. TERSE excludes the logging of DETAIL, HINT, |QUERY, and CONTEXT error information. VERBOSE output includes the SQLSTATE |error code (see also Appendix A) and the source code file name, function name, |and line number that generated the error. Only superusers can change this |setting. As I mentioned in my original message, it seems odd that for SQL EXECUTE, the PREPARE is shown in "detail", but for the library call, it's shown in "message". This patch resolves that inconsistency by showing it in neither.
Вложения
Hello Justin, On 27.02.2019 21:06, Justin Pryzby wrote: > I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than > making such logs conditional on log_error_verbosity=VERBOSE, since > log_error_verbosity is documented to control whether these are output: > DETAIL/HINT/QUERY/CONTEXT/SQLSTATE. I looked the patch. I got interesting result with different parameters. With log_statement='all' and log_min_duration_statement='0' I get: =# execute test_ins(3); LOG: statement: execute test_ins(3); LOG: duration: 17.283 ms But with log_statement='none' and log_min_duration_statement='0' I get: =# execute test_ins(3); LOG: duration: 8.439 ms statement: execute test_ins(3); DETAIL: prepare: prepare test_ins (int) as insert into test values ($1); Is it intended? In the second result I got the query details. -- Arthur Zakirov Postgres Professional: http://www.postgrespro.com Russian Postgres Company
On Mon, Mar 04, 2019 at 06:53:31PM +0300, Arthur Zakirov wrote:
> Hello Justin,
>
> On 27.02.2019 21:06, Justin Pryzby wrote:
> >I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
> >making such logs conditional on log_error_verbosity=VERBOSE, since
> >log_error_verbosity is documented to control whether these are output:
> >DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.
> I looked the patch. I got interesting result with different parameters.
>
> But with log_statement='none' and log_min_duration_statement='0' I get:
>
> =# execute test_ins(3);
> LOG: duration: 8.439 ms statement: execute test_ins(3);
> DETAIL: prepare: prepare test_ins (int) as
> insert into test values ($1);
>
> Is it intended? In the second result I got the query details.
It wasn't intentional. Find attached v3 patch which handles that case,
by removing the 2nd call to errdetail_execute() ; since it's otherwise unused,
so remove that function entirely.
|postgres=# execute test_ins(3);
|2019-03-04 11:56:15.997 EST [4044] LOG: duration: 0.637 ms statement: execute test_ins(3);
I also fixed a 2nd behavior using library call pqExecPrepared with
log_min_duration_statement=0.
It was logging:
|LOG: duration: 0.264 ms statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: duration: 0.027 ms bind q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: duration: 0.006 ms execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
But now logs:
PGPORT=5679 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg;
d=pg.DB('postgres');d.query('SET client_min_messages=error; SET log_error_verbosity=default; SET
log_min_duration_statement=0;SET log_statement=\"none\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1');
d.query_prepared('q',[1])"
|LOG: duration: 0.479 ms statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: duration: 0.045 ms bind q
|DETAIL: parameters: $1 = '1'
|LOG: duration: 0.008 ms execute q
|DETAIL: parameters: $1 = '1'
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". :)
Justin
Вложения
On 04.03.2019 21:31, Justin Pryzby wrote: > It wasn't intentional. Find attached v3 patch which handles that case, > by removing the 2nd call to errdetail_execute() ; since it's otherwise unused, > so remove that function entirely. Thank you. > 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". :) I perfectly understand your use case. I agree, it is duplicated. But I think some people may want to see it at every EXECUTE, if they don't want to grep for the prepared statement body which was logged earlier. I think it would be good to give possibility to configure this behavior. At first version of your patch you relied on log_error_verbosity GUC. I'm not sure that this variables is suitable for configuring visibility of prepared statement body in logs, because it sets more general behavior. Maybe it would be better to introduce some new GUC variable if the community don't mind. -- Arthur Zakirov Postgres Professional: http://www.postgrespro.com Russian Postgres Company
Hi Justin, On 3/5/19 2:30 PM, Arthur Zakirov wrote: > On 04.03.2019 21:31, Justin Pryzby wrote: >> It wasn't intentional. Find attached v3 patch which handles that case, >> by removing the 2nd call to errdetail_execute() ; since it's otherwise >> unused, >> so remove that function entirely. > > Thank you. > >> 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". :) > > I perfectly understand your use case. I agree, it is duplicated. But I > think some people may want to see it at every EXECUTE, if they don't > want to grep for the prepared statement body which was logged earlier. > > I think it would be good to give possibility to configure this behavior. > At first version of your patch you relied on log_error_verbosity GUC. > I'm not sure that this variables is suitable for configuring visibility > of prepared statement body in logs, because it sets more general > behavior. Maybe it would be better to introduce some new GUC variable if > the community don't mind. Thoughts on this? Regards, -- -David david@pgmasters.net
Hi, On Wed, Mar 20, 2019 at 02:46:00PM +0400, David Steele wrote: > >I perfectly understand your use case. I agree, it is duplicated. But I > >think some people may want to see it at every EXECUTE, if they don't want > >to grep for the prepared statement body which was logged earlier. > > > >I think it would be good to give possibility to configure this behavior. > >At first version of your patch you relied on log_error_verbosity GUC. I'm > >not sure that this variables is suitable for configuring visibility of > >prepared statement body in logs, because it sets more general behavior. > >Maybe it would be better to introduce some new GUC variable if the > >community don't mind. > > Thoughts on this? I'm happy to make the behavior configurable, but I'm having trouble believing many people would want a GUC added for this. But I'd be interested to hear input on whether it should be configurable, or whether the original "verbose" logging is desirable to anyone. This is mostly tangential, but since writing the original patch, I considered the possibility of a logging GUC which is scales better than log_* booleans: https://www.postgresql.org/message-id/20190316122422.GR6030%40telsasoft.com If that idea were desirable, there could be a logging_bit to enable verbose logging of prepared statements. Justin
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
On 2019-Apr-04, Alvaro Herrera wrote:
> 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'
With this patch (pretty much equivalent to reinstanting the
errdetail_execute for that line),
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dbc7b797c6e..fd73d5e9951 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2056,7 +2056,6 @@ exec_execute_message(const char *portal_name, long max_rows)
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : ""),
- errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
}
I get what seems to be pretty much what is wanted for this case:
2019-04-04 15:18:16.817 -03 [4559] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:18:16.819 -03 [4559] LOG: execute <unnamed>
2019-04-04 15:18:16.819 -03 [4559] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:18:16.819 -03 [4559] STATEMENT: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:18:16.820 -03 [4559] LOG: execute <unnamed>
2019-04-04 15:18:16.820 -03 [4559] DETAIL: parameters: $1 = '2'
2019-04-04 15:18:16.820 -03 [4559] STATEMENT: SELECT * FROM test1 WHERE i = $1::int4
However, by setting both log_statement=all and
log_min_duration_statement=0 and that patch (I also added %l to
log_line_prefix), I get this:
2019-04-04 15:23:45 -03 [5208-1] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:23:45 -03 [5208-2] LOG: duration: 0.441 ms
2019-04-04 15:23:45 -03 [5208-3] LOG: duration: 1.127 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:23:45 -03 [5208-4] LOG: duration: 0.789 ms bind <unnamed>
2019-04-04 15:23:45 -03 [5208-5] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:23:45 -03 [5208-6] LOG: execute <unnamed>
2019-04-04 15:23:45 -03 [5208-7] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:23:45 -03 [5208-8] STATEMENT: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:23:45 -03 [5208-9] LOG: duration: 0.088 ms
2019-04-04 15:23:45 -03 [5208-10] LOG: duration: 0.363 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:23:45 -03 [5208-11] LOG: duration: 0.206 ms bind <unnamed>
2019-04-04 15:23:45 -03 [5208-12] DETAIL: parameters: $1 = '2'
2019-04-04 15:23:45 -03 [5208-13] LOG: execute <unnamed>
2019-04-04 15:23:45 -03 [5208-14] DETAIL: parameters: $1 = '2'
2019-04-04 15:23:45 -03 [5208-15] STATEMENT: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:23:45 -03 [5208-16] LOG: duration: 0.053 ms
Note that line 5208-8 is duplicative of 5208-3.
I think we could improve on this by setting a "logged" flag in the
portal; if the Parse logs the statement, then don't include the
statement in further lines, otherwise do.
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 2019-Apr-04, Alvaro Herrera wrote:
> I think we could improve on this by setting a "logged" flag in the
> portal; if the Parse logs the statement, then don't include the
> statement in further lines, otherwise do.
Also: I think such a flag could help the case of a query that takes
long enough to execute to exceed the log_min_duration_statement, but not
long enough to parse. Right now, log_min_duration_statement=500 shows
2019-04-04 15:59:39 -03 [6353-1] LOG: duration: 2002.298 ms execute <unnamed>
2019-04-04 15:59:39 -03 [6353-2] DETAIL: parameters: $1 = 'joe''s place'
if I change the testlibpq3 query to be
"SELECT * FROM test1 WHERE t = $1 and pg_sleep(1) is not null",
Also, if you parse once and bind/execute many times, IMO the statement
should be logged exactly once. I think you could that with the flag I
propose.
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Thu, Apr 04, 2019 at 03:07:04PM -0300, Alvaro Herrera wrote: > which does not look good -- the statement is nowhere to be seen. The commit > message quotes this as desirable output: Good catch. Unnamed statements sent behind the scenes by pqExecParams weren't being logged. I specifically handled unnamed statements in my v1 patch, and tested that in 20190215145704.GW30291@telsasoft.com, but for some reason dropped that logic in v2, which was intended to only remove behavior conditional on log_error_verbosity. Previous patches also never logged pqPrepare with named prepared statements (unnamed prepared statements were handled in v1 and SQL PREPARE was handled as a simple statement). On Thu, Apr 04, 2019 at 03:26:30PM -0300, Alvaro Herrera wrote: > With this patch (pretty much equivalent to reinstanting the > errdetail_execute for that line), That means the text of the prepared statement is duplicated for each execute, which is what we're trying to avoid, no ? Attached patch promotes message to LOG in exec_parse_message. Parse is a protocol-layer message, and I think it's used by (only) pqPrepare and pqExecParams. testlibpq3 now shows: |LOG: parse <unnamed>: SELECT * FROM test1 WHERE t = $1 |LOG: execute <unnamed> |DETAIL: parameters: $1 = 'joe''s place' |LOG: parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 |LOG: execute <unnamed> |DETAIL: parameters: $1 = '2' Compare unpatched v11.2 , the text of the prepared statement was shown in "parse" phase rather than in each execute: |LOG: execute <unnamed>: SELECT * FROM test1 WHERE t = $1 |DETAIL: parameters: $1 = 'joe''s place' |LOG: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4 |DETAIL: parameters: $1 = '2' Justin
Вложения
Hi, On 2019-04-04 16:01:26 -0300, Alvaro Herrera wrote: > Also, if you parse once and bind/execute many times, IMO the statement > should be logged exactly once. I think you could that with the flag I > propose. I'm not actually sure I buy this. Consider e.g. log analysis for workloads with long-running connections. If most statements are just already prepared statements - pretty common in higher throughput apps - the query will suddenly be either far away in the logfile (thereby requiring pretty expensive analysis to figure out the corresponding statement) or even in a different logfile due to rotation. I'm sympathetic to the desire to reduce log volume, but I'm fearful this would make log analysis much harder. Searching through many gigabytes just to find the query text of the statement being executed over and over doesn't sound great. I think deduplicating the logging between bind and execute has less of that hazard. - Andres
Hi, Thanks both for thinking about this. On Fri, Apr 05, 2019 at 06:16:38PM -0700, Andres Freund wrote: > On 2019-04-04 16:01:26 -0300, Alvaro Herrera wrote: > > Also, if you parse once and bind/execute many times, IMO the statement > > should be logged exactly once. I think you could that with the flag I > > propose. > I think deduplicating the logging between bind and execute has less of > that hazard. Do you mean the bind parameters, which are only duplicated in the case of log_min_duration_statement ? I actually implemented that, using Alvaro's suggestion of a flag in the Portal, and decided that if duration is exceeded, for bind or execute, then it's likely desirable to log the params, even if it's duplicitive. Since I've been using log_statement=all, and not log_min_duration_statement, I don't have a strong opinion about it. Perhaps you're right (and perhaps I should switch to log_min_duration_statement). I'll tentately plan to withdraw the patch. Thanks, Justin
On 2019-Apr-07, Justin Pryzby wrote: > [...] Since I've been using log_statement=all, and not > log_min_duration_statement, I don't have a strong opinion about it. Ah, so your plan for this in production is to use the sample-based logging facilities, I see! Did you get Adrien a beer already? -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services