Simon Riggs wrote:
> Following patch is a minor addition to postgres.c that allows the two
> existing statement logging techniques to work with V3 exec. This then
> allows statement logging with PostgreSQL 8.0+ for JDBC and other V3
> connection types.
>
> The rationale of this patch is to add functionality without modifying
> existing behaviour. There is expected to be some difficulty with
> log_statement producing a log line at both parse and exec, but some may
> find that useful. Since there are two ways of producing statement
> logging with duration times, setting log_min_duration_statement=0 will
> avoid the logging of statements for both parse and exec. For many this
> method is already the preferred way of logging statement performance
> stats.
Uh, I am confused by this. Your code test is:
+ if ((log_statement == LOGSTMT_ALL && save_log_duration) ||
+ save_log_min_duration_statement)
+ gettimeofday(&start_t, NULL);
First, log_min_duration_statement == -1 turns off logging. Your test
would enable it for -1. Also, you added "log_statement == LOGSTMT_ALL",
but don't have a similar test lower down where gettimeofday is used, so
I don't understand its usage here, or why it would be used in this
place. The original test is:
+ if (save_log_duration || save_log_min_duration_statement != -1)
+ gettimeofday(&start_t, NULL);
> There is no attempt to log parameters, since these are not often
> required for performance analysis.
OK.
> The enclosed patch has been tested against cvstip.
>
> I also see this as a backpatch onto 8.0, since it prevents statements
> from being logged as described in the manual and prevents effective
> performance tuning. It has not been tested against 8.0.2, though was
> originally written against 8.0.1 and is believed to apply cleanly.
I don't think it should be backpatched. This is a behavior changes that
can be seen as a feature addition.
> Some code has been duplicated with this patch; refactoring and cleanup
> can be performed should anybody desire it.
Not sure it is worth it considering how many variables are involved.
> The patch was produced quickly to assist tuning efforts during
> Scalability & Performance benchmarking of PostgreSQL 8.0 carried out at
> Unisys Corporation's Mission Viejo engineering laboratory. The
> development was sponsored by Unisys Corporation and the patch has now
> been donated to the PostgreSQL community under the standard
> PostgreSQL/BSD licence. Approval for release of this code has been given
> in writing to me by the Director, Open Runtime Products, Unisys on April
> 8, 2005.
I have made a new version of the patch using your patch only as a guide.
I copied the sections you suggested. It compiles fine but I would like
someone to test that it actually works for client-side EXECUTE. I don't
have a test setup for that here.
One thing you did was to log debug_query_string, but I don't see how
that could be the right value. I assume it would be empty in a
client-side execute, or be the previous query. I instead used "EXECUTE
portal_name" because that is what we are passed from the client.
--
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, Pennsylvania 19073
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.443
diff -c -c -r1.443 postgres.c
*** src/backend/tcop/postgres.c 21 Apr 2005 19:18:13 -0000 1.443
--- src/backend/tcop/postgres.c 14 May 2005 20:22:17 -0000
***************
*** 1011,1017 ****
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 (statement_logged && save_log_duration)
--- 1011,1018 ----
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 (statement_logged && save_log_duration)
***************
*** 1579,1584 ****
--- 1580,1590 ----
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;
***************
*** 1615,1620 ****
--- 1621,1646 ----
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();
+
+ statement_logged = false;
+ if (log_statement == LOGSTMT_ALL)
+ {
+ ereport(LOG,
+ (errmsg("statement: EXECUTE %s", portal_name)));
+ statement_logged = true;
+ }
+
BeginCommand(portal->commandTag, dest);
/* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1735,1783 ----
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 (statement_logged && 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",
+ (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)));
+ }
+
+ if (save_log_statement_stats)
+ ShowUsage("QUERY STATISTICS");
+
debug_query_string = NULL;
}
---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?
http://archives.postgresql.org
