Re: [PATCHES] Exec statement logging
Bruce Momjian wrote:
Tom Lane wrote:
Bruce Momjian pgman@candle.pha.pa.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@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/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 - 1.36
--- src/backend/commands/prepare.c 20 May 2005 14:15:12 -
***
*** 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 - 1.443
--- src/backend/tcop/postgres.c 20 May 2005 14:15:17 -
***
*** 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 intInteractiveBackend(StringInfo inBuf);
static intSocketBackend(StringInfo inBuf);
static intReadCommand(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)
-
Re: [PATCHES] Exec statement logging
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@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 - 1.443 --- src/backend/tcop/postgres.c 16 May 2005 03:40:00 - *** *** 1011,1017 stop_t.tv_sec--; stop_t.tv_usec += 100; } ! usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 100 + (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 += 100; } ! usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 100 + ! (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 boolis_trans_exit = false; boolcompleted; charcompletionTag[COMPLETION_TAG_BUFSIZE]; + struct timeval start_t, + stop_t; + boolsave_log_duration = log_duration; + int save_log_min_duration_statement = log_min_duration_statement; + boolsave_log_statement_stats = log_statement_stats;
Re: [PATCHES] Exec statement logging
Bruce Momjian pgman@candle.pha.pa.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 ---(end of broadcast)--- TIP 7: don't forget to increase your free space map settings
Re: [PATCHES] Exec statement logging
Tom Lane wrote: Bruce Momjian pgman@candle.pha.pa.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@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 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
Re: [PATCHES] Exec statement logging
Bruce Momjian pgman@candle.pha.pa.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 ---(end of broadcast)--- TIP 7: don't forget to increase your free space map settings
Re: [PATCHES] Exec statement logging
Tom Lane wrote: Bruce Momjian pgman@candle.pha.pa.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@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 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PATCHES] Exec statement logging
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
Re: [PATCHES] Exec statement logging
Simon Riggs [EMAIL PROTECTED] 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
Re: [PATCHES] Exec statement logging
On Sun, 2005-05-15 at 13:29 -0400, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] 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 Is 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 [EMAIL PROTECTED])
Re: [PATCHES] Exec statement logging
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 Is 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
Re: [PATCHES] Exec statement logging
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 - 1.443 --- src/backend/tcop/postgres.c 14 May 2005 20:22:17 - *** *** 1011,1017 stop_t.tv_sec--; stop_t.tv_usec += 100; } ! usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 100 + (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 += 100; } ! usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 100 + ! (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 boolis_trans_exit = false; boolcompleted; charcompletionTag[COMPLETION_TAG_BUFSIZE]; + struct timeval start_t, + stop_t; + boolsave_log_duration = log_duration; + int save_log_min_duration_statement = log_min_duration_statement; +
Re: [PATCHES] Exec statement logging
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
Re: [PATCHES] Exec statement logging
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
Re: [PATCHES] Exec statement logging
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
Re: [PATCHES] Exec statement logging
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 [EMAIL PROTECTED]
