New DTrace probes proposal

(Resending since it didn't work the first time. Not sure if attaching a
tar file was the culprit.)

I'd like to propose adding the following probes (some of which came from
Simon) to 8.4.

I think these probe provide very useful data. Although some of the data
can be collected now, the main advantages with probes, among others, are
(1) they are always available and can be enabled only when needed
especially in production (2) different combinations of probes can be
used together to collect interesting data.

They work on OS X Leopard & Solaris now, and hopefully on FreeBSD soon.

Preliminary patch attached along with sample DTrace scripts.

-Robert

---------------

* Probes to measure query time
query-parse-start (int, char *)
query-parse-done (int, char *)
query-plan-start ()
query-plan-done ()
query-execute-start ()
query-execute-done ()
query-statement-start (int, char *)
query-statement-done (int, char *)

* Probes to measure dirty buffer writes by the backend because bgwriter
is not effective
dirty-buffer-write-start (int, int, int, int)
dirty-buffer-write-done (int, int, int, int)

* Probes to measure physical writes from the shared buffer
buffer-write-start (int, int, int, int)
buffer-write-done (int, int, int, int, int)

* Probes to measure reads of a relation from a particular buffer block
buffer-read-start (int, int, int, int, int)
buffer-read-done (int, int, int, int, int, int)

* Probes to measure the effectiveness of buffer caching
buffer-hit ()
buffer-miss ()

* Probes to measure I/O time because wal_buffers is too small
wal-buffer-write-start ()
wal-buffer-write-done ()

* Probes to measure checkpoint stats such as running time, buffers
written, xlog files added, removed, recycled, etc
checkpoint-start (int)
checkpoint-done (int, int, int, int, int)

* Probes to measure Idle in Transaction and client/network time
idle-transaction-start (int, int)
idle-transaction-done ()

* Probes to measure sort time
sort-start (int, int, int, int, int)
sort-done (int, long)

* Probes to determine whether or not the deadlock detector has found a
deadlock
deadlock-found ()
deadlock-notfound (int)

* Probes to measure reads/writes by block numbers and relations
smgr-read-start (int, int,  int, int)
smgr-read-end (int, int,  int, int, int, int)
smgr-write-start (int, int, int, int)
smgr-write-end (int, int, int, int, int, int)



Index: backend/access/transam/xlog.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/access/transam/xlog.c,v
retrieving revision 1.295
diff -u -3 -p -r1.295 xlog.c
--- backend/access/transam/xlog.c    25 Mar 2008 22:42:42 -0000    1.295
+++ backend/access/transam/xlog.c    16 May 2008 18:37:22 -0000
@@ -50,6 +50,7 @@
 #include "utils/builtins.h"
 #include "utils/pg_locale.h"
 #include "utils/ps_status.h"
+#include "pg_trace.h"


 /* File path names (all relative to $PGDATA) */
@@ -1258,12 +1259,14 @@ AdvanceXLInsertBuffer(bool new_segment)
                  * Have to write buffers while holding insert lock. This is
                  * not good, so only write as much as we absolutely must.
                  */
+                TRACE_POSTGRESQL_WAL_BUFFER_WRITE_START();
                 WriteRqst.Write = OldPageRqstPtr;
                 WriteRqst.Flush.xlogid = 0;
                 WriteRqst.Flush.xrecoff = 0;
                 XLogWrite(WriteRqst, false, false);
                 LWLockRelease(WALWriteLock);
                 Insert->LogwrtResult = LogwrtResult;
+                TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DONE();
             }
         }
     }
@@ -5665,6 +5668,8 @@ CreateCheckPoint(int flags)
     MemSet(&CheckpointStats, 0, sizeof(CheckpointStats));
     CheckpointStats.ckpt_start_t = GetCurrentTimestamp();

+    TRACE_POSTGRESQL_CHECKPOINT_START(flags);
+
     /*
      * Use a critical section to force system panic if we have trouble.
      */
@@ -5726,6 +5731,7 @@ CreateCheckPoint(int flags)
             LWLockRelease(WALInsertLock);
             LWLockRelease(CheckpointLock);
             END_CRIT_SECTION();
+            TRACE_POSTGRESQL_CHECKPOINT_DONE(UINT_MAX,0,0,0,UINT_MAX);
             return;
         }
     }
@@ -5945,6 +5951,11 @@ CreateCheckPoint(int flags)
     if (log_checkpoints)
         LogCheckpointEnd();

+    TRACE_POSTGRESQL_CHECKPOINT_DONE(CheckpointStats.ckpt_bufs_written,
+                NBuffers, CheckpointStats.ckpt_segs_added,
+                CheckpointStats.ckpt_segs_removed,
+                CheckpointStats.ckpt_segs_recycled);
+
     LWLockRelease(CheckpointLock);
 }

Index: backend/storage/buffer/bufmgr.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/buffer/bufmgr.c,v
retrieving revision 1.228
diff -u -3 -p -r1.228 bufmgr.c
--- backend/storage/buffer/bufmgr.c    1 Jan 2008 19:45:51 -0000    1.228
+++ backend/storage/buffer/bufmgr.c    16 May 2008 18:37:22 -0000
@@ -42,6 +42,7 @@
 #include "storage/smgr.h"
 #include "utils/resowner.h"
 #include "pgstat.h"
+#include "pg_trace.h"


 /* Note: these two macros only work on shared buffers, not local ones! */
@@ -171,6 +172,7 @@ ReadBuffer_common(Relation reln, BlockNu
     if (isExtend)
         blockNum = smgrnblocks(reln->rd_smgr);

+    TRACE_POSTGRESQL_BUFFER_READ_START(blockNum, reln->rd_node.spcNode, reln->rd_node.dbNode, reln->rd_node.relNode,
isLocalBuf);
     pgstat_count_buffer_read(reln);

     if (isLocalBuf)
@@ -200,12 +202,16 @@ ReadBuffer_common(Relation reln, BlockNu
     {
         if (!isExtend)
         {
+            TRACE_POSTGRESQL_BUFFER_HIT();
             /* Just need to update stats before we exit */
             pgstat_count_buffer_hit(reln);

             if (VacuumCostActive)
                 VacuumCostBalance += VacuumCostPageHit;

+            TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum,
+                 reln->rd_node.spcNode, reln->rd_node.dbNode,
+                 reln->rd_node.relNode, isLocalBuf, found);
             return BufferDescriptorGetBuffer(bufHdr);
         }

@@ -257,6 +263,7 @@ ReadBuffer_common(Relation reln, BlockNu
             } while (!StartBufferIO(bufHdr, true));
         }
     }
+    TRACE_POSTGRESQL_BUFFER_MISS();

     /*
      * if we have gotten to this point, we have allocated a buffer for the
@@ -324,6 +331,9 @@ ReadBuffer_common(Relation reln, BlockNu
     if (VacuumCostActive)
         VacuumCostBalance += VacuumCostPageMiss;

+    TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum, reln->rd_node.spcNode,
+        reln->rd_node.dbNode, reln->rd_node.relNode, isLocalBuf, found);
+
     return BufferDescriptorGetBuffer(bufHdr);
 }

@@ -466,6 +476,11 @@ BufferAlloc(Relation reln,
              * happens to be trying to split the page the first one got from
              * StrategyGetBuffer.)
              */
+
+            TRACE_POSTGRESQL_DIRTY_BUFFER_WRITE_START(blockNum,
+              reln->rd_node.spcNode, reln->rd_node.dbNode,
+              reln->rd_node.relNode);
+
             if (LWLockConditionalAcquire(buf->content_lock, LW_SHARED))
             {
                 /*
@@ -488,6 +503,11 @@ BufferAlloc(Relation reln,
                 /* OK, do the I/O */
                 FlushBuffer(buf, NULL);
                 LWLockRelease(buf->content_lock);
+
+                TRACE_POSTGRESQL_DIRTY_BUFFER_WRITE_DONE(
+                  blockNum, reln->rd_node.spcNode,
+                  reln->rd_node.dbNode, reln->rd_node.relNode,
+                  (oldFlags & BM_HINT_BITS_TEST));
             }
             else
             {
@@ -1734,6 +1754,10 @@ FlushBuffer(volatile BufferDesc *buf, SM
     buf->flags &= ~BM_JUST_DIRTIED;
     UnlockBufHdr(buf);

+    TRACE_POSTGRESQL_BUFFER_WRITE_START(buf->tag.blockNum,
+         reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode,
+         reln->smgr_rnode.relNode);
+
     smgrwrite(reln,
               buf->tag.blockNum,
               (char *) BufHdrGetBlock(buf),
@@ -1741,6 +1765,10 @@ FlushBuffer(volatile BufferDesc *buf, SM

     BufferFlushCount++;

+    TRACE_POSTGRESQL_BUFFER_WRITE_DONE(buf->tag.blockNum,
+         reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode,
+         reln->smgr_rnode.relNode, (buf->flags & BM_HINT_BITS_TEST));
+
     /*
      * Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and
      * end the io_in_progress state.
@@ -2155,7 +2183,7 @@ SetBufferCommitInfoNeedsSave(Buffer buff
         Assert(bufHdr->refcount > 0);
         if (!(bufHdr->flags & BM_DIRTY) && VacuumCostActive)
             VacuumCostBalance += VacuumCostPageDirty;
-        bufHdr->flags |= (BM_DIRTY | BM_JUST_DIRTIED);
+        bufHdr->flags |= (BM_DIRTY | BM_JUST_DIRTIED | BM_HINT_BITS_TEST);
         UnlockBufHdr(bufHdr);
     }
 }
@@ -2492,7 +2520,7 @@ TerminateBufferIO(volatile BufferDesc *b
     Assert(buf->flags & BM_IO_IN_PROGRESS);
     buf->flags &= ~(BM_IO_IN_PROGRESS | BM_IO_ERROR);
     if (clear_dirty && !(buf->flags & BM_JUST_DIRTIED))
-        buf->flags &= ~(BM_DIRTY | BM_CHECKPOINT_NEEDED);
+        buf->flags &= ~(BM_DIRTY | BM_CHECKPOINT_NEEDED | BM_HINT_BITS_TEST);
     buf->flags |= set_flag_bits;

     UnlockBufHdr(buf);
Index: backend/storage/lmgr/deadlock.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/lmgr/deadlock.c,v
retrieving revision 1.53
diff -u -3 -p -r1.53 deadlock.c
--- backend/storage/lmgr/deadlock.c    24 Mar 2008 18:22:36 -0000    1.53
+++ backend/storage/lmgr/deadlock.c    16 May 2008 18:37:23 -0000
@@ -30,6 +30,7 @@
 #include "storage/lmgr.h"
 #include "storage/proc.h"
 #include "utils/memutils.h"
+#include "pg_trace.h"


 /* One edge in the waits-for graph */
@@ -222,6 +223,8 @@ DeadLockCheck(PGPROC *proc)
          */
         int            nSoftEdges;

+        TRACE_POSTGRESQL_DEADLOCK_FOUND();
+
         nWaitOrders = 0;
         if (!FindLockCycle(proc, possibleConstraints, &nSoftEdges))
             elog(FATAL, "deadlock seems to have disappeared");
@@ -259,6 +262,8 @@ DeadLockCheck(PGPROC *proc)
         ProcLockWakeup(GetLocksMethodTable(lock), lock);
     }

+    TRACE_POSTGRESQL_DEADLOCK_NOTFOUND(nWaitOrders);
+
     /* Return code tells caller if we had to escape a deadlock or not */
     if (nWaitOrders > 0)
         return DS_SOFT_DEADLOCK;
Index: backend/storage/smgr/md.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/smgr/md.c,v
retrieving revision 1.136
diff -u -3 -p -r1.136 md.c
--- backend/storage/smgr/md.c    10 Mar 2008 20:06:27 -0000    1.136
+++ backend/storage/smgr/md.c    16 May 2008 18:37:23 -0000
@@ -26,6 +26,7 @@
 #include "storage/smgr.h"
 #include "utils/hsearch.h"
 #include "utils/memutils.h"
+#include "pg_trace.h"


 /* interval for calling AbsorbFsyncRequests in mdsync */
@@ -581,6 +582,8 @@ mdread(SMgrRelation reln, BlockNumber bl
     int            nbytes;
     MdfdVec    *v;

+    TRACE_POSTGRESQL_SMGR_READ_START(blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode,
reln->smgr_rnode.relNode);
+
     v = _mdfd_getseg(reln, blocknum, false, EXTENSION_FAIL);

 #ifdef USE_SEGMENTED_FILES
@@ -599,7 +602,11 @@ mdread(SMgrRelation reln, BlockNumber bl
                         reln->smgr_rnode.dbNode,
                         reln->smgr_rnode.relNode)));

-    if ((nbytes = FileRead(v->mdfd_vfd, buffer, BLCKSZ)) != BLCKSZ)
+    nbytes = FileRead(v->mdfd_vfd, buffer, BLCKSZ);
+
+    TRACE_POSTGRESQL_SMGR_READ_DONE(blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode,
reln->smgr_rnode.relNode,nbytes, BLCKSZ); 
+
+    if (nbytes != BLCKSZ)
     {
         if (nbytes < 0)
             ereport(ERROR,
@@ -651,6 +658,8 @@ mdwrite(SMgrRelation reln, BlockNumber b
     Assert(blocknum < mdnblocks(reln));
 #endif

+    TRACE_POSTGRESQL_SMGR_WRITE_START(blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode,
reln->smgr_rnode.relNode);
+
     v = _mdfd_getseg(reln, blocknum, isTemp, EXTENSION_FAIL);

 #ifdef USE_SEGMENTED_FILES
@@ -691,6 +700,8 @@ mdwrite(SMgrRelation reln, BlockNumber b
                  errhint("Check free disk space.")));
     }

+    TRACE_POSTGRESQL_SMGR_WRITE_DONE(blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode,
reln->smgr_rnode.relNode,nbytes, BLCKSZ); 
+
     if (!isTemp)
         register_dirty_segment(reln, v);
 }
Index: backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.547
diff -u -3 -p -r1.547 postgres.c
--- backend/tcop/postgres.c    26 Mar 2008 18:48:59 -0000    1.547
+++ backend/tcop/postgres.c    16 May 2008 18:37:24 -0000
@@ -70,6 +70,7 @@
 #include "mb/pg_wchar.h"

 #include "pgstat.h"
+#include "pg_trace.h"

 extern int    optind;
 extern char *optarg;
@@ -550,6 +551,8 @@ pg_parse_query(const char *query_string)
 {
     List       *raw_parsetree_list;

+    TRACE_POSTGRESQL_QUERY_PARSE_START(query_string);
+
     if (log_parser_stats)
         ResetUsage();

@@ -659,6 +662,8 @@ pg_rewrite_query(Query *query)
         elog_node_display(DEBUG1, "rewritten parse tree", querytree_list,
                           Debug_pretty_print);

+    TRACE_POSTGRESQL_QUERY_PARSE_DONE();
+
     return querytree_list;
 }

@@ -672,6 +677,8 @@ pg_plan_query(Query *querytree, int curs
 {
     PlannedStmt *plan;

+    TRACE_POSTGRESQL_QUERY_PLAN_START();
+
     /* Utility commands have no plans. */
     if (querytree->commandType == CMD_UTILITY)
         return NULL;
@@ -709,6 +716,7 @@ pg_plan_query(Query *querytree, int curs
      */
     if (Debug_print_plan)
         elog_node_display(DEBUG1, "plan", plan, Debug_pretty_print);
+    TRACE_POSTGRESQL_QUERY_PLAN_DONE();

     return plan;
 }
@@ -796,6 +804,7 @@ exec_simple_query(const char *query_stri
     bool        isTopLevel;
     char        msec_str[32];

+
     /*
      * Report query to various monitoring facilities.
      */
@@ -803,6 +812,8 @@ exec_simple_query(const char *query_stri

     pgstat_report_activity(query_string);

+    TRACE_POSTGRESQL_QUERY_STATEMENT_START(MyProcPid, query_string);
+
     /*
      * We use save_log_statement_stats so ShowUsage doesn't report incorrect
      * results because ResetUsage wasn't called.
@@ -1064,6 +1075,8 @@ exec_simple_query(const char *query_stri
     if (save_log_statement_stats)
         ShowUsage("QUERY STATISTICS");

+    TRACE_POSTGRESQL_QUERY_STATEMENT_DONE(MyProcPid, query_string);
+
     debug_query_string = NULL;
 }

@@ -3484,6 +3497,7 @@ PostgresMain(int argc, char *argv[], con
         {
             if (IsTransactionOrTransactionBlock())
             {
+                TRACE_POSTGRESQL_IDLE_TRANSACTION_START(GetCurrentTransactionId(), GetCurrentCommandId(false));
                 set_ps_display("idle in transaction", false);
                 pgstat_report_activity("<IDLE> in transaction");
             }
@@ -3513,6 +3527,8 @@ PostgresMain(int argc, char *argv[], con
          */
         firstchar = ReadCommand(&input_message);

+        TRACE_POSTGRESQL_IDLE_TRANSACTION_DONE();
+
         /*
          * (4) disable async signal conditions again.
          */
Index: backend/tcop/pquery.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/tcop/pquery.c,v
retrieving revision 1.122
diff -u -3 -p -r1.122 pquery.c
--- backend/tcop/pquery.c    26 Mar 2008 18:48:59 -0000    1.122
+++ backend/tcop/pquery.c    16 May 2008 18:37:24 -0000
@@ -24,6 +24,7 @@
 #include "tcop/utility.h"
 #include "utils/memutils.h"
 #include "utils/snapmgr.h"
+#include "pg_trace.h"


 /*
@@ -714,6 +715,8 @@ PortalRun(Portal portal, long count, boo

     AssertArg(PortalIsValid(portal));

+    TRACE_POSTGRESQL_QUERY_EXECUTE_START();
+
     /* Initialize completion tag to empty string */
     if (completionTag)
         completionTag[0] = '\0';
@@ -864,6 +867,8 @@ PortalRun(Portal portal, long count, boo

     if (log_executor_stats && portal->strategy != PORTAL_MULTI_QUERY)
         ShowUsage("EXECUTOR STATISTICS");
+
+    TRACE_POSTGRESQL_QUERY_EXECUTE_DONE();

     return result;
 }
@@ -1234,6 +1239,8 @@ PortalRunMulti(Portal portal, bool isTop
              */
             PlannedStmt *pstmt = (PlannedStmt *) stmt;

+            TRACE_POSTGRESQL_QUERY_EXECUTE_START();
+
             if (log_executor_stats)
                 ResetUsage();

@@ -1254,6 +1261,8 @@ PortalRunMulti(Portal portal, bool isTop

             if (log_executor_stats)
                 ShowUsage("EXECUTOR STATISTICS");
+
+            TRACE_POSTGRESQL_QUERY_EXECUTE_DONE();
         }
         else
         {
Index: backend/utils/probes.d
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/probes.d,v
retrieving revision 1.2
diff -u -3 -p -r1.2 probes.d
--- backend/utils/probes.d    2 Jan 2008 02:42:06 -0000    1.2
+++ backend/utils/probes.d    16 May 2008 18:37:24 -0000
@@ -9,16 +9,60 @@

 provider postgresql {

-probe transaction__start(int);
-probe transaction__commit(int);
-probe transaction__abort(int);
-probe lwlock__acquire(int, int);
-probe lwlock__release(int);
-probe lwlock__startwait(int, int);
-probe lwlock__endwait(int, int);
-probe lwlock__condacquire(int, int);
-probe lwlock__condacquire__fail(int, int);
-probe lock__startwait(int, int);
-probe lock__endwait(int, int);
+    probe transaction__start(int);
+    probe transaction__commit(int);
+    probe transaction__abort(int);
+    probe lwlock__acquire(int, int);
+    probe lwlock__release(int);
+    probe lwlock__startwait(int, int);
+    probe lwlock__endwait(int, int);
+    probe lwlock__condacquire(int, int);
+    probe lwlock__condacquire__fail(int, int);
+    probe lock__startwait(int, int);
+    probe lock__endwait(int, int);
+    probe idle__transaction__start(int, int);
+    probe idle__transaction__done();
+    probe wal__buffer__write__start();
+    probe wal__buffer__write__done();
+    probe query__parse__start(char *query_string);
+    probe query__parse__done();
+    probe query__plan__start();
+    probe query__plan__done();
+    probe query__execute__start();
+    probe query__execute__done();
+    probe query__statement__start(int pid, char *query_string);
+    probe query__statement__done(int pid, char *query_string);
+    probe sort__start(int, int, int, int, int);
+    probe sort__end(int, long);
+    probe buffer__read__start(int blockNum, int tablespaceOid,
+            int databaseOid, int relationOid, int isLocalBuf);
+    probe buffer__read__done(int blockNum, int tablespaceOid,
+             int databaseOid, int relationOid, int isLocalBuf,
+            int isInBuffPool);
+    probe dirty__buffer__write__start(int blockNum, int tablespaceOid,
+            int databaseOid, int relationOid);
+    probe dirty__buffer__write__done(int blockNum, int tablespaceOid,
+             int databaseOid, int relationOid, int isHintBitsWrite);
+    probe buffer__write__start(int blockNum, int tablespaceOid,
+            int databaseOid, int relationOid);
+    probe buffer__write__done(int blockNum, int tablespaceOid,
+             int databaseOid, int relationOid, int isHintBitsWrite);
+    probe buffer__hit();
+    probe buffer__miss();
+    probe deadlock__found();
+    probe deadlock__notfound(int);
+    probe checkpoint__start(int checkpointFlags);
+    probe checkpoint__done(int bufsWritten, int NBuffers, int segsAdded,
+            int segsRemoved, int segsRecycled);
+    probe smgr__read__start(int blockNum, int tablespaceOid,
+            int databaseOid, int relationOid);
+    probe smgr__read__done(int blockNum, int tablespaceOid,
+             int databaseOid, int relationOid, int bytesRead,
+            int blockSize);
+    probe smgr__write__start(int blockNum, int tablespaceOid,
+            int databaseOid, int relationOid);
+    probe smgr__write__done(int blockNum, int tablespaceOid,
+            int databaseOid, int relationOid, int bytesRead,
+            int blockSize);

 };
Index: backend/utils/sort/tuplesort.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/sort/tuplesort.c,v
retrieving revision 1.83
diff -u -3 -p -r1.83 tuplesort.c
--- backend/utils/sort/tuplesort.c    17 Mar 2008 03:45:36 -0000    1.83
+++ backend/utils/sort/tuplesort.c    16 May 2008 18:37:25 -0000
@@ -115,12 +115,18 @@
 #include "utils/pg_rusage.h"
 #include "utils/syscache.h"
 #include "utils/tuplesort.h"
+#include "pg_trace.h"


 /* GUC variables */
 #ifdef TRACE_SORT
 bool        trace_sort = false;
 #endif
+
+#define HEAP_SORT    0
+#define INDEX_SORT    1
+#define DATUM_SORT    2
+
 #ifdef DEBUG_BOUNDED_SORT
 bool        optimize_bounded_sort = true;
 #endif
@@ -569,6 +575,7 @@ tuplesort_begin_heap(TupleDesc tupDesc,
              "begin tuple sort: nkeys = %d, workMem = %d, randomAccess = %c",
              nkeys, workMem, randomAccess ? 't' : 'f');
 #endif
+    TRACE_POSTGRESQL_SORT_START(HEAP_SORT, false, nkeys, workMem, randomAccess);

     state->nKeys = nkeys;

@@ -636,6 +643,8 @@ tuplesort_begin_index_btree(Relation ind

     state->nKeys = RelationGetNumberOfAttributes(indexRel);

+    TRACE_POSTGRESQL_SORT_START(INDEX_SORT, enforceUnique, state->nKeys, workMem, randomAccess);
+
     state->comparetup = comparetup_index_btree;
     state->copytup = copytup_index;
     state->writetup = writetup_index;
@@ -713,6 +722,7 @@ tuplesort_begin_datum(Oid datumType,
              "begin datum sort: workMem = %d, randomAccess = %c",
              workMem, randomAccess ? 't' : 'f');
 #endif
+    TRACE_POSTGRESQL_SORT_START(DATUM_SORT, false, 1, workMem, randomAccess);

     state->nKeys = 1;            /* always a one-column sort */

@@ -825,6 +835,11 @@ tuplesort_end(Tuplesortstate *state)
     }
 #endif

+    TRACE_POSTGRESQL_SORT_END(state->tapeset,
+            (state->tapeset ? LogicalTapeSetBlocks(true) :
+            (state->allowedMem - state->availMem + 1023) / 1024));
+
+
     MemoryContextSwitchTo(oldcontext);

     /*
Index: include/storage/buf_internals.h
===================================================================
RCS file: /projects/cvsroot/pgsql/src/include/storage/buf_internals.h,v
retrieving revision 1.95
diff -u -3 -p -r1.95 buf_internals.h
--- include/storage/buf_internals.h    1 Jan 2008 19:45:58 -0000    1.95
+++ include/storage/buf_internals.h    16 May 2008 18:37:27 -0000
@@ -36,6 +36,7 @@
 #define BM_JUST_DIRTIED            (1 << 5)        /* dirtied since write started */
 #define BM_PIN_COUNT_WAITER        (1 << 6)        /* have waiter for sole pin */
 #define BM_CHECKPOINT_NEEDED    (1 << 7)        /* must write for checkpoint */
+#define BM_HINT_BITS_TEST    (1 << 8)        /* test effect of writes due to hint bits */

 typedef bits16 BufFlags;