Re: statement logging / extended query protocol issues

Oliver Jowett wrote:
> 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.

I think it is more verbose because no FETCH is logged in this type of
prepare/execute.  The goal, I think, is for these type of queries to
look as similar to normal PREPARE/EXECUTE and DECLARE/FETCH as possible.

> > 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?

We don't have a log_statement = verbose mode.

> > (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?

Good point, but when do we parse?  Could you set log_min_error_statement
to error?  I don't think that would work either.

> > (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

The problem here is that scripts that look for "LOG: statement:" would
now need to look for additional words at the start.  It also makes this
type of prepare/execute look different in the logs, while internally it
is quite similar.

> > (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 statement results (C_2, 7 rows)

We don't have a verbose case.  Why should it look different from
client-side stuff? 

--  Bruce Momjian                        |  http://candle.pha.pa.us pgman@candle.pha.pa.us               |  (610)
359-1001+  If your life is a hard drive,     |  13 Roberts Road +  Christ can be your backup.        |  Newtown Square,
Pennsylvania19073