Re: 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 -0000	1.443
--- src/backend/tcop/postgres.c	16 May 2005 03:40:00 -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,1648 ----
  
  	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)
+ 	{
+ 		/* We have the portal, so output the source query. */
+ 		ereport(LOG,
+ 				(errmsg("statement: EXECUTE %s  [PREPARE:  %s]", portal_name,
+ 						portal->sourceText ? portal->sourceText : "")));
+ 		statement_logged = true;
+ 	}
+ 
  	BeginCommand(portal->commandTag, dest);
  
  	/* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1737,1786 ----
  			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  [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;
  }
  
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	16 May 2005 18:00:52 -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	16 May 2005 18:00:54 -0000
***************
*** 73,78 ****
--- 73,79 ----
   */
  const char *debug_query_string; /* for pgmonitor and
  								 * log_min_error_statement */
+ char *prepare_string = NULL;		/* used for passing PREPARE source string */
  
  /* Note: whereToSendOutput is initialized for the bootstrap/standalone case */
  CommandDest whereToSendOutput = Debug;
***************
*** 467,504 ****
  	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) ||
--- 468,526 ----
  	List	   *raw_parsetree_list;
  	ListCell   *parsetree_item;
  
+ 	/* reset prepare_string */
+ 	if (prepare_string != NULL)
+ 		pfree(prepare_string);
+ 	prepare_string = NULL;
+ 	
  	statement_logged = false;
  
  	if (log_parser_stats)
  		ResetUsage();
  
  	raw_parsetree_list = raw_parser(query_string);
  
! 	if (log_statement == LOGSTMT_ALL ||
! 		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 (IsA(parsetree, ExecuteStmt))
+ 			{
+ 				ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
+ 				PreparedStatement *entry;
  
+ 				/*
+ 				 *	For the first EXECUTE we find before printing the
+ 				 *	statement string, find the client statement that
+ 				 *	generated the PREPARE.
+ 				 */
+ 				if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL)
+ 				{
+ 					if (prepare_string == 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_statement == LOGSTMT_MOD &&
  				(IsA(parsetree, InsertStmt) ||
  				 IsA(parsetree, UpdateStmt) ||
***************
*** 508,531 ****
  				  ((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");
--- 530,565 ----
  				  ((CopyStmt *) parsetree)->is_from)))	/* COPY FROM */
  			{
  				ereport(LOG,
! 						(errmsg("statement: %s%s", query_string,
! 								prepare_string ? prepare_string : "")));
  				statement_logged = true;
  				break;
  			}
  			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)))
  			{
  				ereport(LOG,
! 						(errmsg("statement: %s%s", query_string,
! 								prepare_string ? prepare_string : "")));
  				statement_logged = true;
  				break;
  			}
  		}
  	}
+ 	
+ 	if (log_statement == LOGSTMT_ALL)
+ 	{
+ 		ereport(LOG,
+ 				(errmsg("statement: %s%s", query_string,
+ 								prepare_string ? prepare_string : "")));
+ 		statement_logged = true;
+ 	}
  
  	if (log_parser_stats)
  		ShowUsage("PARSER STATISTICS");
***************
*** 740,746 ****
  	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.
  	 */
--- 774,781 ----
  	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	   *my_prepare_string = NULL;
! 	
  	/*
  	 * Report query to various monitoring facilities.
  	 */
***************
*** 796,801 ****
--- 831,840 ----
  	 */
  	parsetree_list = pg_parse_query(query_string);
  
+ 	/* If EXECUTE generated a PREPARE source, record it for later */
+ 	if (prepare_string != NULL)
+ 		my_prepare_string = pstrdup(prepare_string);
+ 
  	/*
  	 * Switch back to transaction context to enter the loop.
  	 */
***************
*** 1029,1039 ****
  			(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)
--- 1068,1079 ----
  			(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)