Date: Wed, 13 Jul 2005 11:07:40 +0100
To: Christopher Kings-Lynne <chriskl@familyhealth.com.au>
Cc: Brent Henry <bh_pgperf@yahoo.com>, Dennis <dennis@works4me.com>,
	Tom Arthurs <tarthurs@jobflash.com>, pgsql-performance@postgresql.org
Subject: Re: General DB Tuning
Message-ID: <20050713100740.GA27912@purplebat.com>
References: <20050713013630.18625.qmail@web33911.mail.mud.yahoo.com>
	<42D473D4.7040500@familyhealth.com.au>
Mime-Version: 1.0
Content-Type: multipart/mixed; boundary="W/nzBZO5zC0uMSeA"
Content-Disposition: inline
In-Reply-To: <42D473D4.7040500@familyhealth.com.au>
User-Agent: Mutt/1.5.9i
From: Mark Rae <mrae@purplebat.com>


--W/nzBZO5zC0uMSeA
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Wed, Jul 13, 2005 at 09:52:20AM +0800, Christopher Kings-Lynne wrote:
> The 8.0.2 jdbc driver uses real prepared statements instead of faked 
> ones.  The problem is the new protocol (that the 8.0.2 driver users) has 
> a bug where protocol-prepared queries don't get logged properly.
> I don't know if it's been fixed...

It's not in 8.0.3, but I was having the same problems with DBD::Pg so
I backported some of it and also changed the code so that it listed the
values of the bind parameters, so you get something like

LOG:  statement: SELECT sr.name,sr.seq_region_id, sr.length, 1 FROM seq_region sr  WHERE sr.name = $1 AND sr.coord_system_id = $2
LOG:  binding: "dbdpg_2" with 2 parameters
LOG:  bind "dbdpg_2" $1 = "20"
LOG:  bind "dbdpg_2" $2 = "1"
LOG:  statement: EXECUTE   [PREPARE:  SELECT sr.name,sr.seq_region_id, sr.length, 1 FROM seq_region sr  WHERE sr.name = $1 AND sr.coord_system_id = $2]
LOG:  duration: 0.164 ms

I've attached a patch in case anyone finds it useful.

    -Mark

--W/nzBZO5zC0uMSeA
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="timing.patch"

*** postgresql-8.0.3/src/backend/tcop/postgres.c	2005-07-13 09:42:04.997669193 +0100
--- postgresql-8.0.3/src/backend/tcop/postgres.c	2005-07-13 09:34:24.618195580 +0100
***************
*** 1370,1375 ****
--- 1370,1378 ----
  	else
  		portal = CreatePortal(portal_name, false, false);
  
+ 	if (log_statement == LOGSTMT_ALL)
+ 	  ereport(LOG, (errmsg("binding: \"%s\" with %d parameters", stmt_name, numParams)));
+ 
  	/*
  	 * Fetch parameters, if any, and store in the portal's memory context.
  	 *
***************
*** 1428,1433 ****
--- 1431,1439 ----
  					 * grotty but is a big win when dealing with very
  					 * large parameter strings.
  					 */
+ 					if (log_statement == LOGSTMT_ALL)
+ 					  ereport(LOG, (errmsg("bind \"%s\" $%d = \"%s\"", stmt_name, i+1, pvalue)));
+ 
  					pbuf.data = (char *) pvalue;
  					pbuf.maxlen = plength + 1;
  					pbuf.len = plength;
***************
*** 1578,1583 ****
--- 1584,1593 ----
  	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;
***************
*** 1614,1619 ****
--- 1624,1647 ----
  
  	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 */
***************
*** 1708,1713 ****
--- 1736,1785 ----
  			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;
  }
  

--W/nzBZO5zC0uMSeA--