Add a trace_sort option to help with measuring resource usage of external

sort operations.  Per recent discussion.  Simon Riggs and Tom Lane.

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 57a2d178a975e4c9140cde2bad8f459b3151ae97..6fde3cf08677105fe01f87ac517dc2107aec7a79 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -4071,6 +4071,21 @@ plruby.use_strict = true        # generates error: unknown class name
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-trace-sort" xreflabel="trace_sort">
+      <term><varname>trace_sort</varname> (<type>boolean</type>)</term>
+      <indexterm>
+       <primary><varname>trace_sort</> configuration parameter</primary>
+      </indexterm>
+      <listitem>
+       <para>
+        If on, emit information about resource usage during sort operations.
+        This option is only available if the <symbol>TRACE_SORT</symbol> macro
+        was defined when <productname>PostgreSQL</productname> was compiled.
+        (However, <symbol>TRACE_SORT</symbol> is currently defined by default.)
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry>
       <term><varname>trace_locks</varname> (<type>boolean</type>)</term>
       <term><varname>trace_lwlocks</varname> (<type>boolean</type>)</term>

diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 9d3d7a200c070a3a52f761c5f300726dad7859cb..2a64cb6b05e84093f3025f09c25ba7eef32fd054 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -92,6 +92,9 @@ extern int    CommitDelay;
 extern int     CommitSiblings;
 extern char *default_tablespace;
 extern bool    fullPageWrites;
+#ifdef TRACE_SORT
+extern bool    trace_sort;
+#endif
 
 static const char *assign_log_destination(const char *value,
                                           bool doit, GucSource source);
@@ -891,6 +894,18 @@ static struct config_bool ConfigureNamesBool[] =
                false, NULL, NULL
        },
 
+#ifdef TRACE_SORT
+       {
+               {"trace_sort", PGC_USERSET, DEVELOPER_OPTIONS,
+                       gettext_noop("Emit information about resource usage in sorting."),
+                       NULL,
+                       GUC_NOT_IN_SAMPLE
+               },
+               &trace_sort,
+               false, NULL, NULL
+       },
+#endif
+
 #ifdef WAL_DEBUG
        {
                {"wal_debug", PGC_SUSET, DEVELOPER_OPTIONS,

diff --git a/src/backend/utils/sort/tuplesort.c b/src/backend/utils/sort/tuplesort.c
index 477efb8eac172c6f71c361d1a089d70debca3d01..b9c60eb1097ed2b31b8866fa1c7033312fe42dbc 100644 (file)
--- a/src/backend/utils/sort/tuplesort.c
+++ b/src/backend/utils/sort/tuplesort.c
@@ -95,10 +95,17 @@
 #include "utils/logtape.h"
 #include "utils/lsyscache.h"
 #include "utils/memutils.h"
+#include "utils/pg_rusage.h"
 #include "utils/syscache.h"
 #include "utils/tuplesort.h"
 
 
+/* GUC variable */
+#ifdef TRACE_SORT
+bool                   trace_sort = false;
+#endif
+
+
 /*
  * Possible states of a Tuplesort object.  These denote the states that
  * persist between calls of Tuplesort routines.
@@ -283,6 +290,13 @@ struct Tuplesortstate
        /* we need typelen and byval in order to know how to copy the Datums. */
        int                     datumTypeLen;
        bool            datumTypeByVal;
+
+       /*
+        * Resource snapshot for time of sort start.
+        */
+#ifdef TRACE_SORT
+       PGRUsage        ru_start;
+#endif
 };
 
 #define COMPARETUP(state,a,b)  ((*(state)->comparetup) (state, a, b))
@@ -422,6 +436,11 @@ tuplesort_begin_common(int workMem, bool randomAccess)
 
        state = (Tuplesortstate *) palloc0(sizeof(Tuplesortstate));
 
+#ifdef TRACE_SORT
+       if (trace_sort)
+               pg_rusage_init(&state->ru_start);
+#endif
+
        state->status = TSS_INITIAL;
        state->randomAccess = randomAccess;
        state->availMem = workMem * 1024L;
@@ -456,6 +475,13 @@ tuplesort_begin_heap(TupleDesc tupDesc,
 
        AssertArg(nkeys > 0);
 
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE,
+                        "begin tuple sort: nkeys = %d, workMem = %d, randomAccess = %c",
+                        nkeys, workMem, randomAccess ? 't' : 'f');
+#endif
+
        state->comparetup = comparetup_heap;
        state->copytup = copytup_heap;
        state->writetup = writetup_heap;
@@ -499,6 +525,14 @@ tuplesort_begin_index(Relation indexRel,
 {
        Tuplesortstate *state = tuplesort_begin_common(workMem, randomAccess);
 
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE,
+                        "begin index sort: unique = %c, workMem = %d, randomAccess = %c",
+                        enforceUnique ? 't' : 'f',
+                        workMem, randomAccess ? 't' : 'f');
+#endif
+
        state->comparetup = comparetup_index;
        state->copytup = copytup_index;
        state->writetup = writetup_index;
@@ -522,6 +556,13 @@ tuplesort_begin_datum(Oid datumType,
        int16           typlen;
        bool            typbyval;
 
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE,
+                        "begin datum sort: workMem = %d, randomAccess = %c",
+                        workMem, randomAccess ? 't' : 'f');
+#endif
+
        state->comparetup = comparetup_datum;
        state->copytup = copytup_datum;
        state->writetup = writetup_datum;
@@ -573,6 +614,12 @@ tuplesort_end(Tuplesortstate *state)
        if (state->sortFnKinds)
                pfree(state->sortFnKinds);
 
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE, "sort ended: %s",
+                        pg_rusage_show(&state->ru_start));
+#endif
+
        pfree(state);
 }
 
@@ -712,6 +759,12 @@ puttuple_common(Tuplesortstate *state, void *tuple)
 void
 tuplesort_performsort(Tuplesortstate *state)
 {
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE, "performsort starting: %s",
+                        pg_rusage_show(&state->ru_start));
+#endif
+
        switch (state->status)
        {
                case TSS_INITIAL:
@@ -751,6 +804,13 @@ tuplesort_performsort(Tuplesortstate *state)
                        elog(ERROR, "invalid tuplesort state");
                        break;
        }
+
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE, "performsort done%s: %s",
+                        (state->status == TSS_FINALMERGE) ? " (except final merge)" : "",
+                        pg_rusage_show(&state->ru_start));
+#endif
 }
 
 /*
@@ -986,6 +1046,12 @@ inittapes(Tuplesortstate *state)
        int                     ntuples,
                                j;
 
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE, "switching to external sort: %s",
+                        pg_rusage_show(&state->ru_start));
+#endif
+
        state->tapeset = LogicalTapeSetCreate(MAXTAPES);
 
        /*
@@ -1243,6 +1309,12 @@ mergeonerun(Tuplesortstate *state)
         */
        markrunend(state, destTape);
        state->tp_runs[TAPERANGE]++;
+
+#ifdef TRACE_SORT
+       if (trace_sort)
+               elog(NOTICE, "finished merge step: %s",
+                        pg_rusage_show(&state->ru_start));
+#endif
 }
 
 /*
@@ -1456,6 +1528,14 @@ dumptuples(Tuplesortstate *state, bool alltuples)
                        state->tp_runs[state->destTape]++;
                        state->tp_dummy[state->destTape]--; /* per Alg D step D2 */
 
+#ifdef TRACE_SORT
+                       if (trace_sort)
+                               elog(NOTICE, "finished writing%s run %d: %s",
+                                        (state->memtupcount == 0) ? " final" : "",
+                                        state->currentRun,
+                                        pg_rusage_show(&state->ru_start));
+#endif
+
                        /*
                         * Done if heap is empty, else prepare for new run.
                         */

diff --git a/src/include/pg_config_manual.h b/src/include/pg_config_manual.h
index d3945ebbc8a461908841cefaba9a7595342c47ad..699e3c116bfb72ee22e282bf56a287b11bbabff5 100644 (file)
--- a/src/include/pg_config_manual.h
+++ b/src/include/pg_config_manual.h
@@ -229,11 +229,15 @@
  */
 /* #define WAL_DEBUG */
 
+/*
+ * Enable tracing of resource consumption during sort operations;
+ * see also the trace_sort GUC var.  For 8.1 this is enabled by default.
+ */
+#define TRACE_SORT 1
+
 /*
  * Other debug #defines (documentation, anyone?)
  */
-/* #define IPORTAL_DEBUG  */
-/* #define HEAPDEBUGALL  */
+/* #define HEAPDEBUGALL */
 /* #define ACLDEBUG */
 /* #define RTDEBUG */
-/* #define GISTDEBUG */