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(); };