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.

There is no attempt to log parameters, since these are not often
required for performance analysis.

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.

Some code has been duplicated with this patch; refactoring and cleanup
can be performed should anybody desire it.

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.

Best Regards, Simon Riggs



---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://archives.postgresql.org

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.

Good.

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

I don't understand what you are saying above. How is the logging
different from what we currently have in terms of the GUC variables?

> There is no attempt to log parameters, since these are not often
> required for performance analysis.

Makes sense.

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

Unlikely for 8.0.X as current behavior is not a bug nor has it been
complained about alot.

> Some code has been duplicated with this patch; refactoring and cleanup
> can be performed should anybody desire it.

Yes, is it worth factoring it out? I am thinking not.

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

Amazing something in writing was required for this. Was this their
idea, or yours, or based on their previous litigation over the "GIF"
patent?

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

---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to majordomo@postgresql.org

On Wed, 2005-05-11 at 22:15 -0400, Bruce Momjian wrote:
> > 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.
>
> Amazing something in writing was required for this.

Think of it as due credit and politeness, rather than a requirement.

Best Regards, Simon Riggs



---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?

http://archives.postgresql.org

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

Bruce Momjian <pgman@candle.pha.pa.us> writes:
> 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.

You could use portal->sourceText whenever that isn't null; it should be
the querystring that the portal was created by.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > 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.
>
> You could use portal->sourceText whenever that isn't null; it should be
> the querystring that the portal was created by.

Interesting, but right now we don't display the query using EXECUTE:

test=> SET client_min_messages='log';
SET
test=> SET log_statement = 'all';
SET
test=> PREPARE xx AS SELECT 1;
LOG: statement: PREPARE xx AS SELECT 1;
PREPARE
test=> EXECUTE xx;
LOG: statement: EXECUTE xx;
?column?
----------
1
(1 row)

test=>

so I assume client-side EXECUTE shouldn't either. Do people want it
displayed? The patch actually hard-codes the word EXECUTE after
"statement:" and prints the portal name:

LOG: statement: EXECUTE xx

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

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

On Sat, 2005-05-14 at 16:55 -0400, Bruce Momjian wrote:
> 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);

Yes, that looks wrong. Thanks for your diligence. I'm sorry that you've
had to both spot an error and recode for it, I was expecting to do that.

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

I used the debug_query_string because even in the EXEC case it is set,
so that the SQL statement appears correctly in pg_stat_activity. It may
look wrong, but it is there.

That part, at least, is correct, since I have used the patch in tuning.

Perhaps it is only there when stats_command_string is set?

Setting the SQL string to be only EXECUTE portal_name makes the log
output almost useless for query tuning, so please reconsider that.
Perhaps you could include both the portal name and the SQL statement?

Best Regards, Simon Riggs


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

Simon Riggs <simon@2ndquadrant.com> writes:
> On Sat, 2005-05-14 at 16:55 -0400, Bruce Momjian wrote:
>> One thing you did was to log debug_query_string, but I don't see how
>> that could be the right value.

> I used the debug_query_string because even in the EXEC case it is set,
> so that the SQL statement appears correctly in pg_stat_activity. It may
> look wrong, but it is there.

The reason debug_query_string is the right thing is that
exec_execute_message is careful to set it up...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: the planner will ignore your desire to choose an index scan if your
joining column's datatypes do not match

On Sun, 2005-05-15 at 13:29 -0400, Tom Lane wrote:
> Simon Riggs <simon@2ndquadrant.com> writes:
> > On Sat, 2005-05-14 at 16:55 -0400, Bruce Momjian wrote:
> >> One thing you did was to log debug_query_string, but I don't see how
> >> that could be the right value.
>
> > I used the debug_query_string because even in the EXEC case it is set,
> > so that the SQL statement appears correctly in pg_stat_activity. It may
> > look wrong, but it is there.
>
> The reason debug_query_string is the right thing is that
> exec_execute_message is careful to set it up...

I realised that luck played little part and that some foreward planning
had gone into it.

Somebody out there is too modest to point out how often it is that I
only dot the "I"s they have left for me...

Best Regards, Simon Riggs


---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
(send "unregister YourEmailAddressHere" to majordomo@postgresql.org)

On Sun, May 15, 2005 at 10:48:47PM +0100, Simon Riggs wrote:

> Somebody out there is too modest to point out how often it is that I
> only dot the "I"s they have left for me...

Funny you mention it. Remember that shared row locking project of mine
-- guess what. The idea comes from Bruce (his phantom Xids, remember
those?) The infrastructure comes from Tom (who coded our current
pg_clog mechanism) and Manfred Koizar (who abstracted it in a nice way.)

Only thing I did was add some bugs on top of it all. Tom then corrected
them all -- and hurray, we have a new feature!

--
Alvaro Herrera (<alvherre[a]surnet.cl>)
"This is a foot just waiting to be shot" (Andrew Dunstan)

---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster