Thread: 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