DTrace probes patch

Should I apply this or hold it for 8.5?

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

Robert Lor wrote:

The attached patch contains a couple of fixes in the existing probes and
includes a few new ones.

- Fixed compilation errors on OS X for probes that use typedefs
- Fixed a number of probes to pass ForkNumber per the relation forks patch
- The new probes are those that were taken out from the previous
submitted patch and required simple fixes. Will submit the other probes
that may require more discussion in a separate patch.

-Robert

Index: src/backend/access/transam/xlog.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/access/transam/xlog.c,v
retrieving revision 1.322
diff -u -3 -p -r1.322 xlog.c
--- src/backend/access/transam/xlog.c	9 Nov 2008 17:51:15 -0000	1.322
+++ src/backend/access/transam/xlog.c	15 Dec 2008 05:12:41 -0000
@@ -48,6 +48,7 @@
#include "utils/builtins.h"
#include "utils/guc.h"
#include "utils/ps_status.h"
+#include "pg_trace.h"

/* File path names (all relative to $PGDATA) */
@@ -486,6 +487,8 @@ XLogInsert(RmgrId rmid, uint8 info, XLog
if (info & XLR_INFO_MASK)
elog(PANIC, "invalid xlog info mask %02X", info);

+	TRACE_POSTGRESQL_XLOG_INSERT(rmid, info);
+
/*
* In bootstrap mode, we don't actually log anything but XLOG resources;
* return a phony record pointer.
@@ -914,6 +917,8 @@ begin:;
XLogwrtRqst FlushRqst;
XLogRecPtr	OldSegEnd;

+		TRACE_POSTGRESQL_XLOG_SWITCH();
+
LWLockAcquire(WALWriteLock, LW_EXCLUSIVE);

/*
@@ -1313,12 +1318,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();
}
}
}
@@ -5904,6 +5911,8 @@ CreateCheckPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags);

+	TRACE_POSTGRESQL_CHECKPOINT_START(flags);
+
/*
* Before flushing data, we must wait for any transactions that are
* currently in their commit critical sections.  If an xact inserted its
@@ -6069,6 +6078,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: src/backend/storage/buffer/bufmgr.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/buffer/bufmgr.c,v
retrieving revision 1.242
diff -u -3 -p -r1.242 bufmgr.c
--- src/backend/storage/buffer/bufmgr.c	19 Nov 2008 10:34:52 -0000	1.242
+++ src/backend/storage/buffer/bufmgr.c	15 Dec 2008 05:12:45 -0000
@@ -203,8 +203,7 @@ ReadBuffer_common(SMgrRelation smgr, boo
if (isExtend)
blockNum = smgrnblocks(smgr, forkNum);

-	TRACE_POSTGRESQL_BUFFER_READ_START(blockNum, smgr->smgr_rnode.spcNode,
-		smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode, isLocalBuf);
+	TRACE_POSTGRESQL_BUFFER_READ_START(forkNum, blockNum, smgr->smgr_rnode.spcNode, smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode, isLocalBuf);

if (isLocalBuf)
{
@@ -253,7 +252,7 @@ ReadBuffer_common(SMgrRelation smgr, boo
if (VacuumCostActive)
VacuumCostBalance += VacuumCostPageHit;

-			TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum,
+			TRACE_POSTGRESQL_BUFFER_READ_DONE(forkNum, blockNum,
smgr->smgr_rnode.spcNode,
smgr->smgr_rnode.dbNode,
smgr->smgr_rnode.relNode, isLocalBuf, found);
@@ -380,9 +379,9 @@ ReadBuffer_common(SMgrRelation smgr, boo
if (VacuumCostActive)
VacuumCostBalance += VacuumCostPageMiss;

-	TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum, smgr->smgr_rnode.spcNode,
-			smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode,
-			isLocalBuf, found);
+	TRACE_POSTGRESQL_BUFFER_READ_DONE(forkNum, blockNum,
+			smgr->smgr_rnode.spcNode, smgr->smgr_rnode.dbNode,
+			smgr->smgr_rnode.relNode, isLocalBuf, found);

return BufferDescriptorGetBuffer(bufHdr);
}
@@ -526,6 +525,11 @@ BufferAlloc(SMgrRelation smgr, ForkNumbe
* happens to be trying to split the page the first one got from
* StrategyGetBuffer.)
*/
+
+                        TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY_START(forkNum,
+			  blockNum, smgr->smgr_rnode.spcNode,
+			  smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode);
+
if (LWLockConditionalAcquire(buf->content_lock, LW_SHARED))
{
/*
@@ -548,6 +552,11 @@ BufferAlloc(SMgrRelation smgr, ForkNumbe
/* OK, do the I/O */
FlushBuffer(buf, NULL);
LWLockRelease(buf->content_lock);
+
+                                TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY_DONE(
+                                  forkNum, blockNum, smgr->smgr_rnode.spcNode,
+                                  smgr->smgr_rnode.dbNode,
+				  smgr->smgr_rnode.relNode);
}
else
{
@@ -1682,6 +1691,7 @@ CheckPointBuffers(int flags)
CheckpointStats.ckpt_write_t = GetCurrentTimestamp();
BufferSync(flags);
CheckpointStats.ckpt_sync_t = GetCurrentTimestamp();
+	TRACE_POSTGRESQL_BUFFER_CHECKPOINT_SYNC_START();
smgrsync();
CheckpointStats.ckpt_sync_end_t = GetCurrentTimestamp();
TRACE_POSTGRESQL_BUFFER_CHECKPOINT_DONE();
Index: src/backend/storage/smgr/md.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/smgr/md.c,v
retrieving revision 1.141
diff -u -3 -p -r1.141 md.c
--- src/backend/storage/smgr/md.c	14 Nov 2008 11:09:50 -0000	1.141
+++ src/backend/storage/smgr/md.c	15 Dec 2008 05:12:46 -0000
@@ -27,6 +27,7 @@
#include "storage/smgr.h"
#include "utils/hsearch.h"
#include "utils/memutils.h"
+#include "pg_trace.h"

/* interval for calling AbsorbFsyncRequests in mdsync */
@@ -560,6 +561,8 @@ mdread(SMgrRelation reln, ForkNumber for
int nbytes;
MdfdVec *v;

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

seekpos = (off_t) BLCKSZ * (blocknum % ((BlockNumber) RELSEG_SIZE));
@@ -571,7 +574,11 @@ mdread(SMgrRelation reln, ForkNumber for
errmsg("could not seek to block %u of relation %s: %m",
blocknum, relpath(reln->smgr_rnode, forknum))));

-	if ((nbytes = FileRead(v->mdfd_vfd, buffer, BLCKSZ)) != BLCKSZ)
+	nbytes = FileRead(v->mdfd_vfd, buffer, BLCKSZ);
+
+	TRACE_POSTGRESQL_SMGR_MD_READ_DONE(forknum, blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode, reln->smgr_rnode.relNode, relpath(reln->smgr_rnode, forknum), nbytes, BLCKSZ);
+
+	if (nbytes != BLCKSZ)
{
if (nbytes < 0)
ereport(ERROR,
@@ -618,6 +625,8 @@ mdwrite(SMgrRelation reln, ForkNumber fo
Assert(blocknum < mdnblocks(reln, forknum));
#endif

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

seekpos = (off_t) BLCKSZ * (blocknum % ((BlockNumber) RELSEG_SIZE));
@@ -629,7 +638,11 @@ mdwrite(SMgrRelation reln, ForkNumber fo
errmsg("could not seek to block %u of relation %s: %m",
blocknum, relpath(reln->smgr_rnode, forknum))));

-	if ((nbytes = FileWrite(v->mdfd_vfd, buffer, BLCKSZ)) != BLCKSZ)
+	nbytes = FileWrite(v->mdfd_vfd, buffer, BLCKSZ);
+
+	TRACE_POSTGRESQL_SMGR_MD_WRITE_DONE(forknum, blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode, reln->smgr_rnode.relNode, relpath(reln->smgr_rnode, forknum), nbytes, BLCKSZ);
+
+	if (nbytes != BLCKSZ)
{
if (nbytes < 0)
ereport(ERROR,
Index: src/backend/utils/probes.d
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/probes.d,v
retrieving revision 1.3
diff -u -3 -p -r1.3 probes.d
--- src/backend/utils/probes.d	1 Aug 2008 13:16:09 -0000	1.3
+++ src/backend/utils/probes.d	15 Dec 2008 05:12:46 -0000
@@ -9,20 +9,19 @@

/* typedefs used in PostgreSQL */
-typedef unsigned int LocalTransactionId;
-typedef int LWLockId;
-typedef int LWLockMode;
-typedef int LOCKMODE;
-typedef unsigned int BlockNumber;
-typedef unsigned int Oid;
-
+#define LocalTransactionId unsigned int
+#define LWLockId int
+#define LWLockMode int
+#define LOCKMODE int
+#define BlockNumber unsigned int
+#define Oid unsigned int
+#define ForkNumber int
#define bool char

provider postgresql {

/* 
-	 * Due to a bug in Mac OS X 10.5, using built-in typedefs (e.g. uintptr_t,
-	 * uint32_t, etc.) cause compilation errors.  
+	 * Note: Do not use built-in typedefs (e.g. uintptr_t, uint32_t, etc)		 *       as they cause compilation errors in Mac OS X 10.5.  
*/

probe transaction__start(LocalTransactionId);
@@ -36,13 +35,8 @@ provider postgresql {
probe lwlock__condacquire(LWLockId, LWLockMode);
probe lwlock__condacquire__fail(LWLockId, LWLockMode);

-	/* The following probe declarations cause compilation errors
-         * on Mac OS X but not on Solaris. Need further investigation.
-	 * probe lock__wait__start(unsigned int, LOCKMODE);
-	 * probe lock__wait__done(unsigned int, LOCKMODE);
-	 */
-	probe lock__wait__start(unsigned int, int);
-	probe lock__wait__done(unsigned int, int);
+	probe lock__wait__start(unsigned int, LOCKMODE);
+	probe lock__wait__done(unsigned int, LOCKMODE);

probe query__parse__start(const char *);
probe query__parse__done(const char *);
@@ -59,27 +53,27 @@ provider postgresql {
probe sort__start(int, bool, int, int, bool);
probe sort__done(unsigned long, long);

-	/* The following probe declarations cause compilation errors
-         * on Mac OS X but not on Solaris. Need further investigation.
-	 * probe buffer__read__start(BlockNumber, Oid, Oid, Oid, bool);
-	 * probe buffer__read__done(BlockNumber, Oid, Oid, Oid, bool, bool);
-	 */
-	probe buffer__read__start(unsigned int, unsigned int, unsigned int, unsigned int, bool);
-	probe buffer__read__done(unsigned int, unsigned int, unsigned int, unsigned int, bool, bool);
-
+	probe buffer__read__start(ForkNumber, BlockNumber, Oid, Oid, Oid, bool);
+	probe buffer__read__done(ForkNumber, BlockNumber, Oid, Oid, Oid,
+					 bool, bool);
probe buffer__flush__start(Oid, Oid, Oid);
probe buffer__flush__done(Oid, Oid, Oid);

probe buffer__hit(bool);
probe buffer__miss(bool);
probe buffer__checkpoint__start(int);
+	probe buffer__checkpoint__sync__start();
probe buffer__checkpoint__done();
probe buffer__sync__start(int, int);
probe buffer__sync__written(int);
probe buffer__sync__done(int, int, int);
+	probe buffer__write__dirty__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
+	probe buffer__write__dirty__done(ForkNumber, BlockNumber, Oid, Oid, Oid);

probe deadlock__found();

+	probe checkpoint__start(int);
+	probe checkpoint__done(int, int, int, int, int);
probe clog__checkpoint__start(bool);
probe clog__checkpoint__done(bool);
probe subtrans__checkpoint__start(bool);
@@ -88,4 +82,16 @@ provider postgresql {
probe multixact__checkpoint__done(bool);
probe twophase__checkpoint__start();
probe twophase__checkpoint__done();
+
+	probe smgr__md__read__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
+	probe smgr__md__read__done(ForkNumber, BlockNumber, Oid, Oid, Oid,
+                                   const char *, int, int);
+	probe smgr__md__write__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
+	probe smgr__md__write__done(ForkNumber, BlockNumber, Oid, Oid, Oid,
+                                    const char *, int, int);
+
+	probe xlog__insert(unsigned char, unsigned char);
+	probe xlog__switch();
+	probe wal__buffer__write__start();
+	probe wal__buffer__write__done();
};

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

Robert Lor wrote:

The attached patch contains a couple of fixes in the existing probes and
includes a few new ones.

- Fixed compilation errors on OS X for probes that use typedefs

Could you explain what these errors are about? I don't see any errors
on my machine.

Peter Eisentraut wrote:

Robert Lor wrote:

The attached patch contains a couple of fixes in the existing probes
and includes a few new ones.

- Fixed compilation errors on OS X for probes that use typedefs

Could you explain what these errors are about? I don't see any errors
on my machine.

In the current probes.d, the following probe definitions are commented
out because they cause compilation errors on OS X.

* probe lock__wait__start(unsigned int, LOCKMODE);
* probe lock__wait__done(unsigned int, LOCKMODE);
* probe buffer__read__start(BlockNumber, Oid, Oid, Oid, bool);
* probe buffer__read__done(BlockNumber, Oid, Oid, Oid, bool, bool);

The problem was fixed by making the changes below. probes.d is
preprocessed with cpp and as such only macros get expanded.

From:

typedef unsigned int LocalTransactionId;
typedef int LWLockId;
typedef int LWLockMode;
typedef int LOCKMODE;
typedef unsigned int BlockNumber;
typedef unsigned int Oid;
typedef int ForkNumber;

To:

#define LocalTransactionId unsigned int
#define LWLockId int
#define LWLockMode int
#define LOCKMODE int
#define BlockNumber unsigned int
#define Oid unsigned int
#define ForkNumber int

Robert Lor wrote:

Peter Eisentraut wrote:

Robert Lor wrote:

The attached patch contains a couple of fixes in the existing probes
and includes a few new ones.

- Fixed compilation errors on OS X for probes that use typedefs

Could you explain what these errors are about? I don't see any errors
on my machine.

In the current probes.d, the following probe definitions are commented
out because they cause compilation errors on OS X.

Yeah, this was something we agreed to fix when we committed the previous
DTrace patch. The current code was said to be a stopgap.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Bruce Momjian wrote:

Should I apply this or hold it for 8.5?

I think it should go into 8.4 as it also fixes existing problems.

-Robert

Robert Lor wrote:

Bruce Momjian wrote:

Should I apply this or hold it for 8.5?

I think it should go into 8.4 as it also fixes existing problems.

I am seeing the following error when linking the backend on a BSD machine:

./../src/port/libpgport_srv.a -lssl -lcrypto -lgetopt -ldl -lutil -lm -o
postgres
storage/buffer/bufmgr.o: In function `ReadBuffer_common':
storage/buffer/bufmgr.o(.text+0x4e2): undefined reference to
`TRACE_POSTGRESQL_BUFFER_READ_DONE'
storage/smgr/md.o: In function `mdread':
storage/smgr/md.o(.text+0x8a7): undefined reference to
`TRACE_POSTGRESQL_SMGR_MD_READ_DONE'
storage/smgr/md.o: In function `mdwrite':
storage/smgr/md.o(.text+0xab6): undefined reference to
`TRACE_POSTGRESQL_SMGR_MD_WRITE_DONE'
gmake[2]: *** [postgres] Error 1
gmake[2]: Leaving directory
`/usr/var/local/src/gen/pgsql/CURRENT/pgsql/src/backend'
gmake[1]: *** [all] Error 2
gmake[1]: Leaving directory
`/usr/var/local/src/gen/pgsql/CURRENT/pgsql/src'

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

Bruce Momjian wrote:

I am seeing the following error when linking the backend on a BSD machine:

./../src/port/libpgport_srv.a -lssl -lcrypto -lgetopt -ldl -lutil -lm -o
postgres
storage/buffer/bufmgr.o: In function `ReadBuffer_common':
storage/buffer/bufmgr.o(.text+0x4e2): undefined reference to
`TRACE_POSTGRESQL_BUFFER_READ_DONE'
storage/smgr/md.o: In function `mdread':
storage/smgr/md.o(.text+0x8a7): undefined reference to

The reason is that Gen_dummy_probes.sed handles only up to 6 args, and
this function has 7. Just add one more line to that file.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Bruce Momjian wrote:

I am seeing the following error when linking the backend on a BSD machine:

The updated patch attached should fix this problem. My bad for
overlooking this.

-Robert

Thanks, applied.

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

Robert Lor wrote:

Bruce Momjian wrote:

I am seeing the following error when linking the backend on a BSD machine:

The updated patch attached should fix this problem. My bad for
overlooking this.

-Robert

Index: src/backend/access/transam/xlog.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/access/transam/xlog.c,v
retrieving revision 1.322
diff -u -3 -p -r1.322 xlog.c
--- src/backend/access/transam/xlog.c	9 Nov 2008 17:51:15 -0000	1.322
+++ src/backend/access/transam/xlog.c	16 Dec 2008 19:46:08 -0000
@@ -48,6 +48,7 @@
#include "utils/builtins.h"
#include "utils/guc.h"
#include "utils/ps_status.h"
+#include "pg_trace.h"

/* File path names (all relative to $PGDATA) */
@@ -486,6 +487,8 @@ XLogInsert(RmgrId rmid, uint8 info, XLog
if (info & XLR_INFO_MASK)
elog(PANIC, "invalid xlog info mask %02X", info);

+	TRACE_POSTGRESQL_XLOG_INSERT(rmid, info);
+
/*
* In bootstrap mode, we don't actually log anything but XLOG resources;
* return a phony record pointer.
@@ -914,6 +917,8 @@ begin:;
XLogwrtRqst FlushRqst;
XLogRecPtr	OldSegEnd;

+		TRACE_POSTGRESQL_XLOG_SWITCH();
+
LWLockAcquire(WALWriteLock, LW_EXCLUSIVE);

/*
@@ -1313,12 +1318,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();
}
}
}
@@ -5904,6 +5911,8 @@ CreateCheckPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags);

+	TRACE_POSTGRESQL_CHECKPOINT_START(flags);
+
/*
* Before flushing data, we must wait for any transactions that are
* currently in their commit critical sections.  If an xact inserted its
@@ -6069,6 +6078,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: src/backend/storage/buffer/bufmgr.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/buffer/bufmgr.c,v
retrieving revision 1.242
diff -u -3 -p -r1.242 bufmgr.c
--- src/backend/storage/buffer/bufmgr.c	19 Nov 2008 10:34:52 -0000	1.242
+++ src/backend/storage/buffer/bufmgr.c	16 Dec 2008 19:46:11 -0000
@@ -203,8 +203,7 @@ ReadBuffer_common(SMgrRelation smgr, boo
if (isExtend)
blockNum = smgrnblocks(smgr, forkNum);

-	TRACE_POSTGRESQL_BUFFER_READ_START(blockNum, smgr->smgr_rnode.spcNode,
-		smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode, isLocalBuf);
+	TRACE_POSTGRESQL_BUFFER_READ_START(forkNum, blockNum, smgr->smgr_rnode.spcNode, smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode, isLocalBuf);

if (isLocalBuf)
{
@@ -253,7 +252,7 @@ ReadBuffer_common(SMgrRelation smgr, boo
if (VacuumCostActive)
VacuumCostBalance += VacuumCostPageHit;

-			TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum,
+			TRACE_POSTGRESQL_BUFFER_READ_DONE(forkNum, blockNum,
smgr->smgr_rnode.spcNode,
smgr->smgr_rnode.dbNode,
smgr->smgr_rnode.relNode, isLocalBuf, found);
@@ -380,9 +379,9 @@ ReadBuffer_common(SMgrRelation smgr, boo
if (VacuumCostActive)
VacuumCostBalance += VacuumCostPageMiss;

-	TRACE_POSTGRESQL_BUFFER_READ_DONE(blockNum, smgr->smgr_rnode.spcNode,
-			smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode,
-			isLocalBuf, found);
+	TRACE_POSTGRESQL_BUFFER_READ_DONE(forkNum, blockNum,
+			smgr->smgr_rnode.spcNode, smgr->smgr_rnode.dbNode,
+			smgr->smgr_rnode.relNode, isLocalBuf, found);

return BufferDescriptorGetBuffer(bufHdr);
}
@@ -526,6 +525,11 @@ BufferAlloc(SMgrRelation smgr, ForkNumbe
* happens to be trying to split the page the first one got from
* StrategyGetBuffer.)
*/
+
+                        TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY_START(forkNum,
+			  blockNum, smgr->smgr_rnode.spcNode,
+			  smgr->smgr_rnode.dbNode, smgr->smgr_rnode.relNode);
+
if (LWLockConditionalAcquire(buf->content_lock, LW_SHARED))
{
/*
@@ -548,6 +552,11 @@ BufferAlloc(SMgrRelation smgr, ForkNumbe
/* OK, do the I/O */
FlushBuffer(buf, NULL);
LWLockRelease(buf->content_lock);
+
+                                TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY_DONE(
+                                  forkNum, blockNum, smgr->smgr_rnode.spcNode,
+                                  smgr->smgr_rnode.dbNode,
+				  smgr->smgr_rnode.relNode);
}
else
{
@@ -1682,6 +1691,7 @@ CheckPointBuffers(int flags)
CheckpointStats.ckpt_write_t = GetCurrentTimestamp();
BufferSync(flags);
CheckpointStats.ckpt_sync_t = GetCurrentTimestamp();
+	TRACE_POSTGRESQL_BUFFER_CHECKPOINT_SYNC_START();
smgrsync();
CheckpointStats.ckpt_sync_end_t = GetCurrentTimestamp();
TRACE_POSTGRESQL_BUFFER_CHECKPOINT_DONE();
Index: src/backend/storage/smgr/md.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/storage/smgr/md.c,v
retrieving revision 1.141
diff -u -3 -p -r1.141 md.c
--- src/backend/storage/smgr/md.c	14 Nov 2008 11:09:50 -0000	1.141
+++ src/backend/storage/smgr/md.c	16 Dec 2008 19:46:12 -0000
@@ -27,6 +27,7 @@
#include "storage/smgr.h"
#include "utils/hsearch.h"
#include "utils/memutils.h"
+#include "pg_trace.h"

/* interval for calling AbsorbFsyncRequests in mdsync */
@@ -560,6 +561,8 @@ mdread(SMgrRelation reln, ForkNumber for
int nbytes;
MdfdVec *v;

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

seekpos = (off_t) BLCKSZ * (blocknum % ((BlockNumber) RELSEG_SIZE));
@@ -571,7 +574,11 @@ mdread(SMgrRelation reln, ForkNumber for
errmsg("could not seek to block %u of relation %s: %m",
blocknum, relpath(reln->smgr_rnode, forknum))));

-	if ((nbytes = FileRead(v->mdfd_vfd, buffer, BLCKSZ)) != BLCKSZ)
+	nbytes = FileRead(v->mdfd_vfd, buffer, BLCKSZ);
+
+	TRACE_POSTGRESQL_SMGR_MD_READ_DONE(forknum, blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode, reln->smgr_rnode.relNode, relpath(reln->smgr_rnode, forknum), nbytes, BLCKSZ);
+
+	if (nbytes != BLCKSZ)
{
if (nbytes < 0)
ereport(ERROR,
@@ -618,6 +625,8 @@ mdwrite(SMgrRelation reln, ForkNumber fo
Assert(blocknum < mdnblocks(reln, forknum));
#endif

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

seekpos = (off_t) BLCKSZ * (blocknum % ((BlockNumber) RELSEG_SIZE));
@@ -629,7 +638,11 @@ mdwrite(SMgrRelation reln, ForkNumber fo
errmsg("could not seek to block %u of relation %s: %m",
blocknum, relpath(reln->smgr_rnode, forknum))));

-	if ((nbytes = FileWrite(v->mdfd_vfd, buffer, BLCKSZ)) != BLCKSZ)
+	nbytes = FileWrite(v->mdfd_vfd, buffer, BLCKSZ);
+
+	TRACE_POSTGRESQL_SMGR_MD_WRITE_DONE(forknum, blocknum, reln->smgr_rnode.spcNode, reln->smgr_rnode.dbNode, reln->smgr_rnode.relNode, relpath(reln->smgr_rnode, forknum), nbytes, BLCKSZ);
+
+	if (nbytes != BLCKSZ)
{
if (nbytes < 0)
ereport(ERROR,
Index: src/backend/utils/Gen_dummy_probes.sed
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/Gen_dummy_probes.sed,v
retrieving revision 1.2
diff -u -3 -p -r1.2 Gen_dummy_probes.sed
--- src/backend/utils/Gen_dummy_probes.sed	1 Aug 2008 13:16:09 -0000	1.2
+++ src/backend/utils/Gen_dummy_probes.sed	16 Dec 2008 19:46:13 -0000
@@ -17,5 +17,7 @@ s/([^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}
s/([^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\})/(INT1, INT2, INT3, INT4)/
s/([^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\})/(INT1, INT2, INT3, INT4, INT5)/
s/([^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\})/(INT1, INT2, INT3, INT4, INT5, INT6)/
+s/([^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\})/(INT1, INT2, INT3, INT4, INT5, INT6, INT7)/
+s/([^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\}, [^,)]\{1,\})/(INT1, INT2, INT3, INT4, INT5, INT6, INT7, INT8)/
P
s/(.*$/_ENABLED() (0)/
Index: src/backend/utils/probes.d
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/probes.d,v
retrieving revision 1.3
diff -u -3 -p -r1.3 probes.d
--- src/backend/utils/probes.d	1 Aug 2008 13:16:09 -0000	1.3
+++ src/backend/utils/probes.d	16 Dec 2008 19:46:13 -0000
@@ -9,20 +9,19 @@

/* typedefs used in PostgreSQL */
-typedef unsigned int LocalTransactionId;
-typedef int LWLockId;
-typedef int LWLockMode;
-typedef int LOCKMODE;
-typedef unsigned int BlockNumber;
-typedef unsigned int Oid;
-
+#define LocalTransactionId unsigned int
+#define LWLockId int
+#define LWLockMode int
+#define LOCKMODE int
+#define BlockNumber unsigned int
+#define Oid unsigned int
+#define ForkNumber int
#define bool char

provider postgresql {

/* 
-	 * Due to a bug in Mac OS X 10.5, using built-in typedefs (e.g. uintptr_t,
-	 * uint32_t, etc.) cause compilation errors.  
+	 * Note: Do not use built-in typedefs (e.g. uintptr_t, uint32_t, etc)		 *       as they cause compilation errors in Mac OS X 10.5.  
*/

probe transaction__start(LocalTransactionId);
@@ -36,13 +35,8 @@ provider postgresql {
probe lwlock__condacquire(LWLockId, LWLockMode);
probe lwlock__condacquire__fail(LWLockId, LWLockMode);

-	/* The following probe declarations cause compilation errors
-         * on Mac OS X but not on Solaris. Need further investigation.
-	 * probe lock__wait__start(unsigned int, LOCKMODE);
-	 * probe lock__wait__done(unsigned int, LOCKMODE);
-	 */
-	probe lock__wait__start(unsigned int, int);
-	probe lock__wait__done(unsigned int, int);
+	probe lock__wait__start(unsigned int, LOCKMODE);
+	probe lock__wait__done(unsigned int, LOCKMODE);

probe query__parse__start(const char *);
probe query__parse__done(const char *);
@@ -59,27 +53,26 @@ provider postgresql {
probe sort__start(int, bool, int, int, bool);
probe sort__done(unsigned long, long);

-	/* The following probe declarations cause compilation errors
-         * on Mac OS X but not on Solaris. Need further investigation.
-	 * probe buffer__read__start(BlockNumber, Oid, Oid, Oid, bool);
-	 * probe buffer__read__done(BlockNumber, Oid, Oid, Oid, bool, bool);
-	 */
-	probe buffer__read__start(unsigned int, unsigned int, unsigned int, unsigned int, bool);
-	probe buffer__read__done(unsigned int, unsigned int, unsigned int, unsigned int, bool, bool);
-
+	probe buffer__read__start(ForkNumber, BlockNumber, Oid, Oid, Oid, bool);
+	probe buffer__read__done(ForkNumber, BlockNumber, Oid, Oid, Oid, bool, bool);
probe buffer__flush__start(Oid, Oid, Oid);
probe buffer__flush__done(Oid, Oid, Oid);

probe buffer__hit(bool);
probe buffer__miss(bool);
probe buffer__checkpoint__start(int);
+	probe buffer__checkpoint__sync__start();
probe buffer__checkpoint__done();
probe buffer__sync__start(int, int);
probe buffer__sync__written(int);
probe buffer__sync__done(int, int, int);
+	probe buffer__write__dirty__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
+	probe buffer__write__dirty__done(ForkNumber, BlockNumber, Oid, Oid, Oid);

probe deadlock__found();

+	probe checkpoint__start(int);
+	probe checkpoint__done(int, int, int, int, int);
probe clog__checkpoint__start(bool);
probe clog__checkpoint__done(bool);
probe subtrans__checkpoint__start(bool);
@@ -88,4 +81,14 @@ provider postgresql {
probe multixact__checkpoint__done(bool);
probe twophase__checkpoint__start();
probe twophase__checkpoint__done();
+
+	probe smgr__md__read__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
+	probe smgr__md__read__done(ForkNumber, BlockNumber, Oid, Oid, Oid, const char *, int, int);
+	probe smgr__md__write__start(ForkNumber, BlockNumber, Oid, Oid, Oid);
+	probe smgr__md__write__done(ForkNumber, BlockNumber, Oid, Oid, Oid, const char *, int, int);
+
+	probe xlog__insert(unsigned char, unsigned char);
+	probe xlog__switch();
+	probe wal__buffer__write__start();
+	probe wal__buffer__write__done();
};

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

Hi,

On Wed, Dec 17, 2008 at 4:53 AM, Robert Lor <Robert.Lor@sun.com> wrote:

@@ -1313,12 +1318,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();

Why is TRACE_POSTGRESQL_WAL_BUFFER_WRITE_START/DONE called
only in AdvanceXLInsertBuffer? We can trace only a part of WAL buffer write?

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Fujii Masao wrote:

Hi,

On Wed, Dec 17, 2008 at 4:53 AM, Robert Lor <Robert.Lor@sun.com> wrote:

@@ -1313,12 +1318,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();

Why is TRACE_POSTGRESQL_WAL_BUFFER_WRITE_START/DONE called
only in AdvanceXLInsertBuffer? We can trace only a part of WAL buffer write?

The intention of these probes is to determine if wal_buffers is too
small by monitoring how frequent the server has to write out the buffers
along with the I/O time.

-Robert

Robert Lor escribi�:

Fujii Masao wrote:

Hi,

On Wed, Dec 17, 2008 at 4:53 AM, Robert Lor <Robert.Lor@sun.com> wrote:

Why is TRACE_POSTGRESQL_WAL_BUFFER_WRITE_START/DONE called
only in AdvanceXLInsertBuffer? We can trace only a part of WAL buffer write?

The intention of these probes is to determine if wal_buffers is too
small by monitoring how frequent the server has to write out the buffers
along with the I/O time.

But there are 5 callers of XLogWrite ... why aren't the other ones being
tracked too?

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Alvaro Herrera wrote:

But there are 5 callers of XLogWrite ... why aren't the other ones being
tracked too?

This probe originally came from Simon, so it can't possibly be wrong :-)

My understanding is that we only want to track the XLogWrite when
advancing to the next buffer page, and if there is unwritten data in the
new buffer page, that indicates no more empty WAL buffer pages
available, but I may be wrong. I did some tests by adjusting
wal_buffers, and I could observe this behavior, more calls to XLogWrite
with smaller wal_buffers.

-Robert

Hi,

On Thu, Dec 18, 2008 at 4:49 AM, Robert Lor <Robert.Lor@sun.com> wrote:

Alvaro Herrera wrote:

But there are 5 callers of XLogWrite ... why aren't the other ones being
tracked too?

This probe originally came from Simon, so it can't possibly be wrong :-)

My understanding is that we only want to track the XLogWrite when advancing
to the next buffer page, and if there is unwritten data in the new buffer
page, that indicates no more empty WAL buffer pages available, but I may be
wrong. I did some tests by adjusting wal_buffers, and I could observe this
behavior, more calls to XLogWrite with smaller wal_buffers.

I understood your intention. But, I think that its function name is somewhat
confusing.

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

"Fujii Masao" <masao.fujii@gmail.com> writes:

On Thu, Dec 18, 2008 at 4:49 AM, Robert Lor <Robert.Lor@sun.com> wrote:

My understanding is that we only want to track the XLogWrite when advancing
to the next buffer page, and if there is unwritten data in the new buffer
page, that indicates no more empty WAL buffer pages available, but I may be
wrong. I did some tests by adjusting wal_buffers, and I could observe this
behavior, more calls to XLogWrite with smaller wal_buffers.

I understood your intention. But, I think that its function name is somewhat
confusing.

I agree. If the probe is meant to track only *some* WAL writes
then it needs to be named something less generic than
TRACE_POSTGRESQL_WAL_BUFFER_WRITE.

regards, tom lane

Tom Lane wrote:

"Fujii Masao" <masao.fujii@gmail.com> writes:

I understood your intention. But, I think that its function name is somewhat
confusing.

I agree. If the probe is meant to track only *some* WAL writes
then it needs to be named something less generic than
TRACE_POSTGRESQL_WAL_BUFFER_WRITE.

How about change it to TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY similar to TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY for shared buffers?

-Robert

Robert Lor <Robert.Lor@Sun.COM> writes:

Tom Lane wrote:

I agree. If the probe is meant to track only *some* WAL writes
then it needs to be named something less generic than
TRACE_POSTGRESQL_WAL_BUFFER_WRITE.

How about change it to TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY similar to TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY for shared buffers?

Works for me...

regards, tom lane

Tom Lane wrote:

Robert Lor <Robert.Lor@Sun.COM> writes:

Tom Lane wrote:

I agree. If the probe is meant to track only *some* WAL writes
then it needs to be named something less generic than
TRACE_POSTGRESQL_WAL_BUFFER_WRITE.

How about change it to TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY similar to TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY for shared buffers?

Works for me...

Attached is the patch for the above name change.

-Robert

Thanks, applied.

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

Robert Lor wrote:

Tom Lane wrote:

Robert Lor <Robert.Lor@Sun.COM> writes:

Tom Lane wrote:

I agree. If the probe is meant to track only *some* WAL writes
then it needs to be named something less generic than
TRACE_POSTGRESQL_WAL_BUFFER_WRITE.

How about change it to TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY similar to TRACE_POSTGRESQL_BUFFER_WRITE_DIRTY for shared buffers?

Works for me...

Attached is the patch for the above name change.

-Robert

Index: src/backend/access/transam/xlog.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/access/transam/xlog.c,v
retrieving revision 1.324
diff -u -3 -p -r1.324 xlog.c
--- src/backend/access/transam/xlog.c	17 Dec 2008 01:39:03 -0000	1.324
+++ src/backend/access/transam/xlog.c	22 Dec 2008 16:28:00 -0000
@@ -1318,14 +1318,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();
+				TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY_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();
+				TRACE_POSTGRESQL_WAL_BUFFER_WRITE_DIRTY_DONE();
}
}
}
Index: src/backend/utils/probes.d
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/probes.d,v
retrieving revision 1.4
diff -u -3 -p -r1.4 probes.d
--- src/backend/utils/probes.d	17 Dec 2008 01:39:04 -0000	1.4
+++ src/backend/utils/probes.d	22 Dec 2008 16:28:01 -0000
@@ -89,6 +89,6 @@ provider postgresql {

probe xlog__insert(unsigned char, unsigned char);
probe xlog__switch();
-	probe wal__buffer__write__start();
-	probe wal__buffer__write__done();
+	probe wal__buffer__write__dirty__start();
+	probe wal__buffer__write__dirty__done();
};

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +