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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073