On Wed, Jul 13, 2005 at 09:52:20AM +0800, Christopher Kings-Lynne wrote:
> The 8.0.2 jdbc driver uses real prepared statements instead of faked
> ones. The problem is the new protocol (that the 8.0.2 driver users) has
> a bug where protocol-prepared queries don't get logged properly.
> I don't know if it's been fixed...
It's not in 8.0.3, but I was having the same problems with DBD::Pg so
I backported some of it and also changed the code so that it listed the
values of the bind parameters, so you get something like
LOG: statement: SELECT sr.name,sr.seq_region_id, sr.length, 1 FROM seq_region
sr WHERE sr.name = $1 AND sr.coord_system_id = $2
LOG: binding: "dbdpg_2" with 2 parameters
LOG: bind "dbdpg_2" $1 = "20"
LOG: bind "dbdpg_2" $2 = "1"
LOG: statement: EXECUTE [PREPARE: SELECT sr.name,sr.seq_region_id,
sr.length, 1 FROM seq_region sr WHERE sr.name = $1 AND sr.coord_system_id = $2]
LOG: duration: 0.164 ms
I've attached a patch in case anyone finds it useful.
-Mark
*** postgresql-8.0.3/src/backend/tcop/postgres.c 2005-07-13
09:42:04.997669193 +0100
--- postgresql-8.0.3/src/backend/tcop/postgres.c 2005-07-13
09:34:24.618195580 +0100
***************
*** 1370,1375 ****
--- 1370,1378 ----
else
portal = CreatePortal(portal_name, false, false);
+ if (log_statement == LOGSTMT_ALL)
+ ereport(LOG, (errmsg("binding: \"%s\" with %d parameters", stmt_name,
numParams)));
+
/*
* Fetch parameters, if any, and store in the portal's memory context.
*
***************
*** 1428,1433 ****
--- 1431,1439 ----
* grotty but is a big win when dealing
with very
* large parameter strings.
*/
+ if (log_statement == LOGSTMT_ALL)
+ ereport(LOG, (errmsg("bind \"%s\" $%d
= \"%s\"", stmt_name, i+1, pvalue)));
+
pbuf.data = (char *) pvalue;
pbuf.maxlen = plength + 1;
pbuf.len = plength;
***************
*** 1578,1583 ****
--- 1584,1593 ----
bool is_trans_exit = false;
bool completed;
char completionTag[COMPLETION_TAG_BUFSIZE];
+ struct timeval start_t, stop_t;
+ bool save_log_duration = log_duration;
+ int save_log_min_duration_statement =
log_min_duration_statement;
+ bool save_log_statement_stats = log_statement_stats;
/* Adjust destination to tell printtup.c what to do */
dest = whereToSendOutput;
***************
*** 1614,1619 ****
--- 1624,1647 ----
set_ps_display(portal->commandTag);
+ /*
+ * We use save_log_* so "SET log_duration = true" and "SET
+ * log_min_duration_statement = true" don't report incorrect time
+ * because gettimeofday() wasn't called. Similarly,
+ * log_statement_stats has to be captured once.
+ */
+ if (save_log_duration || save_log_min_duration_statement != -1)
+ gettimeofday(&start_t, NULL);
+
+ if (save_log_statement_stats)
+ 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);
/* Check for transaction-control commands */
***************
*** 1708,1713 ****
--- 1736,1785 ----
pq_putemptymessage('s');
}
+ /*
+ * Combine processing here as we need to calculate the query duration
+ * in both instances.
+ */
+ if (save_log_duration || save_log_min_duration_statement != -1)
+ {
+ long usecs;
+
+ gettimeofday(&stop_t, NULL);
+ if (stop_t.tv_usec < start_t.tv_usec)
+ {
+ stop_t.tv_sec--;
+ stop_t.tv_usec += 1000000;
+ }
+ usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
+ (long) (stop_t.tv_usec - start_t.tv_usec);
+
+ /* Only print duration if we previously printed the statement.
*/
+ if (log_statement == LOGSTMT_ALL && save_log_duration)
+ ereport(LOG,
+ (errmsg("duration: %ld.%03ld ms",
+ (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)));
+
+ /*
+ * Output a duration_statement to the log if the query has
+ * exceeded the min duration, or if we are to print all
durations.
+ */
+ 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)
+ ShowUsage("QUERY STATISTICS");
+
debug_query_string = NULL;
}
---------------------------(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
