Re: query logging of prepared statements

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