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 - 1.289
--- src/backend/utils/misc/guc.c 2 Oct 2005 19:58:02 -
***
*** 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 - 1.50
--- src/backend/utils/sort/tuplesort.c 2 Oct 2005 19:58:02 -
***
*** 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)
