diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c index f2ccbe1..729c6d8 100644 *** a/src/backend/storage/lmgr/lwlock.c --- b/src/backend/storage/lmgr/lwlock.c *************** *** 29,34 **** --- 29,55 ---- #include "storage/ipc.h" #include "storage/proc.h" #include "storage/spin.h" + #include "portability/instr_time.h" + + /* displays counters (number of lock acquires, etc) + * on process exit */ + #define LWLOCK_STATS + + #ifdef LWLOCK_STATS + + /* also displays cumulative timings of time spent + * waiting and holding locks + * (depends on LWLOCK_STATS) + */ + #define LWLOCK_TIMING_STATS + + /* displays only locks which were waited on more than + * this amount of seconds (set to 0 to display all) + * (depends on LWLOCK_TIMING_STATS) + */ + #define LWLOCKS_STATS_TIME_DISPLAY_THRESHOLD 0.1 + #endif /* LWLOCK_STATS */ + /* We use the ShmemLock spinlock to protect LWLockAssign */ *************** static LWLockId held_lwlocks[MAX_SIMUL_L *** 88,100 **** static int lock_addin_request = 0; static bool lock_addin_request_allowed = true; - #ifdef LWLOCK_STATS - static int counts_for_pid = 0; - static int *sh_acquire_counts; - static int *ex_acquire_counts; - static int *block_counts; - #endif - #ifdef LOCK_DEBUG bool Trace_lwlocks = false; --- 109,114 ---- *************** LOG_LWDEBUG(const char *where, LWLockId *** 121,146 **** #ifdef LWLOCK_STATS static void print_lwlock_stats(int code, Datum arg) { ! int i; int *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int)); int numLocks = LWLockCounter[1]; /* Grab an LWLock to keep different backends from mixing reports */ LWLockAcquire(0, LW_EXCLUSIVE); for (i = 0; i < numLocks; i++) { ! if (sh_acquire_counts[i] || ex_acquire_counts[i] || block_counts[i]) ! fprintf(stderr, "PID %d lwlock %d: shacq %u exacq %u blk %u\n", ! MyProcPid, i, sh_acquire_counts[i], ex_acquire_counts[i], ! block_counts[i]); } LWLockRelease(0); } #endif /* LWLOCK_STATS */ --- 135,282 ---- #ifdef LWLOCK_STATS + typedef struct + { + /* Process-local Counters for the number of times the lock has been ... */ + int count_acquired_share; /* acquired in SHARE mode */ + int count_waited_share; /* and it needed to wait */ + + int count_acquired_exclusive; /* acquired in EXCLUSIVEmode */ + int count_waited_exclusive; /* and it needed to wait */ + + #ifdef LWLOCK_TIMING_STATS + /* Process local sum of time during which ... */ + instr_time time_waited_share; /* we waited to get a SHARE lock */ + instr_time time_held_share; /* we held the SHARE lock */ + instr_time time_waited_exclusive; /* we waited to get an EXCLUSIVE lock */ + instr_time time_held_exclusive; /* we held the EXCLUSIVE lock */ + + instr_time ta, th; /* temp variables */ + #endif + } LWLockStatsData; + + static int counts_for_pid = 0; + static LWLockStatsData *lwlock_stats; + #ifdef LWLOCK_TIMING_STATS + static instr_time lwlock_stats_begin_time; + #endif + + static const char* lwlock_stats_lock_name( LWLockId id ) + { + static const char * names[] = { + "BufFreelist", + "ShmemIndex", + "OidGen", + "XidGen", + "ProcArray", + "SInvalRead", + "SInvalWrite", + "WALInsert", + "WALWrite", + "ControlFile", + "Checkpoint", + "CLogControl", + "SubtransControl", + "MultiXactGen", + "MultiXactOffsetControl", + "MultiXactMemberControl", + "RelCacheInit", + "BgWriterComm", + "TwoPhaseState", + "TablespaceCreate", + "BtreeVacuum", + "AddinShmemInit", + "Autovacuum", + "AutovacuumSchedule", + "SyncScan" }; + + if( id >= 0 && id < (sizeof( names )/sizeof( names[0] ))) + return names[id]; + else + return ""; + } + static void print_lwlock_stats(int code, Datum arg) { ! int i, lines=0; int *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int)); int numLocks = LWLockCounter[1]; + #ifdef LWLOCK_TIMING_STATS + instr_time end_time; + double total_percents; + INSTR_TIME_SET_CURRENT( end_time ); + INSTR_TIME_SUBTRACT( end_time, lwlock_stats_begin_time ); + total_percents = 100.0 / INSTR_TIME_GET_DOUBLE( end_time ); + #endif + fprintf( stderr, "\n-------- Lock stats for PID %d\n", MyProcPid ); + /* Grab an LWLock to keep different backends from mixing reports */ LWLockAcquire(0, LW_EXCLUSIVE); for (i = 0; i < numLocks; i++) { ! LWLockStatsData *p = &lwlock_stats[i]; ! #ifdef LWLOCK_TIMING_STATS ! double time_waited_share = INSTR_TIME_GET_DOUBLE(p->time_waited_share ); ! double time_held_share = INSTR_TIME_GET_DOUBLE(p->time_held_share ); ! double time_waited_exclusive = INSTR_TIME_GET_DOUBLE(p->time_waited_exclusive); ! double time_held_exclusive = INSTR_TIME_GET_DOUBLE(p->time_held_exclusive ); ! #endif ! ! if( !( p->count_waited_share || p->count_waited_exclusive )) ! continue; ! ! #ifdef LWLOCK_TIMING_STATS ! if( time_waited_share < LWLOCKS_STATS_TIME_DISPLAY_THRESHOLD ! && time_waited_exclusive < LWLOCKS_STATS_TIME_DISPLAY_THRESHOLD ) ! continue; ! #endif ! ! #ifdef LWLOCK_TIMING_STATS ! if( !(lines++ & 15) ) ! fprintf( stderr, " PID Lock ShAcq ShWait ShWaitT ShHeldT ExAcq " ! "ExWait ExWaitT ExHeldT Name\n" ); ! ! fprintf( stderr, ! "%7d %7d %10d %10d %11.02f %11.02f %10d %10d %11.02f (%6.02f %%) %11.02f (%6.02f %%) %s\n", ! MyProcPid, i, ! p->count_acquired_share, p->count_waited_share, time_waited_share, time_held_share, ! p->count_acquired_exclusive, p->count_waited_exclusive, ! time_waited_exclusive, time_waited_exclusive * total_percents, ! time_held_exclusive, time_held_exclusive * total_percents, ! lwlock_stats_lock_name( i )); ! #else ! if( !(lines++ & 15) ) ! fprintf( stderr, " PID Lock ShAcq ShWait ExAcq ExWait Name\n" ); ! ! fprintf( stderr, ! "%7d %7d %10d %10d %10d %10d %s\n", ! MyProcPid, i, ! p->count_acquired_share, p->count_waited_share, ! p->count_acquired_exclusive, p->count_waited_exclusive, ! lwlock_stats_lock_name( i )); ! #endif } LWLockRelease(0); } + + static void lock_stats_setup( void ) + { + int *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int)); + int numLocks = LWLockCounter[1]; + + lwlock_stats = calloc(numLocks, sizeof(LWLockStatsData)); + counts_for_pid = MyProcPid; + + #ifdef LWLOCK_TIMING_STATS + INSTR_TIME_SET_CURRENT( lwlock_stats_begin_time ); + #endif + + on_shmem_exit(print_lwlock_stats, 0); + } #endif /* LWLOCK_STATS */ *************** LWLockAcquire(LWLockId lockid, LWLockMod *** 321,341 **** #ifdef LWLOCK_STATS /* Set up local count state first time through in a given process */ if (counts_for_pid != MyProcPid) ! { ! int *LWLockCounter = (int *) ((char *) LWLockArray - 2 * sizeof(int)); ! int numLocks = LWLockCounter[1]; ! ! sh_acquire_counts = calloc(numLocks, sizeof(int)); ! ex_acquire_counts = calloc(numLocks, sizeof(int)); ! block_counts = calloc(numLocks, sizeof(int)); ! counts_for_pid = MyProcPid; ! on_shmem_exit(print_lwlock_stats, 0); ! } /* Count lock acquisition attempts */ ! if (mode == LW_EXCLUSIVE) ! ex_acquire_counts[lockid]++; ! else ! sh_acquire_counts[lockid]++; #endif /* LWLOCK_STATS */ /* --- 457,471 ---- #ifdef LWLOCK_STATS /* Set up local count state first time through in a given process */ if (counts_for_pid != MyProcPid) ! lock_stats_setup(); ! /* Count lock acquisition attempts */ ! if (mode == LW_EXCLUSIVE) lwlock_stats[lockid].count_acquired_exclusive++; ! else lwlock_stats[lockid].count_acquired_share++; ! #ifdef LWLOCK_TIMING_STATS ! /* record start of wait time and lock mode */ ! INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].ta ); ! #endif #endif /* LWLOCK_STATS */ /* *************** LWLockAcquire(LWLockId lockid, LWLockMod *** 445,451 **** LOG_LWDEBUG("LWLockAcquire", lockid, "waiting"); #ifdef LWLOCK_STATS ! block_counts[lockid]++; #endif TRACE_POSTGRESQL_LWLOCK_WAIT_START(lockid, mode); --- 575,583 ---- LOG_LWDEBUG("LWLockAcquire", lockid, "waiting"); #ifdef LWLOCK_STATS ! /* count lock waits */ ! if (mode == LW_EXCLUSIVE) lwlock_stats[lockid].count_waited_exclusive++; ! else lwlock_stats[lockid].count_waited_share++; #endif TRACE_POSTGRESQL_LWLOCK_WAIT_START(lockid, mode); *************** LWLockAcquire(LWLockId lockid, LWLockMod *** 480,485 **** --- 612,625 ---- */ while (extraWaits-- > 0) PGSemaphoreUnlock(&proc->sem); + + #ifdef LWLOCK_TIMING_STATS + /* record end of wait time and start of hold time */ + INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].th ); + + if (mode == LW_EXCLUSIVE) INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_waited_exclusive, lwlock_stats[lockid].th, lwlock_stats[lockid].ta ); + else INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_waited_share, lwlock_stats[lockid].th, lwlock_stats[lockid].ta ); + #endif } /* *************** LWLockConditionalAcquire(LWLockId lockid *** 548,553 **** --- 688,707 ---- /* Add lock to list of locks held by this backend */ held_lwlocks[num_held_lwlocks++] = lockid; TRACE_POSTGRESQL_LWLOCK_CONDACQUIRE(lockid, mode); + + #ifdef LWLOCK_STATS + /* Set up local count state first time through in a given process */ + if (counts_for_pid != MyProcPid) + lock_stats_setup(); + + /* Count lock acquisition attempts */ + if (mode == LW_EXCLUSIVE) lwlock_stats[lockid].count_acquired_exclusive++; + else lwlock_stats[lockid].count_acquired_share++; + #ifdef LWLOCK_TIMING_STATS + /* record start of hold time */ + INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].th ); + #endif + #endif /* LWLOCK_STATS */ } return !mustwait; *************** LWLockRelease(LWLockId lockid) *** 563,568 **** --- 717,725 ---- PGPROC *head; PGPROC *proc; int i; + #ifdef LWLOCK_TIMING_STATS + bool was_exclusive = false; + #endif PRINT_LWDEBUG("LWLockRelease", lockid, lock); *************** LWLockRelease(LWLockId lockid) *** 586,592 **** --- 743,754 ---- /* Release my hold on lock */ if (lock->exclusive > 0) + { lock->exclusive--; + #ifdef LWLOCK_TIMING_STATS + was_exclusive = true; + #endif + } else { Assert(lock->shared > 0); *************** LWLockRelease(LWLockId lockid) *** 651,656 **** --- 813,825 ---- * Now okay to allow cancel/die interrupts. */ RESUME_INTERRUPTS(); + #ifdef LWLOCK_TIMING_STATS + /* record end of hold time */ + INSTR_TIME_SET_CURRENT( lwlock_stats[lockid].ta ); + + if (was_exclusive) INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_held_exclusive, lwlock_stats[lockid].ta, lwlock_stats[lockid].th ); + else INSTR_TIME_ACCUM_DIFF( lwlock_stats[lockid].time_held_share, lwlock_stats[lockid].ta, lwlock_stats[lockid].th ); + #endif }