On Sun, 2005-10-02 at 19:43 +0100, Simon Riggs wrote:
> The following patch implements a fairly light set of timing statements
> aimed at understanding external sort performance. There is no attempt to
> alter the algorithms.

Minor update of patch, use this version please.

> Best Regards, Simon Riggs
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.289
diff -c -c -r1.289 guc.c
*** src/backend/utils/misc/guc.c	24 Sep 2005 22:54:39 -0000	1.289
--- src/backend/utils/misc/guc.c	2 Oct 2005 19:58:02 -0000
***************
*** 92,97 ****
--- 92,98 ----
  extern int	CommitSiblings;
  extern char *default_tablespace;
  extern bool	fullPageWrites;
+ extern bool debug_sort;
  
  static const char *assign_log_destination(const char *value,
  					   bool doit, GucSource source);
***************
*** 764,770 ****
  		false, NULL, NULL
  	},
  #endif
! 
  	{
  		{"log_hostname", PGC_SIGHUP, LOGGING_WHAT,
  			gettext_noop("Logs the host name in the connection logs."),
--- 765,779 ----
  		false, NULL, NULL
  	},
  #endif
! 	{
! 		{"debug_sort", PGC_USERSET, DEVELOPER_OPTIONS,
! 			gettext_noop("no description available"),
! 			NULL,
! 			GUC_NOT_IN_SAMPLE
! 		},
! 		&debug_sort,
! 		false, NULL, NULL
! 	},
  	{
  		{"log_hostname", PGC_SIGHUP, LOGGING_WHAT,
  			gettext_noop("Logs the host name in the connection logs."),
Index: src/backend/utils/sort/tuplesort.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/sort/tuplesort.c,v
retrieving revision 1.50
diff -c -c -r1.50 tuplesort.c
*** src/backend/utils/sort/tuplesort.c	23 Sep 2005 15:36:57 -0000	1.50
--- src/backend/utils/sort/tuplesort.c	2 Oct 2005 19:58:02 -0000
***************
*** 85,90 ****
--- 85,92 ----
  
  #include "postgres.h"
  
+ #include <sys/time.h>
+ 
  #include "access/heapam.h"
  #include "access/nbtree.h"
  #include "catalog/pg_amop.h"
***************
*** 394,399 ****
--- 396,404 ----
   */
  static Tuplesortstate *qsort_tuplesortstate;
  
+ /* debug variables */
+ bool debug_sort = false;
+ struct timeval start_t, current_t;
  
  /*
   *		tuplesort_begin_xxx
***************
*** 422,427 ****
--- 427,439 ----
  
  	state = (Tuplesortstate *) palloc0(sizeof(Tuplesortstate));
  
+     if (debug_sort)
+ 	{
+     	ereport(NOTICE,
+ 			(errmsg("tuplesort begin  work_mem= %u", workMem)));
+        	gettimeofday(&start_t, NULL);
+     }
+ 
  	state->status = TSS_INITIAL;
  	state->randomAccess = randomAccess;
  	state->availMem = workMem * 1024L;
***************
*** 454,459 ****
--- 466,475 ----
  	Tuplesortstate *state = tuplesort_begin_common(workMem, randomAccess);
  	int			i;
  
+     if (debug_sort)
+ 		ereport(NOTICE,
+ 			(errmsg("+0 secs  heap sort  nkeys= %u", nkeys)));
+ 
  	AssertArg(nkeys > 0);
  
  	state->comparetup = comparetup_heap;
***************
*** 499,504 ****
--- 515,524 ----
  {
  	Tuplesortstate *state = tuplesort_begin_common(workMem, randomAccess);
  
+     if (debug_sort)
+ 		ereport(NOTICE,
+ 			(errmsg("+0 secs  index sort")));
+ 
  	state->comparetup = comparetup_index;
  	state->copytup = copytup_index;
  	state->writetup = writetup_index;
***************
*** 666,671 ****
--- 686,698 ----
  			/*
  			 * Nope; time to switch to tape-based operation.
  			 */
+             if (debug_sort)
+             {
+            		gettimeofday(&current_t, NULL);
+         		ereport(NOTICE,
+         			(errmsg("+%ld secs  switching to external sort", 
+         					(long) (current_t.tv_sec - start_t.tv_sec))));
+             }
  			inittapes(state);
  
  			/*
***************
*** 1042,1047 ****
--- 1069,1082 ----
  	int			j;
  	int			a;
  
+     if (debug_sort)
+     {
+    		gettimeofday(&current_t, NULL);
+ 		ereport(NOTICE,
+ 			(errmsg("+%ld secs  starting build of next run", 
+ 					(long) (current_t.tv_sec - start_t.tv_sec))));
+     }
+ 
  	/* Step D3: advance j (destTape) */
  	if (state->tp_dummy[state->destTape] < state->tp_dummy[state->destTape + 1])
  	{
***************
*** 1082,1087 ****
--- 1117,1131 ----
  	Assert(state->status == TSS_BUILDRUNS);
  	Assert(state->memtupcount == 0);
  
+     if (debug_sort)
+     {
+    		gettimeofday(&current_t, NULL);
+ 		ereport(NOTICE,
+ 			(errmsg("+%ld secs  run building complete  nruns= %u", 
+ 					(long) (current_t.tv_sec - start_t.tv_sec),
+                     state->currentRun)));
+     }
+ 
  	/*
  	 * If we produced only one initial run (quite likely if the total data
  	 * volume is between 1X and 2X workMem), we can just use that tape as
***************
*** 1093,1100 ****
--- 1137,1158 ----
  		/* must freeze and rewind the finished output tape */
  		LogicalTapeFreeze(state->tapeset, state->result_tape);
  		state->status = TSS_SORTEDONTAPE;
+         if (debug_sort)
+         {
+        		gettimeofday(&current_t, NULL);
+        		ereport(NOTICE,
+        			(errmsg("+%ld secs  no final merge required", 
+    					(long) (current_t.tv_sec - start_t.tv_sec))));
+         }
  		return;
  	}
+     if (debug_sort)
+     {
+    		gettimeofday(&current_t, NULL);
+    		ereport(NOTICE,
+    			(errmsg("+%ld secs  merging runs with 6 tapes", 
+     			(long) (current_t.tv_sec - start_t.tv_sec))));
+     }
  
  	/* End of step D2: rewind all output tapes to prepare for merging */
  	for (tapenum = 0; tapenum < TAPERANGE; tapenum++)
***************
*** 1126,1131 ****
--- 1184,1196 ----
  				/* Initialize for the final merge pass */
  				beginmerge(state);
  				state->status = TSS_FINALMERGE;
+                 if (debug_sort)
+                 {
+                		gettimeofday(&current_t, NULL);
+             		ereport(NOTICE,
+             			(errmsg("+%ld secs  starting final merge", 
+         					(long) (current_t.tv_sec - start_t.tv_sec))));
+                 }
  				return;
  			}
  			if (allDummy)
***************
*** 1177,1182 ****
--- 1242,1254 ----
  	state->result_tape = state->tp_tapenum[TAPERANGE];
  	LogicalTapeFreeze(state->tapeset, state->result_tape);
  	state->status = TSS_SORTEDONTAPE;
+     if (debug_sort)
+     {
+     	gettimeofday(&current_t, NULL);
+    		ereport(NOTICE,
+         	(errmsg("+%ld secs  starting final merge", 
+    					(long) (current_t.tv_sec - start_t.tv_sec))));
+     }
  }
  
  /*
***************
*** 1243,1248 ****
--- 1315,1327 ----
  	 */
  	markrunend(state, destTape);
  	state->tp_runs[TAPERANGE]++;
+     if (debug_sort)
+     {
+     	gettimeofday(&current_t, NULL);
+    		ereport(NOTICE,
+         	(errmsg("+%ld secs  intermediate merge", 
+    					(long) (current_t.tv_sec - start_t.tv_sec))));
+     }
  }
  
  /*
---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Reply via email to