Skip site navigation (1) Skip section navigation (2)

Re: Exec statement logging

From: Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us>
To: Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us>
Cc: PostgreSQL-patches <pgsql-patches(at)postgresql(dot)org>,Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>, Simon Riggs <simon(at)2ndquadrant(dot)com>
Subject: Re: Exec statement logging
Date: 2005-05-24 04:18:21
Message-ID: 200505240418.j4O4ILL18484@candle.pha.pa.us (view raw or flat)
Thread:
Lists: pgsql-patches
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

In response to

pgsql-patches by date

Next:From: Markus BertheauDate: 2005-05-24 06:02:25
Subject: Re: ARRAY() returning NULL instead of ARRAY[] resp. {}
Previous:From: Bruce MomjianDate: 2005-05-24 04:16:38
Subject: Re: [BUGS] BUG #1609: Bug in interval datatype for 64 Bit timestamps

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group