Add a few more DTrace probes to the backend.

Robert Lor

4 files changed, 55 insertions, 11 deletions

diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c
index bd8529d617c..e40a815b5dd 100644
--- a/src/backend/storage/buffer/bufmgr.c
+++ b/src/backend/storage/buffer/bufmgr.c
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.234 2008/07/13 20:45:47 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.235 2008/08/01 13:16:08 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -34,6 +34,8 @@
 #include <unistd.h>
 
 #include "miscadmin.h"
+#include "pg_trace.h"
+#include "pgstat.h"
 #include "postmaster/bgwriter.h"
 #include "storage/buf_internals.h"
 #include "storage/bufmgr.h"
@@ -42,7 +44,6 @@
 #include "storage/smgr.h"
 #include "utils/rel.h"
 #include "utils/resowner.h"
-#include "pgstat.h"
 
 
 /* Note: these two macros only work on shared buffers, not local ones! */
@@ -213,12 +214,22 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, BlockNumber blockNum,
 	if (isExtend)
 		blockNum = smgrnblocks(smgr);
 
+	TRACE_POSTGRESQL_BUFFER_READ_START(blockNum, smgr->smgr_rnode.spcNode,
+		smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode, isLocalBuf);
+
 	if (isLocalBuf)
 	{
 		ReadLocalBufferCount++;
 		bufHdr = LocalBufferAlloc(smgr, blockNum, &found);
 		if (found)
+		{
 			LocalBufferHitCount++;
+			TRACE_POSTGRESQL_BUFFER_HIT(true); /* true == local buffer */
+		}
+		else
+		{
+			TRACE_POSTGRESQL_BUFFER_MISS(true); /* ditto */
+		}
 	}
 	else
 	{
@@ -230,7 +241,14 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, BlockNumber blockNum,
 		 */
 		bufHdr = BufferAlloc(smgr, blockNum, strategy, &found);
 		if (found)
+		{
 			BufferHitCount++;
+			TRACE_POSTGRESQL_BUFFER_HIT(false); /* false != local buffer */
+		}
+		else
+		{
+			TRACE_POSTGRESQL_BUFFER_MISS(false); /* ditto */
+		}
 	}
 
 	/* At this point we do NOT hold any locks. */
@@ -246,6 +264,11 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, BlockNumber blockNum,
 			if (VacuumCostActive)
 				VacuumCostBalance += VacuumCostPageHit;
 
+			TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum,
+				smgr->smgr_rnode.spcNode,
+				smgr->smgr_rnode.dbNode,
+				smgr->smgr_rnode.relNode, isLocalBuf, found);
+
 			return BufferDescriptorGetBuffer(bufHdr);
 		}
 
@@ -368,6 +391,10 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, BlockNumber blockNum,
 	if (VacuumCostActive)
 		VacuumCostBalance += VacuumCostPageMiss;
 
+	TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum, smgr->smgr_rnode.spcNode,
+			smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode,
+			isLocalBuf, found);
+
 	return BufferDescriptorGetBuffer(bufHdr);
 }
 
@@ -1086,6 +1113,8 @@ BufferSync(int flags)
 	if (num_to_write == 0)
 		return;					/* nothing to do */
 
+	TRACE_POSTGRESQL_BUFFER_SYNC_START(NBuffers, num_to_write);
+
 	/*
 	 * Loop over all buffers again, and write the ones (still) marked with
 	 * BM_CHECKPOINT_NEEDED.  In this loop, we start at the clock sweep point
@@ -1117,6 +1146,7 @@ BufferSync(int flags)
 		{
 			if (SyncOneBuffer(buf_id, false) & BUF_WRITTEN)
 			{
+				TRACE_POSTGRESQL_BUFFER_SYNC_WRITTEN(buf_id);
 				BgWriterStats.m_buf_written_checkpoints++;
 				num_written++;
 
@@ -1147,6 +1177,8 @@ BufferSync(int flags)
 			buf_id = 0;
 	}
 
+	TRACE_POSTGRESQL_BUFFER_SYNC_DONE(NBuffers, num_written, num_to_write);
+
 	/*
 	 * Update checkpoint statistics. As noted above, this doesn't include
 	 * buffers written by other backends or bgwriter scan.
@@ -1653,11 +1685,13 @@ PrintBufferLeakWarning(Buffer buffer)
 void
 CheckPointBuffers(int flags)
 {
+	TRACE_POSTGRESQL_BUFFER_CHECKPOINT_START(flags);
 	CheckpointStats.ckpt_write_t = GetCurrentTimestamp();
 	BufferSync(flags);
 	CheckpointStats.ckpt_sync_t = GetCurrentTimestamp();
 	smgrsync();
 	CheckpointStats.ckpt_sync_end_t = GetCurrentTimestamp();
+	TRACE_POSTGRESQL_BUFFER_CHECKPOINT_DONE();
 }
 
 
@@ -1759,6 +1793,10 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
 	if (reln == NULL)
 		reln = smgropen(buf->tag.rnode);
 
+	TRACE_POSTGRESQL_BUFFER_FLUSH_START(reln->smgr_rnode.spcNode,
+		 reln->smgr_rnode.dbNode,
+		 reln->smgr_rnode.relNode);
+
 	/*
 	 * Force XLOG flush up to buffer's LSN.  This implements the basic WAL
 	 * rule that log updates must hit disk before any of the data-file changes
@@ -1785,6 +1823,9 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln)
 
 	BufferFlushCount++;
 
+	TRACE_POSTGRESQL_BUFFER_FLUSH_DONE(reln->smgr_rnode.spcNode,
+		 reln->smgr_rnode.dbNode, reln->smgr_rnode.relNode);
+
 	/*
 	 * Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and
 	 * end the io_in_progress state.
diff --git a/src/backend/storage/lmgr/deadlock.c b/src/backend/storage/lmgr/deadlock.c
index 97be7d9dc72..8a564a1754c 100644
--- a/src/backend/storage/lmgr/deadlock.c
+++ b/src/backend/storage/lmgr/deadlock.c
@@ -12,7 +12,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/deadlock.c,v 1.53 2008/03/24 18:22:36 tgl Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/deadlock.c,v 1.54 2008/08/01 13:16:09 alvherre Exp $
  *
  *	Interface:
  *
@@ -26,6 +26,7 @@
 #include "postgres.h"
 
 #include "miscadmin.h"
+#include "pg_trace.h"
 #include "pgstat.h"
 #include "storage/lmgr.h"
 #include "storage/proc.h"
@@ -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");
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index fbd1be586bb..991d94fe353 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/lock.c,v 1.183 2008/03/17 19:44:41 petere Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/lock.c,v 1.184 2008/08/01 13:16:09 alvherre Exp $
  *
  * NOTES
  *	  A lock table is a shared memory hash table.  When
@@ -36,11 +36,11 @@
 #include "access/twophase.h"
 #include "access/twophase_rmgr.h"
 #include "miscadmin.h"
+#include "pg_trace.h"
 #include "pgstat.h"
 #include "utils/memutils.h"
 #include "utils/ps_status.h"
 #include "utils/resowner.h"
-#include "pg_trace.h"
 
 
 /* This configuration variable is used to set the lock table size */
@@ -787,11 +787,11 @@ LockAcquire(const LOCKTAG *locktag,
 		 * Sleep till someone wakes me up.
 		 */
 
-		TRACE_POSTGRESQL_LOCK_STARTWAIT(locktag->locktag_field2, lockmode);
+		TRACE_POSTGRESQL_LOCK_WAIT_START(locktag->locktag_field2, lockmode);
 
 		WaitOnLock(locallock, owner);
 
-		TRACE_POSTGRESQL_LOCK_ENDWAIT(locktag->locktag_field2, lockmode);
+		TRACE_POSTGRESQL_LOCK_WAIT_DONE(locktag->locktag_field2, lockmode);
 
 		/*
 		 * NOTE: do not do any material change of state between here and
diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c
index 5fcad46f2fa..488b7bdc5ac 100644
--- a/src/backend/storage/lmgr/lwlock.c
+++ b/src/backend/storage/lmgr/lwlock.c
@@ -15,7 +15,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/lwlock.c,v 1.51 2008/03/17 19:44:41 petere Exp $
+ *	  $PostgreSQL: pgsql/src/backend/storage/lmgr/lwlock.c,v 1.52 2008/08/01 13:16:09 alvherre Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -25,10 +25,10 @@
 #include "access/multixact.h"
 #include "access/subtrans.h"
 #include "miscadmin.h"
+#include "pg_trace.h"
 #include "storage/ipc.h"
 #include "storage/proc.h"
 #include "storage/spin.h"
-#include "pg_trace.h"
 
 
 /* We use the ShmemLock spinlock to protect LWLockAssign */
@@ -448,7 +448,7 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 		block_counts[lockid]++;
 #endif
 
-		TRACE_POSTGRESQL_LWLOCK_STARTWAIT(lockid, mode);
+		TRACE_POSTGRESQL_LWLOCK_WAIT_START(lockid, mode);
 
 		for (;;)
 		{
@@ -459,7 +459,7 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode)
 			extraWaits++;
 		}
 
-		TRACE_POSTGRESQL_LWLOCK_ENDWAIT(lockid, mode);
+		TRACE_POSTGRESQL_LWLOCK_WAIT_DONE(lockid, mode);
 
 		LOG_LWDEBUG("LWLockAcquire", lockid, "awakened");