diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index 1dac695..fbe2b78 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -4183,6 +4183,8 @@ SubPostmasterMain(int argc, char *argv[]) static void ExitPostmaster(int status) { + LWLockDumpHistograms(); + /* should cleanup shared memory and kill all backends */ /* diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index 4de6a72..a20638b 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -2436,7 +2436,7 @@ UnlockBuffers(void) * Acquire or release the content_lock for the buffer. */ void -LockBuffer(Buffer buffer, int mode) +LockBufferReally(Buffer buffer, int mode, const char *file, int line) { volatile BufferDesc *buf; @@ -2449,9 +2449,9 @@ LockBuffer(Buffer buffer, int mode) if (mode == BUFFER_LOCK_UNLOCK) LWLockRelease(buf->content_lock); else if (mode == BUFFER_LOCK_SHARE) - LWLockAcquire(buf->content_lock, LW_SHARED); + LWLockAcquireReally(buf->content_lock, LW_SHARED, file, line); else if (mode == BUFFER_LOCK_EXCLUSIVE) - LWLockAcquire(buf->content_lock, LW_EXCLUSIVE); + LWLockAcquireReally(buf->content_lock, LW_EXCLUSIVE, file, line); else elog(ERROR, "unrecognized buffer lock mode: %d", mode); } diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c index f152376..a469d8b 100644 --- a/src/backend/storage/lmgr/lwlock.c +++ b/src/backend/storage/lmgr/lwlock.c @@ -27,6 +27,7 @@ #include "commands/async.h" #include "miscadmin.h" #include "pg_trace.h" +#include "portability/instr_time.h" #include "storage/ipc.h" #include "storage/predicate.h" #include "storage/proc.h" @@ -45,6 +46,9 @@ typedef struct LWLock int shared; /* # of shared holders (0..MaxBackends) */ PGPROC *head; /* head of list of waiting PGPROCs */ PGPROC *tail; /* tail of list of waiting PGPROCs */ + const char *file; /* file of lock holder */ + int line; /* line of lock holder */ + uint64 histogram[33]; /* gigantic! */ /* tail is undefined when head is NULL */ } LWLock; @@ -60,7 +64,7 @@ typedef struct LWLock * LWLock is between 16 and 32 bytes on all known platforms, so these two * cases are sufficient. */ -#define LWLOCK_PADDED_SIZE (sizeof(LWLock) <= 16 ? 16 : 32) +#define LWLOCK_PADDED_SIZE 512 typedef union LWLockPadded { @@ -84,6 +88,8 @@ NON_EXEC_STATIC LWLockPadded *LWLockArray = NULL; */ #define MAX_SIMUL_LWLOCKS 100 +#define LWLOCK_GRIPE_TIME 1000 + static int num_held_lwlocks = 0; static LWLockId held_lwlocks[MAX_SIMUL_LWLOCKS]; @@ -336,14 +342,20 @@ LWLockAssign(void) * Side effect: cancel/die interrupts are held off until lock release. */ void -LWLockAcquire(LWLockId lockid, LWLockMode mode) +LWLockAcquireReally(LWLockId lockid, LWLockMode mode, const char *file, + int line) { volatile LWLock *lock = &(LWLockArray[lockid].lock); PGPROC *proc = MyProc; bool retry = false; int extraWaits = 0; + instr_time start_time; + const char *blocked_by_file = "_fail_"; + int blocked_by_line = 0; + int64 time_elapsed = 0; PRINT_LWDEBUG("LWLockAcquire", lockid, lock); + INSTR_TIME_SET_ZERO(start_time); #ifdef LWLOCK_STATS /* Set up local count state first time through in a given process */ @@ -407,20 +419,33 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode) if (lock->exclusive == 0 && lock->shared == 0) { lock->exclusive++; + lock->file = file; + lock->line = line; mustwait = false; } else + { mustwait = true; + blocked_by_file = lock->file; + blocked_by_line = lock->line; + } } else { if (lock->exclusive == 0) { lock->shared++; + lock->file = file; + lock->line = line; mustwait = false; } else + { mustwait = true; + blocked_by_file = lock->file; + blocked_by_line = lock->line; + } + } if (!mustwait) @@ -462,6 +487,9 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode) */ LOG_LWDEBUG("LWLockAcquire", lockid, "waiting"); + if (INSTR_TIME_IS_ZERO(start_time)) + INSTR_TIME_SET_CURRENT(start_time); + #ifdef LWLOCK_STATS block_counts[lockid]++; #endif @@ -485,9 +513,29 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode) retry = true; } + if (!INSTR_TIME_IS_ZERO(start_time)) + { + instr_time end_time; + int f; + + INSTR_TIME_SET_CURRENT(end_time); + INSTR_TIME_SUBTRACT(end_time, start_time); + time_elapsed = INSTR_TIME_GET_MICROSEC(end_time); + f = fls((int) time_elapsed); + lock->histogram[f]++; + } + /* We are done updating shared state of the lock itself. */ SpinLockRelease(&lock->mutex); + if (!INSTR_TIME_IS_ZERO(start_time)) + { + if (time_elapsed >= LWLOCK_GRIPE_TIME) + elog(LOG, "lock %d: waited %.3f ms at %s:%d blocked by %s:%d", + lockid, ((double) time_elapsed) / 1000.0, + file, line, blocked_by_file, blocked_by_line); + } + TRACE_POSTGRESQL_LWLOCK_ACQUIRE(lockid, mode); /* Add lock to list of locks held by this backend */ @@ -508,10 +556,13 @@ LWLockAcquire(LWLockId lockid, LWLockMode mode) * If successful, cancel/die interrupts are held off until lock release. */ bool -LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode) +LWLockConditionalAcquireReally(LWLockId lockid, LWLockMode mode, + const char *file, int line) { volatile LWLock *lock = &(LWLockArray[lockid].lock); bool mustwait; + const char *blocked_by_file; + int blocked_by_line; PRINT_LWDEBUG("LWLockConditionalAcquire", lockid, lock); @@ -535,20 +586,32 @@ LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode) if (lock->exclusive == 0 && lock->shared == 0) { lock->exclusive++; + lock->file = file; + lock->line = line; mustwait = false; } else + { mustwait = true; + blocked_by_file = lock->file; + blocked_by_line = lock->line; + } } else { if (lock->exclusive == 0) { lock->shared++; + lock->file = file; + lock->line = line; mustwait = false; } else + { mustwait = true; + blocked_by_file = lock->file; + blocked_by_line = lock->line; + } } /* We are done updating shared state of the lock itself. */ @@ -586,12 +649,15 @@ LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode) * wake up, observe that their records have already been flushed, and return. */ bool -LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode) +LWLockAcquireOrWaitReally(LWLockId lockid, LWLockMode mode, + const char *file, int line) { volatile LWLock *lock = &(LWLockArray[lockid].lock); PGPROC *proc = MyProc; bool mustwait; int extraWaits = 0; + const char *blocked_by_file; + int blocked_by_line; PRINT_LWDEBUG("LWLockAcquireOrWait", lockid, lock); @@ -621,24 +687,41 @@ LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode) if (lock->exclusive == 0 && lock->shared == 0) { lock->exclusive++; + lock->file = file; + lock->line = line; mustwait = false; } else + { mustwait = true; + blocked_by_file = lock->file; + blocked_by_line = lock->line; + } } else { if (lock->exclusive == 0) { lock->shared++; + lock->file = file; + lock->line = line; mustwait = false; } else + { mustwait = true; + blocked_by_file = lock->file; + blocked_by_line = lock->line; + } } if (mustwait) { + instr_time start_time; + instr_time end_time; + int64 time_elapsed; + int f; + /* * Add myself to wait queue. * @@ -667,6 +750,8 @@ LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode) */ LOG_LWDEBUG("LWLockAcquireOrWait", lockid, "waiting"); + INSTR_TIME_SET_CURRENT(start_time); + #ifdef LWLOCK_STATS block_counts[lockid]++; #endif @@ -682,6 +767,19 @@ LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode) extraWaits++; } + INSTR_TIME_SET_CURRENT(end_time); + INSTR_TIME_SUBTRACT(end_time, start_time); + time_elapsed = INSTR_TIME_GET_MICROSEC(end_time); + f = fls((int) time_elapsed); + SpinLockAcquire(&lock->mutex); + lock->histogram[f]++; + SpinLockRelease(&lock->mutex); + + if (time_elapsed >= LWLOCK_GRIPE_TIME) + elog(LOG, "lock %d: waited %.3f ms at %s:%d blocked by %s:%d", + lockid, ((double) time_elapsed) / 1000.0, + file, line, blocked_by_file, blocked_by_line); + TRACE_POSTGRESQL_LWLOCK_WAIT_DONE(lockid, mode); LOG_LWDEBUG("LWLockAcquireOrWait", lockid, "awakened"); @@ -878,3 +976,37 @@ LWLockHeldByMe(LWLockId lockid) } return false; } + +void +LWLockDumpHistograms(void) +{ + int i; + int k; + char buffer[2048]; + char *s; + int *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int)); + int numLocks = LWLockCounter[1]; + + for (i = 0; i < numLocks; i++) + { + volatile LWLock *lock = &(LWLockArray[i].lock); + buffer[0] = '\0'; + s = buffer; + + for (k = 0; k < 32; ++k) + { + if (!lock->histogram[k]) + continue; + if (s != buffer) + { + *s++ = ','; + *s++ = ' '; + } + sprintf(s, "%d:%llu", k, + (long long unsigned) lock->histogram[k]); + s += strlen(s); + } + if (s != buffer) + elog(LOG, "lock %d: %s", i, buffer); + } +} diff --git a/src/include/storage/bufmgr.h b/src/include/storage/bufmgr.h index d72bad9..21f1fa8 100644 --- a/src/include/storage/bufmgr.h +++ b/src/include/storage/bufmgr.h @@ -204,8 +204,12 @@ extern void BufferGetTag(Buffer buffer, RelFileNode *rnode, extern void SetBufferCommitInfoNeedsSave(Buffer buffer); +#define LockBuffer(b, m) \ + LockBufferReally(b, m, __FILE__, __LINE__) + extern void UnlockBuffers(void); -extern void LockBuffer(Buffer buffer, int mode); +extern void LockBufferReally(Buffer buffer, int mode, const char *file, + int line); extern bool ConditionalLockBuffer(Buffer buffer); extern void LockBufferForCleanup(Buffer buffer); extern bool ConditionalLockBufferForCleanup(Buffer buffer); diff --git a/src/include/storage/lwlock.h b/src/include/storage/lwlock.h index 57a4f66..db9dfa5 100644 --- a/src/include/storage/lwlock.h +++ b/src/include/storage/lwlock.h @@ -106,9 +106,20 @@ extern bool Trace_lwlocks; #endif extern LWLockId LWLockAssign(void); -extern void LWLockAcquire(LWLockId lockid, LWLockMode mode); -extern bool LWLockConditionalAcquire(LWLockId lockid, LWLockMode mode); -extern bool LWLockAcquireOrWait(LWLockId lockid, LWLockMode mode); + +#define LWLockAcquire(l, m) \ + LWLockAcquireReally(l, m, __FILE__, __LINE__) +#define LWLockConditionalAcquire(l, m) \ + LWLockConditionalAcquireReally(l, m, __FILE__, __LINE__) +#define LWLockAcquireOrWait(l, m) \ + LWLockAcquireOrWaitReally(l, m, __FILE__, __LINE__) + +extern void LWLockAcquireReally(LWLockId lockid, LWLockMode mode, + const char *file, int line); +extern bool LWLockConditionalAcquireReally(LWLockId lockid, LWLockMode mode, + const char *file, int line); +extern bool LWLockAcquireOrWaitReally(LWLockId lockid, LWLockMode mode, + const char *file, int line); extern void LWLockRelease(LWLockId lockid); extern void LWLockReleaseAll(void); extern bool LWLockHeldByMe(LWLockId lockid); @@ -118,5 +129,6 @@ extern Size LWLockShmemSize(void); extern void CreateLWLocks(void); extern void RequestAddinLWLocks(int n); +extern void LWLockDumpHistograms(void); #endif /* LWLOCK_H */