Re: statement logging / extended query protocol issues

Your patch has been added to the PostgreSQL unapplied patches list at:
http://momjian.postgresql.org/cgi-bin/pgpatches

It will be applied as soon as one of the PostgreSQL committers reviews
and approves it.

---------------------------------------------------------------------------


Simon Riggs wrote:
> On Thu, 2005-09-08 at 13:14 +1200, Oliver Jowett wrote:
> > Simon Riggs wrote:
> > > Oliver, would it be possible to show a simplified call sequence and what
> > > you would like to see logged for each call? 
> 
> These are good: Maybe it should even be in the docs for the driver?
> It would be good if it could be written as a test within the driver, so
> we can expand it and test the logging.
> 
> > The JDBC driver generates one of these sequences:
> > 
> > (1)
> >   Parse (unnamed statement) "SELECT 1"
> >   Bind (unnamed statement -> unnamed portal)
> >   Execute (unnamed portal, no row limit)
> > 
> > (2)
> >   Parse (named statement S_1) "SELECT 1"
> >   repeatedly:
> >     Bind (named statement S_1 -> unnamed portal)
> >     Execute (unnamed portal, no row limit)
> > 
> > (3)
> >   Parse (named statement S_2) "SELECT 1"
> >   repeatedly:
> >     Bind (named statement S_2 -> named portal C_2)
> >     repeatedly:
> >       Execute (named portal C_2, row limit 42)
> 
> Are we sure there is just 3 cases?
> 
> > Ideal output is:
> > 
> > (1)  LOG: statement: SELECT 1
> > 
> > (2)  LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> > 
> > (3)  LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> > 
> > In case (3), that's one log line per repeat of the outer loop,
> > regardless of how many Executes are sent in the inner loop.
> 
> > Note that case (1) is the most common case for application queries via
> > the JDBC driver, and case (2) is the most common for internally
> > generated statements like BEGIN.
> 
> Even if case (3) is not that common, I still want to know it is
> occurring, to see what effect or overhead it has.
> 
> > As you can see from the output I'd like, I don't think that synthesizing
> > FETCH / EXECUTE queries that don't actually exist [is a]
> > useful thing to do, at least at the Joe Average User
> > level.
> 
> Your original point at the top of this thread was valid: a get-next-rows
> shouldn't look like a re-execute. We can call it something else if you
> like, as long as we can tell the difference.
> 
> We'll only see the output for case (3) when someone has programmed
> things that way by using setFetchSize.
> 
> > Also note that the JDBC driver doesn't exercise all of the extended
> > protocol -- for example it's possible to re-Bind the same unnamed
> > statement repeatedly, or have multiple Executes on an unnamed portal
> > with a row limit, but the JDBC driver never does that.
> 
> I agree there's not much gained from displaying the BIND statement as it
> is. I argued previously against including the BIND parameters. Now I
> would say we should either include them or leave out BIND altogether.
> 
> Here's a new suggestion and patch that brings together
> - Oliver and Simon's wish to remove BIND from normal logging
> - Oliver's suggestion to remove the PREPARE logging for unnamed
> statements, which would otherwise double-up logging for case(1)
> - Bruce and Simon's view to keep some form of FETCH logging
> - Tom's view to rationalise the way ROWS is mentioned
> 
> (lines beginning jdbc don't show in the log, but are just there to show
> clearly the time sequence of activities and what gets subsequently
> logged)
> 
> (1)
> >   Parse (unnamed statement) "SELECT * from pg_proc"
> >   Bind (unnamed statement -> unnamed portal)
> >   Execute (unnamed portal, no row limit)
> 
> (1)
> jdbc parse
> jdbc bind
> jdbc execute
> LOG:  statement: SELECT * from pg_proc
> 
> jdbc parse
> jdbc bind
> jdbc execute
> LOG:  statement: SELECT * from pg_proc
> 
> 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.
> 
> (2)
> >   Parse (named statement S_1) "SELECT * from pg_proc"
> >   repeatedly:
> >     Bind (named statement S_1 -> unnamed portal)
> >     Execute (unnamed portal, no row limit)
> 
> (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]
> 
> jdbc bind S_1
> jdbc execute
> LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]
> 
> jdbc bind S_1
> jdbc execute
> LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]
> 
> 
> ...I wonder if <unnamed> just confuses what is going on here? I've left
> it in for now, but suggest that we take that out again?
> 
> (3)
> >   Parse (named statement S_2) "SELECT * from pg_proc"
> >   repeatedly:
> >     Bind (named statement S_2 -> named portal C_2)
> >     repeatedly:
> >       Execute (named portal C_2, row limit 42)
> 
> (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
> 
> 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
> LOG:  statement: FETCH C_2 ROWS 42
> jdbc next (after cache has run out on 84th row)
> v3 protocol sends E for Execute, execution halts at 95 rows for this set
> of bind parameters
> LOG:  statement: FETCH C_2 ROWS 11
> 
> Note: log_min_duration_statement logs after execution so can give
> accurate row counts of what was retrieved for first execute and
> subsequent fetches. In that case we log using the word ROWS.
> log_statement=all logs before execution and so only knows what the
> maximum number of rows requested is, not what the actual number of rows
> retrieved will be. In that case we log using the word MAXROWS.
> ROWS and MAXROWS are *not* mentioned unless we specifically set max_rows
> in the execute request using the v3 protocol.
> 
> If we agree, I'd suggest this goes into the docs...
> 
> I've not written a comprehensive test program that covers all of the
> different settings of v2/v3, named/unnamed, allrows/restricted rows,
> log_statement=all/log_min_duration_statement. I'm not sure that will fit
> within the existing test framework. So this patch is still prototype.
> 
> Comments?
> 
> Best Regards, Simon Riggs

[ Attachment, skipping... ]

> 
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

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