> Oliver Jowett wrote:
> > 8.1-beta1 produces some odd results with statement logging enabled when
> > the extended query protocol is used (e.g. when using the JDBC driver).
> > Repeatedly running a simple query with log_statement = 'all' produces this:
...
> > Secondly, running a query that uses portals produces output like this:
> >
> > LOG: statement: PREPARE S_3 AS SELECT * from pg_proc
> > LOG: statement: <BIND> C_4
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> > LOG: statement: EXECUTE C_4 [PREPARE: SELECT * from pg_proc]
> >
> > Comments:
> > - The <BIND> is still fairly content-free.
> > - The EXECUTEs are a bit misleading as the SELECT was actually only run
> > once (there are multiple Execute messages for the same portal). You
> > could infer that there is only one SELECT from the repeated portal name
> > and the lack of an intervening <BIND>, I suppose.
I've put together this prototype to offer more useful messages in the
situation Oliver describes.
Subsequent calls to the same portal are described as FETCHes rather than
as EXECUTEs. The portal name is still given and number of rows is
provided also.
I haven't tested this with the java program supplied, since this is a
fairly short-hack for comments. I'll correct any mistakes before
submission to patches.
Comments?
Best Regards, Simon Riggs
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.457
diff -c -c -r1.457 postgres.c
*** src/backend/tcop/postgres.c 11 Aug 2005 21:11:45 -0000 1.457
--- src/backend/tcop/postgres.c 5 Sep 2005 18:57:22 -0000
***************
*** 1681,1686 ****
--- 1681,1687 ----
bool save_log_duration = log_duration;
int save_log_min_duration_statement = log_min_duration_statement;
bool save_log_statement_stats = log_statement_stats;
+ bool subsequent_fetch = false;
/* Adjust destination to tell printtup.c what to do */
dest = whereToSendOutput;
***************
*** 1693,1698 ****
--- 1694,1707 ----
(errcode(ERRCODE_UNDEFINED_CURSOR),
errmsg("portal \"%s\" does not exist", portal_name)));
+ /*
+ * If we re-issue an Execute protocol request against an existing
+ * portal, then we are only fetching more rows rather than
+ * completely re-executing the query from the start
+ */
+ if (!portal->atEnd)
+ subsequent_fetch = true;
+
/*
* If the original query was a null string, just return
* EmptyQueryResponse.
***************
*** 1704,1710 ****
return;
}
! if (portal->sourceText)
{
debug_query_string = portal->sourceText;
pgstat_report_activity(portal->sourceText);
--- 1713,1724 ----
return;
}
! if (subsequent_fetch)
! {
! debug_query_string = "fetch message";
! pgstat_report_activity("<FETCH>");
! }
! else if (portal->sourceText)
{
debug_query_string = portal->sourceText;
pgstat_report_activity(portal->sourceText);
***************
*** 1730,1739 ****
ResetUsage();
if (log_statement == LOGSTMT_ALL)
! /* We have the portal, so output the source query. */
! ereport(LOG,
(errmsg("statement: EXECUTE %s [PREPARE: %s]", portal_name,
portal->sourceText ? portal->sourceText : "")));
BeginCommand(portal->commandTag, dest);
--- 1744,1760 ----
ResetUsage();
if (log_statement == LOGSTMT_ALL)
! {
! if (subsequent_fetch)
! ereport(LOG,
! (errmsg("statement: FETCH %s ROWS %ld", portal_name,
! max_rows)));
! else
! /* We have the portal, so output the source query. */
! ereport(LOG,
(errmsg("statement: EXECUTE %s [PREPARE: %s]", portal_name,
portal->sourceText ? portal->sourceText : "")));
+ }
BeginCommand(portal->commandTag, dest);
***************
*** 1862,1874 ****
if (save_log_min_duration_statement == 0 ||
(save_log_min_duration_statement > 0 &&
usecs >= save_log_min_duration_statement * 1000))
! ereport(LOG,
(errmsg("duration: %ld.%03ld ms statement: EXECUTE %s [PREPARE: %s]",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
(stop_t.tv_usec - start_t.tv_usec) / 1000),
(long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
portal_name,
portal->sourceText ? portal->sourceText : "")));
}
if (save_log_statement_stats)
--- 1883,1906 ----
if (save_log_min_duration_statement == 0 ||
(save_log_min_duration_statement > 0 &&
usecs >= save_log_min_duration_statement * 1000))
! {
! if (subsequent_fetch)
! ereport(LOG,
! (errmsg("duration: %ld.%03ld ms statement: FETCH %s ROWS %ld ",
! (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
! (stop_t.tv_usec - start_t.tv_usec) / 1000),
! (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! portal_name,
! max_rows)));
! else
! ereport(LOG,
(errmsg("duration: %ld.%03ld ms statement: EXECUTE %s [PREPARE: %s]",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
(stop_t.tv_usec - start_t.tv_usec) / 1000),
(long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
portal_name,
portal->sourceText ? portal->sourceText : "")));
+ }
}
if (save_log_statement_stats)
---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match
