Re: Exec statement logging

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

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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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

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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)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

Tom Lane wrote:
> Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)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(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

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

Simon Riggs <simon(at)2ndquadrant(dot)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

On Sun, 2005-05-15 at 13:29 -0400, Tom Lane wrote:
> Simon Riggs <simon(at)2ndquadrant(dot)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

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)

OK, new patch. I used portal->sourceText as Tom suggested, and checked
for NULL before printing. I put the original query in brackets in the
log output, patch attached.

I would like to also do this for server-side EXECUTE. I am have
attached a second version that does it by using the existing loop we use
to check for a match for log_statement patterns. The code checks for an
ExecuteStmt node, and saves the prepare string that matches the portal.
The system can't determine the actual prepare string, so I used the
debug_query_string for a server-side PREPARE --- previously it just had
a null for the prepare string. Also, rather than change the API for
pg_parse_query(), I use a global variable that I check after the
function call. Here is sample output with log_statement and
log_min_duration_statement enabled:

PREPARE xx AS SELECT 1;
LOG: statement: PREPARE xx AS SELECT 1;
LOG: duration: 1.102 ms statement: PREPARE xx AS SELECT 1;
PREPARE

EXECUTE xx;
LOG: statement: EXECUTE xx; [client PREPARE: PREPARE xx AS SELECT 1;]
LOG: duration: 0.990 ms statement: EXECUTE xx; [client PREPARE: PREPARE xx AS SELECT 1;]
?column?
----------
1
(1 row)

---------------------------------------------------------------------------

Simon Riggs wrote:
> 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
>

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> a null for the prepare string. Also, rather than change the API for
> pg_parse_query(), I use a global variable that I check after the
> function call.

This is horribly ugly and will doubtless lead to pfree crashes. What
was the point again?

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > a null for the prepare string. Also, rather than change the API for
> > pg_parse_query(), I use a global variable that I check after the
> > function call.
>
> This is horribly ugly and will doubtless lead to pfree crashes. What

Agreed, it needs work. I modified the patch to use malloc/free so that
you can always free the memory at the top of the function.

> was the point again?

Simon said that the EXECUTE is pretty useless for debugging unless we
show the prepare query. His patch shows the prepare query for
client-side prepare, but not for server side when using the
PREPARE/EXECUTE commands --- seems we should display it in both cases.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Tom Lane wrote:
> Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > a null for the prepare string. Also, rather than change the API for
> > pg_parse_query(), I use a global variable that I check after the
> > function call.
>
> This is horribly ugly and will doubtless lead to pfree crashes. What
> was the point again?

Can we change the API of pg_parse_query() to optionally return a PREPARE
string?

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
>> What was the point again?

> Simon said that the EXECUTE is pretty useless for debugging unless we
> show the prepare query. His patch shows the prepare query for
> client-side prepare, but not for server side when using the
> PREPARE/EXECUTE commands --- seems we should display it in both cases.

So we need to make sure that prepared statements always capture the
originating query string. I thought you'd done that by using
debug_query_string ... which is a bit ugly but not horrid. Why do
we need more mechanism than that?

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> >> What was the point again?
>
> > Simon said that the EXECUTE is pretty useless for debugging unless we
> > show the prepare query. His patch shows the prepare query for
> > client-side prepare, but not for server side when using the
> > PREPARE/EXECUTE commands --- seems we should display it in both cases.
>
> So we need to make sure that prepared statements always capture the
> originating query string. I thought you'd done that by using
> debug_query_string ... which is a bit ugly but not horrid. Why do
> we need more mechanism than that?

The problem is we have to pass that string down to the completion of the
query for log_min_duration_statement printing.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > > a null for the prepare string. Also, rather than change the API for
> > > pg_parse_query(), I use a global variable that I check after the
> > > function call.
> >
> > This is horribly ugly and will doubtless lead to pfree crashes. What
>
> Agreed, it needs work. I modified the patch to use malloc/free so that
> you can always free the memory at the top of the function.
>
> > was the point again?
>
> Simon said that the EXECUTE is pretty useless for debugging unless we
> show the prepare query. His patch shows the prepare query for
> client-side prepare, but not for server side when using the
> PREPARE/EXECUTE commands --- seems we should display it in both cases.

Here is an updated version of the patch. It pulls post-parse logging
out into a separate function, called log_after_parse(), so we only log
in places we want it. I added code to log client-side parse, and
prepare, were appropriate, and have the logging of client-side and
server-side execute with the PREPARE string.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Applied.

---------------------------------------------------------------------------

Bruce Momjian wrote:
> Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> writes:
> > > > a null for the prepare string. Also, rather than change the API for
> > > > pg_parse_query(), I use a global variable that I check after the
> > > > function call.
> > >
> > > This is horribly ugly and will doubtless lead to pfree crashes. What
> >
> > Agreed, it needs work. I modified the patch to use malloc/free so that
> > you can always free the memory at the top of the function.
> >
> > > was the point again?
> >
> > Simon said that the EXECUTE is pretty useless for debugging unless we
> > show the prepare query. His patch shows the prepare query for
> > client-side prepare, but not for server side when using the
> > PREPARE/EXECUTE commands --- seems we should display it in both cases.
>
> Here is an updated version of the patch. It pulls post-parse logging
> out into a separate function, called log_after_parse(), so we only log
> in places we want it. I added code to log client-side parse, and
> prepare, were appropriate, and have the logging of client-side and
> server-side execute with the PREPARE string.
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> pgman(at)candle(dot)pha(dot)pa(dot)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/commands/prepare.c
> ===================================================================
> RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
> retrieving revision 1.36
> diff -c -c -r1.36 prepare.c
> *** src/backend/commands/prepare.c 1 Jan 2005 05:43:06 -0000 1.36
> --- src/backend/commands/prepare.c 20 May 2005 14:15:12 -0000
> ***************
> *** 104,112 ****
> /* Generate plans for queries. Snapshot is already set. */
> plan_list = pg_plan_queries(query_list, NULL, false);
>
> ! /* Save the results. */
> StorePreparedStatement(stmt->name,
> ! NULL, /* text form not available */
> commandTag,
> query_list,
> plan_list,
> --- 104,115 ----
> /* Generate plans for queries. Snapshot is already set. */
> plan_list = pg_plan_queries(query_list, NULL, false);
>
> ! /*
> ! * Save the results. We don't have the query string for this PREPARE,
> ! * but we do have the string we got from the client, so use that.
> ! */
> StorePreparedStatement(stmt->name,
> ! debug_query_string,
> commandTag,
> query_list,
> plan_list,
> 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 20 May 2005 14:15:17 -0000
> ***************
> *** 82,90 ****
>
> LogStmtLevel log_statement = LOGSTMT_NONE;
>
> - /* flag indicating if the statement satisfies log_statement */
> - bool statement_logged;
> -
> /* GUC variable for maximum stack depth (measured in kilobytes) */
> int max_stack_depth = 2048;
>
> --- 82,87 ----
> ***************
> *** 152,157 ****
> --- 149,156 ----
> static int InteractiveBackend(StringInfo inBuf);
> static int SocketBackend(StringInfo inBuf);
> static int ReadCommand(StringInfo inBuf);
> + static bool log_after_parse(List *raw_parsetree_list,
> + const char *query_string, char **prepare_string);
> static void start_xact_command(void);
> static void finish_xact_command(void);
> static void SigHupHandler(SIGNAL_ARGS);
> ***************
> *** 465,538 ****
> pg_parse_query(const char *query_string)
> {
> List *raw_parsetree_list;
> - ListCell *parsetree_item;
> -
> - statement_logged = false;
> - if (log_statement == LOGSTMT_ALL)
> - {
> - ereport(LOG,
> - (errmsg("statement: %s", query_string)));
> - statement_logged = true;
> - }
>
> if (log_parser_stats)
> ResetUsage();
>
> raw_parsetree_list = raw_parser(query_string);
>
> - /* do log_statement tests for mod and ddl */
> - if (log_statement == LOGSTMT_MOD ||
> - log_statement == LOGSTMT_DDL)
> - {
> - foreach(parsetree_item, raw_parsetree_list)
> - {
> - Node *parsetree = (Node *) lfirst(parsetree_item);
> - const char *commandTag;
> -
> - if (IsA(parsetree, ExplainStmt) &&
> - ((ExplainStmt *) parsetree)->analyze)
> - parsetree = (Node *) (((ExplainStmt *) parsetree)->query);
> -
> - if (IsA(parsetree, PrepareStmt))
> - parsetree = (Node *) (((PrepareStmt *) parsetree)->query);
> -
> - if (IsA(parsetree, SelectStmt))
> - continue; /* optimization for frequent command */
> -
> - if (log_statement == LOGSTMT_MOD &&
> - (IsA(parsetree, InsertStmt) ||
> - IsA(parsetree, UpdateStmt) ||
> - IsA(parsetree, DeleteStmt) ||
> - IsA(parsetree, TruncateStmt) ||
> - (IsA(parsetree, CopyStmt) &&
> - ((CopyStmt *) parsetree)->is_from))) /* COPY FROM */
> - {
> - ereport(LOG,
> - (errmsg("statement: %s", query_string)));
> - statement_logged = true;
> - break;
> - }
> - commandTag = CreateCommandTag(parsetree);
> - if (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 ||
> - strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 ||
> - strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 ||
> - IsA(parsetree, GrantStmt) || /* GRANT or REVOKE */
> - IsA(parsetree, CommentStmt))
> - {
> - ereport(LOG,
> - (errmsg("statement: %s", query_string)));
> - statement_logged = true;
> - break;
> - }
> - }
> - }
> -
> if (log_parser_stats)
> ShowUsage("PARSER STATISTICS");
>
> return raw_parsetree_list;
> }
>
> /*
> * Given a raw parsetree (gram.y output), and optionally information about
> * types of parameter symbols ($n), perform parse analysis and rule rewriting.
> --- 464,557 ----
> pg_parse_query(const char *query_string)
> {
> List *raw_parsetree_list;
>
> if (log_parser_stats)
> ResetUsage();
>
> raw_parsetree_list = raw_parser(query_string);
>
> if (log_parser_stats)
> ShowUsage("PARSER STATISTICS");
>
> return raw_parsetree_list;
> }
>
> + static bool
> + log_after_parse(List *raw_parsetree_list, const char *query_string,
> + char **prepare_string)
> + {
> + ListCell *parsetree_item;
> + bool log_this_statement = (log_statement == LOGSTMT_ALL);
> +
> + *prepare_string = NULL;
> +
> + /* Check if we need to log the statement, and get prepare_string. */
> + foreach(parsetree_item, raw_parsetree_list)
> + {
> + Node *parsetree = (Node *) lfirst(parsetree_item);
> + const char *commandTag;
> +
> + if (IsA(parsetree, ExplainStmt) &&
> + ((ExplainStmt *) parsetree)->analyze)
> + parsetree = (Node *) (((ExplainStmt *) parsetree)->query);
> +
> + if (IsA(parsetree, PrepareStmt))
> + parsetree = (Node *) (((PrepareStmt *) parsetree)->query);
> +
> + if (IsA(parsetree, SelectStmt))
> + continue; /* optimization for frequent command */
> +
> + if (log_statement == LOGSTMT_MOD &&
> + (IsA(parsetree, InsertStmt) ||
> + IsA(parsetree, UpdateStmt) ||
> + IsA(parsetree, DeleteStmt) ||
> + IsA(parsetree, TruncateStmt) ||
> + (IsA(parsetree, CopyStmt) &&
> + ((CopyStmt *) parsetree)->is_from))) /* COPY FROM */
> + log_this_statement = true;
> +
> + commandTag = CreateCommandTag(parsetree);
> + if ((log_statement == LOGSTMT_MOD ||
> + log_statement == LOGSTMT_DDL) &&
> + (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 ||
> + strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 ||
> + strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 ||
> + IsA(parsetree, GrantStmt) || /* GRANT or REVOKE */
> + IsA(parsetree, CommentStmt)))
> + log_this_statement = true;
> +
> + /*
> + * For the first EXECUTE we find, record the client statement
> + * used by the PREPARE.
> + */
> + if (IsA(parsetree, ExecuteStmt))
> + {
> + ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
> + PreparedStatement *entry;
> +
> + if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
> + entry->query_string)
> + {
> + *prepare_string = palloc(strlen(entry->query_string) +
> + strlen(" [client PREPARE: %s]") - 1);
> + sprintf(*prepare_string, " [client PREPARE: %s]",
> + entry->query_string);
> + }
> + }
> + }
> +
> + if (log_this_statement)
> + {
> + ereport(LOG,
> + (errmsg("statement: %s%s", query_string,
> + *prepare_string ? *prepare_string : "")));
> + return true;
> + }
> + else
> + return false;
> + }
> +
> +
> /*
> * Given a raw parsetree (gram.y output), and optionally information about
> * types of parameter symbols ($n), perform parse analysis and rule rewriting.
> ***************
> *** 735,746 ****
> MemoryContext oldcontext;
> List *parsetree_list;
> ListCell *parsetree_item;
> ! 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;
> !
> /*
> * Report query to various monitoring facilities.
> */
> --- 754,766 ----
> MemoryContext oldcontext;
> List *parsetree_list;
> ListCell *parsetree_item;
> ! 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;
> ! char *prepare_string = NULL;
> ! bool was_logged = false;
> !
> /*
> * Report query to various monitoring facilities.
> */
> ***************
> *** 796,801 ****
> --- 816,825 ----
> */
> parsetree_list = pg_parse_query(query_string);
>
> + if (log_statement != LOGSTMT_NONE || save_log_min_duration_statement != -1)
> + was_logged = log_after_parse(parsetree_list, query_string,
> + &prepare_string);
> +
> /*
> * Switch back to transaction context to enter the loop.
> */
> ***************
> *** 1011,1020 ****
> 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 +
> --- 1035,1045 ----
> 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 (was_logged && save_log_duration)
> ereport(LOG,
> (errmsg("duration: %ld.%03ld ms",
> (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
> ***************
> *** 1029,1044 ****
> (save_log_min_duration_statement > 0 &&
> usecs >= save_log_min_duration_statement * 1000))
> ereport(LOG,
> ! (errmsg("duration: %ld.%03ld ms statement: %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,
> ! query_string)));
> }
>
> if (save_log_statement_stats)
> ShowUsage("QUERY STATISTICS");
>
> debug_query_string = NULL;
> }
>
> --- 1054,1073 ----
> (save_log_min_duration_statement > 0 &&
> usecs >= save_log_min_duration_statement * 1000))
> ereport(LOG,
> ! (errmsg("duration: %ld.%03ld ms statement: %s%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,
> ! query_string,
> ! prepare_string ? prepare_string : "")));
> }
>
> if (save_log_statement_stats)
> ShowUsage("QUERY STATISTICS");
>
> + if (prepare_string != NULL)
> + pfree(prepare_string);
> +
> debug_query_string = NULL;
> }
>
> ***************
> *** 1074,1079 ****
> --- 1103,1112 ----
> if (save_log_statement_stats)
> ResetUsage();
>
> + if (log_statement == LOGSTMT_ALL)
> + ereport(LOG,
> + (errmsg("statement: PREPARE %s AS %s", stmt_name, query_string)));
> +
> /*
> * Start up a transaction command so we can run parse analysis etc.
> * (Note that this will normally change current memory context.)
> ***************
> *** 1371,1376 ****
> --- 1404,1413 ----
> else
> portal = CreatePortal(portal_name, false, false);
>
> + if (log_statement == LOGSTMT_ALL)
> + ereport(LOG,
> + (errmsg("statement: <BIND> %s", portal_name)));
> +
> /*
> * Fetch parameters, if any, and store in the portal's memory context.
> *
> ***************
> *** 1579,1584 ****
> --- 1616,1625 ----
> 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 ****
> --- 1656,1679 ----
>
> 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 */
> ***************
> *** 1709,1714 ****
> --- 1768,1817 ----
> 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 2: you can get off all lists at once with the unregister command
> (send "unregister YourEmailAddressHere" to majordomo(at)postgresql(dot)org)

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073