lwlock_hold_durations.stp
application/octet-stream
Filename: lwlock_hold_durations.stp
Type: application/octet-stream
Part: 1
#
# This tapscript requires a postgres patched with my lwlock tracepoint enhancements.
#
# It requires the absolute path to the target postgres executable as the first
# positional argument after the script.
#
# You'll have to run with a bunch of resource limits turned off for this to work since the script
# is very expensive and not optimised right now.
#
# I use
#
# stap -v -g --suppress-time-limits
#
# A typical invocation with some parameters might be:
#
# /usr/local/systemtap/bin/stap -v -g --suppress-time-limits -G track_per_process=1 -G cumulative=1 -G log_waits_longer_than_us=9000 -G log_holds_longer_than_us=20000 -G track_blockers=1 -G hide_wait_total_summary_lt_us=10000 -G hide_held_total_summary_lt_us=20000 -G hide_wait_total_pid_lt_us=1000 -G hide_held_total_pid_lt_us=5000 lwlock_hold_durations.stp /path/to/your/postgres
#
# PARAMETERS
#
# -G hide_wait_total_summary_lt_us=0
# -G hide_held_total_summary_lt_us=0
# -G hide_wait_total_pid_lt_us=0
# -G hide_held_total_pid_lt_us=0
#
# Suppress display of wait or hold entries whose totals are less than
# the supplied values. Helps reduce noise in output.
#
# -G track_per_process=0
#
# Produce summary output but omit per-process-id tracking of locks.
# Signficantly reduces overhead and reduces the volume of output.
#
# -G periodic_summary=0
#
# Suppress the periodic updates of the summary counter.
#
# -G cumulative=0
#
# Reset allprocs samples each time interval. Does not affect
# per-process samples since they're only emitted once at process exit
# anyway. Has no effect if periodic_summary=0.
#
# -G log_waits_longer_than_us=50000
# -G log_holds_longer_than_us=50000
#
# Report individual waits or holds if they are long. Time in
# microseconds above which the wait or hold is reported.
#
# If debuginfo is available this will report the application_name or,
# if unset, the backend type, for both waiter and holder if possible.
#
# -G track_application_names=0
#
# Don't attempt to track application names and backend IDs. Only
# affects log_waits_longer_than_us and log_holds_longer_than_us.
#
# Turning this off saves some runtime.
#
# -G track_blockers=0
#
# Don't try to track blocker for waits. Only affects
# log_waits_longer_than_us and log_holds_longer_than_us.
#
# Turning this off saves some runtime.
#
#
# All these parameters can be tweaked during script execution if using
# stap --monitor mode.
#
# TODO measure time lock is held while contested separately
# TODO filter out timings for locks that were uncontested and short
# TODO support tracking by MyBackendType category
#
%( $# > 0 %?
@define POSTGRES_PATH %( @1 %)
%:
@define POSTGRES_PATH %( "/home/craig/projects/2Q/postgres/dev/lwlock-tracepoints/build/tmp_install/home/craig/pg/lwlock-tracepoints/bin/postgres" %)
%)
// These globals control options that can be set with -G flags on the
// command line. See the header comment.
global periodic_summary = 1
global track_per_process = 1
global cumulative = 1
global log_waits_longer_than_us = 0
global log_holds_longer_than_us = 0
global backtrace_long_waits_or_holds = 1
global track_blockers = 0
global track_application_names = 1
global hide_wait_total_summary_lt_us = 0
global hide_held_total_summary_lt_us = 0
global hide_wait_total_pid_lt_us = 0
global hide_held_total_pid_lt_us = 0
probe postgres = process(@POSTGRES_PATH) {}
// Track currently-held locks by pid. Indexed by [lwlock_p, pid()] => timestamp acquired
private locks_held_by_pid;
// For lock waits in progress track the waiting pid's start wait time
private lock_wait_start_us;
// and the lock being acquired
private lock_wait_lwlock_p;
// For lwlock wait tracking of the blocking pid, if it can be found. Also
// blocking pid's application_name at the time we noticed it was blocking.
private lock_wait_blocker;
private lock_wait_blocker_appname;
// The acquire function we're in right now. By pid.
private acquire_func;
// If we're tracking application names, track the application_name of each pid
private application_names;
// Track MyBackendType for each backend too, if we're tracking appnames.
private backend_types;
// Stats arrays indexed by [tranche_id, mode], for lock wait stats and lock hold stats
private held_durations_allprocs[1000];
private wait_durations_allprocs[1000];
// Stats array indexed by [pid(), tranche_id, mode]
//
// This array must be very large if we're going to accumulate all pid stats so
// instead we write stats for each pid once it exits. Also let this array cycle
// (% suffix)
private held_durations_pid[5000];
private wait_durations_pid[5000];
// tranche id -> name mapping, since we don't want to rely on seeing
// the tranches registered at startup.
private tranche_names;
// enum LWLockMode
@define LW_EXCLUSIVE %( 0 %)
@define LW_SHARED %( 1 %)
@define LW_WAIT_UNTIL_FREE %( 2 %)
probe postgres.mark("lwlock__acquired") {
mode = $arg2
lwlock_p = $arg3
tranche_id = $arg4
assert (mode == @LW_EXCLUSIVE || mode == @LW_SHARED, sprintf("invalid lockmode %d", mode));
if (!([tranche_id] in tranche_names)) {
// This assumes tranche id->name is consistent across procs. That's not
// guaranteed, but it's close enough for this purpose.
tranche_name_p = $arg1
tranche_names[tranche_id] = user_string(tranche_name_p);
}
locks_held_by_pid[pid(), lwlock_p] = gettimeofday_us();
}
probe postgres.mark("lwlock__release") {
//tranche_name = user_string($arg1)
mode = $arg2
lwlock_p = $arg3
tranche_id = $arg4
assert (mode == @LW_EXCLUSIVE || mode == @LW_SHARED, sprintf("invalid lockmode %d", mode));
acquired_us = locks_held_by_pid[pid(), lwlock_p]
if (acquired_us != 0) {
released_us = gettimeofday_us();
held = released_us - acquired_us;
// Summary across all pids by lockmode, and by (tranche_id, lockmode)
//
held_durations_allprocs[-1, mode] <<< held;
held_durations_allprocs[tranche_id, mode] <<< held;
// And for this process
if (track_per_process) {
held_durations_pid[pid(), tranche_id, mode] <<< held;
held_durations_pid[pid(), -1, mode] <<< held;
}
if (log_holds_longer_than_us > 0 && held > log_holds_longer_than_us) {
appname = application_names[pid()]
backend_type = backend_types[pid()]
if (appname != "")
appname = " (" . appname . ")"
printf("!!H!! [%6d]:%-3d %20s %8d (%10s)%s\n",
pid(), backend_type, tranche_id_str(tranche_id),
held, usecs_to_string(held),
appname);
}
// TODO: We should really categorize processes, but there's not
// currently an easy way to do ask "what kind of process is
// this" and get a sensible answer, short of using
// application_name. The backend_type populated by
// pg_stat_activity is a string fetched dynamically. Don't want to have
// to check am_walsender and all that individually. So for now not
// doing backend categories.
delete locks_held_by_pid[pid(), lwlock_p]
}
}
// LWLock waits. Note that we may wait multiple times for a given acquire. We don't presently
// try to keep track of the total wait time for each acquire, we treat each wait as individual
// incidents.
//
// We want to accumulate each wait into a total since the number of wakeups is less interesting
// than the total time waited. We won't bother counting the wakeups.
//
probe postgres.mark("lwlock__wait__start") {
mode = $arg2;
lwlock_p = $arg3;
tranche_id = $arg4;
// Only record the wait-start time if this is the first wait for the
// lock acquire. We don't want to forget the first wait time if a prior
// wakeup failed to get the lock.
if (!([pid()] in lock_wait_start_us))
{
lock_wait_start_us[pid()] = gettimeofday_us()
lock_wait_lwlock_p[pid()] = lwlock_p
if (track_blockers) {
// This is how to get the pid that holds the lock now. It's slow though. And
// we could land up waiting on a different holder each time we wake if it's
// quite contested. So this is optional.
//
foreach ([blocker_pid, entry_lwlock_p] in locks_held_by_pid[*, *]) {
/* Workaround for issue where specifying lwlock_p as search filter fails */
if (entry_lwlock_p == lwlock_p)
{
lock_wait_blocker[pid()] = blocker_pid;
// Save blocker's application name or backend
// type now, since it might be cleared due to
// blocker exit before we notice the lock
// release and go to report it.
lock_wait_blocker_appname[pid()] = application_names[blocker_pid]
break;
}
}
}
}
else
{
assert(lock_wait_lwlock_p[pid()] == lwlock_p,
sprintf("wait resume lwlock ptr mismatch: got %p expected %p", lock_wait_lwlock_p[pid()], lwlock_p));
}
}
/*
* We don't use the lwlock__wait__done event here. Because a single lock acquire
* may do many waits, we're more interested in the total time between the first
* wait and the actual acquire.
*/
/*
probe postgres.mark("lwlock__wait__done") {
mode = $arg2;
lwlock_p = $arg3;
tranche_id = $arg4;
wait_start_us = lock_wait_start_us[pid(), lwlock_p];
}
*/
/*
* So track the individual lock acquire events specifically.
*
* TODO provide a single event for all "done waiting" cases.
*/
probe lwlock_acquired = postgres.mark("lwlock__acquired")
{
acquired = 1
mode = $arg2
lwlock_p = $arg3
tranche_id = $arg4
}
// LWLockWaitForVar doesn't acquire the lock so it doesn't hit
// lwlock__acquired. Handle separately.
probe lwlock_waitforvar_done = postgres.mark("lwlock__waitforvar__done")
{
acquired = 0
mode = @LW_EXCLUSIVE
lwlock_p = $arg2
tranche_id = $arg3
// oldval = $arg5
// newval = $arg6
// result = $arg7
}
// Same for the fail-path for condacquire or AcquireOrWait. The success-paths
// hits lwlock__acquired.
probe lwlock_condacquire_fail = postgres.mark("lwlock__condacquire__fail"),
postgres.mark("lwlock__acquire__or__wait__fail")
{
acquired = 0
mode = $arg2
lwlock_p = $arg3
tranche_id = $arg4
}
probe lwlock_acquired, lwlock_waitforvar_done, lwlock_condacquire_fail
{
wait_start_us = lock_wait_start_us[pid()];
// Ignore uncontested locks where we didn't wait, or locks where
// we didn't see the start-event.
//
// TODO count uncontested acquires too.
//
if (wait_start_us != 0) {
func = acquire_func[pid()]
assert(lock_wait_lwlock_p[pid()] == lwlock_p,
sprintf("mismatched lwlock pointer in acquired: got %p expected %p (in %s)", lock_wait_lwlock_p[pid()], lwlock_p, func))
wait_end_us = gettimeofday_us();
waited = wait_end_us - wait_start_us;
wait_durations_allprocs[-1, mode] <<< waited;
wait_durations_allprocs[tranche_id, mode] <<< waited;
if (track_per_process) {
wait_durations_pid[pid(), tranche_id, mode] <<< waited;
wait_durations_pid[pid(), -1, mode] <<< waited;
}
if (log_waits_longer_than_us > 0 && waited > log_waits_longer_than_us) {
backend_type = backend_types[pid()]
msg = sprintf("!!W!! [%6d]:%-3d %20s %8d (%10s) in %s",
pid(), backend_type, tranche_id_str(tranche_id),
waited, usecs_to_string(waited), func);
appname = application_names[pid()]
if (appname != "") {
msg .= " (" . appname . ")"
}
if (track_blockers) {
blocked_by = lock_wait_blocker[pid()];
if (blocked_by != 0) {
msg .= sprintf(" => [%6d]", blocked_by)
}
blocker_appname = lock_wait_blocker_appname[pid()]
if (blocker_appname != "") {
msg .= " (" . blocker_appname . ")"
}
}
println(msg);
}
}
delete lock_wait_start_us[pid()]
delete lock_wait_lwlock_p[pid()]
delete lock_wait_blocker[pid()]
delete lock_wait_blocker_appname[pid()]
delete acquire_func[pid()]
}
/*
* SANITY CHECK
*
* If we try to begin an acquire while another is ongoing, that must be a trace
* script bug. Detect it.
*/
probe postgres.mark("lwlock__acquire__start"),
postgres.mark("lwlock__condacquire__start"),
postgres.mark("lwlock__waitforvar__start")
{
assert(!([pid()] in acquire_func),
sprintf("already in acquire func %s when entering %s",
acquire_func[pid()], $$name))
assert(!([pid()] in lock_wait_start_us),
sprintf("already waiting when entering %s", $$name))
assert(!([pid()] in lock_wait_lwlock_p),
sprintf("already have lwlock ptr %p when entering %s", lock_wait_lwlock_p[pid()], $$name))
assert(!([pid()] in lock_wait_blocker),
sprintf("already have blocker when entering %s", $$name))
assert(!([pid()] in lock_wait_blocker_appname),
sprintf("already have blocker appname when entering %s", $$name))
acquire_func[pid()] = $$name;
}
/*
* SANITY CHECK
*
* Must have reported lock acquire and cleared state when we finish acquire or
* condacquire, so acquire_func must be clear.
*/
probe postgres.mark("lwlock__condacquire"), postgres.mark("lwlock__acquire"), postgres.mark("lwlock__acquire__or__wait")
{
assert(!([pid()] in acquire_func),
sprintf("expected empty acquire_func in %s but got %s", $$name, acquire_func[pid()]))
}
// If we're tracking application names. This will only work with debuginfo so make it
// an optional probe.
//
// Only called for backends that actually have an application_name, so can't be used
// to init the backend type.
//
// TODO ensure this gets an SDT marker in future.
//
probe postgres.function("assign_application_name") if (track_application_names) {
if ($newval != 0) {
appname = user_string($newval,"")
if (appname == "") {
appname = describe_my_backend();
}
if (appname != "") {
application_names[pid()] = appname
}
}
}
// enum BackendType from miscadmin.h
@define B_INVALID %( 0 %)
@define B_AUTOVAC_LAUNCHER %( 1 %)
@define B_AUTOVAC_WORKER %( 2 %)
@define B_BACKEND %( 3 %)
@define B_BG_WORKER %( 4 %)
@define B_BG_WRITER %( 5 %)
@define B_CHECKPOINTER %( 6 %)
@define B_STARTUP %( 7 %)
@define B_WAL_RECEIVER %( 8 %)
@define B_WAL_SENDER %( 9 %)
@define B_WAL_WRITER %( 10 %)
@define B_ARCHIVER %( 11 %)
@define B_STATS_COLLECTOR %( 12 %)
@define B_LOGGER %( 13 %)
// Describe the backend type for this backend. We shouldn't need all this mess,
// but postgres doesn't give us a single sensible place to look for it.
//
// Follow similar logic to log_line_prefix() and GetBackendTypeDesc()
//
function describe_my_backend:string() {
if (pid() == @var("PostmasterPid", @POSTGRES_PATH))
return "postmaster";
betype = @var("MyBackendType", @POSTGRES_PATH)
backend_types[pid()] = betype
return describe_backend_type(betype)
}
function describe_backend_type:string(betype:long) {
if (betype == @B_INVALID)
return ""
if (betype == @B_AUTOVAC_LAUNCHER)
return "autovacuum launcher"
if (betype == @B_AUTOVAC_WORKER)
return "autovacuum worker"
if (betype == @B_BACKEND)
return "backend"
if (betype == @B_BG_WORKER)
return user_string(@var("MyBgworkerEntry", @POSTGRES_PATH)->bgw_type, "background worker");
if (betype == @B_BG_WRITER)
return "bgwriter"
if (betype == @B_CHECKPOINTER)
return "checkpointer"
if (betype == @B_STARTUP)
return "startup process"
if (betype == @B_WAL_RECEIVER)
return "walreceiver"
if (betype == @B_WAL_SENDER)
return "walsender"
if (betype == @B_WAL_WRITER)
return "wal writer"
if (betype == @B_ARCHIVER)
return "archiver"
if (betype == @B_STATS_COLLECTOR)
return "stats collector"
if (betype == @B_LOGGER)
return "logging collector"
return ""
}
/*
* There's no set accessor for setting the backend type and it isn't set in any
* consistent place. Many processes set it at the start of their main loops. So
* it's not easy to probe.
*
* At least we should be able to rely on it being set before init_ps_display()
* is called, and that should get called by most if not all worker types. If
* application_name is set, we'll override this with the app name later.
*/
probe postgres.function("init_ps_display") if (track_application_names) {
application_names[pid()] = describe_my_backend()
}
/*
* We have to clean up entries for all the per-pid arrays manually
* to ensure we don't leak and fill the arrays.
*/
function delete_per_pid_entries()
{
foreach (acquired_us = [pid, lwlock_p] in locks_held_by_pid[pid(), *])
{
leaked_locks ++;
printf("[%6d] leaked LWLock %p!\n", pid, lwlock_p);
}
delete locks_held_by_pid[pid(), *]
delete lock_wait_start_us[pid()]
delete lock_wait_lwlock_p[pid()]
delete lock_wait_blocker[pid()]
delete lock_wait_blocker_appname[pid()]
delete acquire_func[pid()]
delete application_names[pid()]
delete backend_types[pid()]
}
function tranche_id_str:string(tranche_id:long) {
n = tranche_names[tranche_id]
return n != "" ? n : sprintf("<tranche_id %d>", tranche_id)
}
function lockmode_str:string(mode:long) {
if (mode == @LW_EXCLUSIVE) {
return "E"
} else if (mode == @LW_SHARED) {
return "S"
} else if (mode == @LW_WAIT_UNTIL_FREE) {
return "W"
} else {
error(sprintf("unknown lockmode %d", mode));
}
}
function print_stats_header(label) {
printf("%-20s %30s %4s %8s %12s %8s %8s %8s %8s\n", label, "tranche", "mode", "count", "total", "avg", "variance", "min", "max");
}
/*
* Can't pass a stats-variable directly so we have to pass the keys, and repeat them
* for each access, making it much harder to generalize this.
*/
function print_held_stats_summary(label:string,fortranche:long,formode:long)
{
tranche_name = fortranche == -1 ? "(all)" : tranche_id_str(fortranche)
held_count = @count(held_durations_allprocs[fortranche,formode])
held_total = @sum(held_durations_allprocs[fortranche,formode])
if (held_count > 0
&& (hide_held_total_summary_lt_us == 0 || held_total > hide_held_total_summary_lt_us))
{
printf("%-20s %30s %4s %8d %12d %8d %8d %8d %8d\n",
label, tranche_name, lockmode_str(formode),
held_count, held_total,
@avg(held_durations_allprocs[fortranche,formode]),
@variance(held_durations_allprocs[fortranche,formode]),
@min(held_durations_allprocs[fortranche,formode]),
@max(held_durations_allprocs[fortranche,formode]))
}
}
function print_wait_stats_summary(label:string,fortranche:long,formode:long)
{
tranche_name = fortranche == -1 ? "(all)" : tranche_id_str(fortranche)
wait_count = @count(wait_durations_allprocs[fortranche,formode])
wait_total = @sum(wait_durations_allprocs[fortranche,formode])
if (wait_count > 0
&& (hide_wait_total_summary_lt_us == 0 || wait_total > hide_wait_total_summary_lt_us))
{
printf("%-20s %30s %4s %8d %12d %8d %8d %8d %8d\n",
label, tranche_name, lockmode_str(formode),
wait_count, wait_total,
@avg(wait_durations_allprocs[fortranche,formode]),
@variance(wait_durations_allprocs[fortranche,formode]),
@min(wait_durations_allprocs[fortranche,formode]),
@max(wait_durations_allprocs[fortranche,formode]))
}
}
function print_stats_pid(forpid:long,fortranche:long,formode:long,atexit:long)
{
tranche_name = fortranche == -1 ? "(all)" : tranche_id_str(fortranche)
held_count = @count(held_durations_pid[forpid,fortranche,formode])
held_total = @sum(held_durations_pid[forpid,fortranche,formode])
if (held_count > 0
&& (hide_held_total_pid_lt_us == 0 || fortranche == -1 || held_total > hide_held_total_pid_lt_us))
{
printf("%1s H [%06d] %30s %4s %8d %12d %8d %8d %8d %8d\n",
atexit == 0 ? "*" : " ",
forpid, tranche_name, lockmode_str(formode),
held_count, held_total,
@avg(held_durations_pid[forpid,fortranche,formode]),
@variance(held_durations_pid[forpid,fortranche,formode]),
@min(held_durations_pid[forpid,fortranche,formode]),
@max(held_durations_pid[forpid,fortranche,formode]))
}
wait_count = @count(wait_durations_pid[forpid,fortranche,formode])
wait_total = @sum(wait_durations_pid[forpid,fortranche,formode])
if (wait_count > 0
&& (hide_wait_total_pid_lt_us == 0 || fortranche == -1 || wait_total > hide_wait_total_pid_lt_us))
{
printf("%1s W [%06d] %30s %4s %8d %12d %8d %8d %8d %8d\n",
atexit == 0 ? "*" : " ",
forpid, tranche_name, lockmode_str(formode),
wait_count, wait_total,
@avg(wait_durations_pid[forpid,fortranche,formode]),
@variance(wait_durations_pid[forpid,fortranche,formode]),
@min(wait_durations_pid[forpid,fortranche,formode]),
@max(wait_durations_pid[forpid,fortranche,formode]))
}
}
function print_stats() {
// Suppress action if nothing collected at all
if ([*, *] in held_durations_allprocs) {
// By-mode rollup
printf("\n")
print_stats_header("held locks: all procs")
print_held_stats_summary(" H LW_EXCLUSIVE", -1, @LW_EXCLUSIVE);
print_held_stats_summary(" H LW_SHARED", -1, @LW_SHARED);
// By tranche id and mode, all procs
printf("\n")
print_stats_header("all procs by tranche")
foreach ([tranche_id+, mode] in held_durations_allprocs[*, *]) {
print_held_stats_summary(" H tranche ", tranche_id, mode)
}
}
if ([*, *] in wait_durations_allprocs) {
// By-mode rollup
printf("\n")
print_stats_header("wait locks: all procs")
print_wait_stats_summary(" W LW_EXCLUSIVE", -1, @LW_EXCLUSIVE);
print_wait_stats_summary(" W LW_SHARED", -1, @LW_SHARED);
// By tranche id and mode, all procs
printf("\n")
print_stats_header("all procs by tranche")
foreach ([tranche_id+, mode] in wait_durations_allprocs[*, *]) {
print_wait_stats_summary(" W tranche ", tranche_id, mode)
}
printf("------\n");
}
if (! cumulative) {
delete held_durations_allprocs[*, *];
delete wait_durations_allprocs[*, *];
}
}
probe timer.ms(5000) if (periodic_summary) {
print_stats();
}
// We print stats on a proc when it exits so we can forget it and not bloat the
// arrays too much.
probe postgres.end if (track_per_process) {
if ([pid(), *, *] in held_durations_pid) {
backend_type = backend_types[pid()]
backend_description = application_names[pid()]
printf("[%6d] backend_type=%-3d (%s) exited\n", pid(), backend_type, backend_description)
print_stats_header(sprintf("[%6d]:", pid()))
foreach ([pid, tranche_id+, mode] in held_durations_pid[pid(), *, *]) {
print_stats_pid(pid, tranche_id, mode, 1)
}
delete held_durations_pid[pid(), *, *];
printf("=======\n");
}
}
// Prevent resource leaks. This must appear after the other .end probes since
// they might refer to the globals we're clearing.
probe postgres.end {
delete_per_pid_entries()
}
probe end {
print_stats();
if (track_per_process)
{
if ([*, *, *] in held_durations_pid) {
print_stats_header("all remaining backends by pid")
// How to print the rollup line first while preserving sorting
// by both pid and tranche? Do we need another var again? Or
// nested loop? A nested loop seems likely to be extemely slow.
// Build a global array of pids just for this job?
/*
last_pid = 0
foreach ([pid, _ign1, _ign2] in held_durations_pid[*, *, *]) {
if (last_pid != pid)
{
foreach ([_ign3, tranche_id+, mode] in held_durations_pid[pid, *, *]) {
print_stats_pid(pid, tranche_id, mode, 0)
}
last_pid = pid
}
}
*/
foreach ([pid, tranche_id, mode] in held_durations_pid[pid, *, *]) {
print_stats_pid(pid, tranche_id, mode, 0)
}
}
}
printf("------\n");
}