From: Mark Rae <mrae@purplebat.com>
To: Christopher Kings-Lynne <chriskl@familyhealth.com.au>
Cc: Brent Henry <bh_pgperf@yahoo.com>
Cc: Dennis <dennis@works4me.com>
Cc: Tom Arthurs <tarthurs@jobflash.com>
Cc: pgsql-performance@postgresql.org
Subject: Re: General DB Tuning
Date: Wed, 13 Jul 2005 11:07:40 +0100
Message-ID: <20050713100740.GA27912@purplebat.com> (raw)
In-Reply-To: <42D473D4.7040500@familyhealth.com.au>
References: <20050713013630.18625.qmail@web33911.mail.mud.yahoo.com>
<42D473D4.7040500@familyhealth.com.au>
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
Attachments:timing.patch (text/plain, 3.8K) download
*** 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;
}
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: mrae@purplebat.com, chriskl@familyhealth.com.au, bh_pgperf@yahoo.com, dennis@works4me.com, tarthurs@jobflash.com
Subject: Re: General DB Tuning
In-Reply-To: <20050713100740.GA27912@purplebat.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox