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(¤t_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(¤t_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(¤t_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(¤t_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(¤t_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(¤t_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(¤t_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(¤t_t, NULL);
+ ereport(NOTICE,
+ (errmsg("+%ld secs intermediate merge",
+ (long) (current_t.tv_sec - start_t.tv_sec))));
+ }
}
/*
---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to [EMAIL PROTECTED] so that your
message can get through to the mailing list cleanly
