Re: statement logging / extended query protocol issues - Mailing list pgsql-hackers

From Oliver Jowett
Subject Re: statement logging / extended query protocol issues
Date
Msg-id 4324CFBA.3080805@opencloud.com
Whole thread Raw
In response to Re: statement logging / extended query protocol issues  (Simon Riggs <simon@2ndquadrant.com>)
Responses Re: statement logging / extended query protocol issues
List pgsql-hackers
Simon Riggs wrote:

> Are we sure there is just 3 cases?

I haven't exhaustively checked, but I think those are the main cases.

> Even if case (3) is not that common, I still want to know it is
> occurring, to see what effect or overhead it has.

I don't want it to be more verbose than the other cases when I set
log_statement = all.

> We'll only see the output for case (3) when someone has programmed
> things that way by using setFetchSize.

Can we put extra output in this case into log_statement = verbose only
please?

> (1)
> jdbc parse
> jdbc bind
> jdbc execute
> LOG:  statement: SELECT * from pg_proc

> Notice that the parse of the unnamed statement does *not* now generate a
> log record.

What about the syntax error case?

> (2)
> jdbc parse S_1
> LOG:  statement: PREPARE S_1 AS SELECT * from pg_proc
> (perhaps this should be logged at BIND time, just like the
> optimization?)
> 
> jdbc bind S_1
> jdbc execute
> LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]

I do not like logging queries that the driver never sent (the driver
sends neither PREPARE nor EXECUTE).

I also don't see why it's useful to log the statement and portal names.

Can we reword this to what I suggested previously?
 LOG: parse statement: SELECT * from pg_proc LOG: execute statement: SELECT * from pg_proc

> (3)
> jdbc prepare S_2
> LOG:  statement: PREPARE S_2 AS SELECT * from pg_proc
> 
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG:  statement: EXECUTE C_2 ROWS 42 [PREPARE:  SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute, execution halts at 49 rows for this set
> of bind parameters
> LOG:  statement: FETCH C_2 ROWS 7

Again I do not like logging synthetic queries that the driver never sent
(PREPARE / EXECUTE / FETCH). BTW, if you do it this way, you could get
the bizarre "PREPARE S_2 AS PREPARE xyz AS SELECT .." result if the
application used PREPARE itself.

I think that logging the second and subsequent Executes is not normally
useful and shouldn't happen when log_statement = all. In that case you
don't need to log the portal name either.

So for the normal case:
 LOG: parse statement: SELECT * from pg_proc LOG: execute statement: SELECT * from pg_proc

and for the verbose case perhaps something like:
 LOG: parse statement: SELECT * from pg_proc LOG: execute statement (C_2, 42 rows): SELECT * from pg_proc LOG: fetch
statementresults (C_2, 7 rows)
 

-O


pgsql-hackers by date:

Previous
From: Gavin Sherry
Date:
Subject: Re: Spinlocks, yet again: a new test case
Next
From: Tom Lane
Date:
Subject: Re: Spinlocks, yet again: analysis and proposed patches