diff --git a/TOOLS.md b/TOOLS.md index 9d79f73..ad57e9b 100644 --- a/TOOLS.md +++ b/TOOLS.md @@ -10,6 +10,9 @@ comprehensive list is available - [mqsnoop](mqsnoop) - Trace POSIX message queue send. - [nfcttrace](nfcttrace) - Show entries about TCP&UDP in nf_conntrack. - [numasched](numasched) - Trace scheduling of system processes between NUMA nodes. +- [pagefaultlatency](pagefaultlatency) - Page fault latency tracing. +- [reclaimlockmonitor](reclaimlockmonitor) - Monitor sleeping locks held during memory reclaim. +- [runnablelockmonitor](runnablelockmonitor) - Monitor sleeping locks held while off-CPU. - [sigsnoop](sigsnoop) - Trace standard and real-time signals. - [slableaktracker](slableaktracker) - Track down slab leaks. - [wakesnoop](wakesnoop) - Task wakeup latency tracing. diff --git a/reclaimlockmonitor/README.md b/reclaimlockmonitor/README.md new file mode 100644 index 0000000..3400029 --- /dev/null +++ b/reclaimlockmonitor/README.md @@ -0,0 +1,192 @@ +# reclaimlockmonitor + +This traces sleeping locks (mutexes, rw_semaphores, and the write side of +percpu_rw_semaphores) that are held while the holder is pushed into memory +reclaim. + +A task can take a lock and then, still holding it, allocate memory. If that +allocation cannot be satisfied immediately, the kernel enters direct reclaim +(global) or memcg reclaim (cgroup limit) inline in the allocation path. Reclaim +can run for hundreds of milliseconds. For that whole time the lock stays held, +and every other task that wants it is blocked -- not because the lock is +genuinely hot, but because the holder wandered into the reclaim path. + +This is awkward to diagnose with ordinary lock tooling. A contention profiler +shows you a lock with long waits and a list of waiters, but not *why* the +holder was slow, so the problem reads as lock contention when it is really +memory pressure leaking into a critical section. `reclaimlockmonitor` connects +the two ends: for each lock held across a reclaim episode it reports the total +hold time, how much of that hold was spent in reclaim, whether anyone was +waiting when the lock was released, where the lock was acquired, and where +reclaim was entered. + +## Output + +Running with no arguments reports every lock that was held across a reclaim +episode. Here a single `dd` is writing to a file inside a cgroup whose +`memory.max` is smaller than the amount of page cache the write dirties: + +``` +# ./reclaimlockmonitor.bt +Attached 23 probes +>>> RECLAIM_LOCK: rwsem write 0xffff888889adaa20 + hold=2549 us reclaim=2072 us reclaim_type=memcg + pid=441946 tid=441946 process=dd thread=dd + acquire stack: + + down_write+5 + btrfs_inode_lock+36 + btrfs_buffered_write+108 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 + + reclaim-entry stack (longest episode): + + try_to_free_mem_cgroup_pages+510 + try_to_free_mem_cgroup_pages+510 + __mem_cgroup_charge+1873 + filemap_add_folio+144 + __filemap_get_folio+745 + prepare_one_folio+76 + btrfs_buffered_write+637 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 +``` + +Reading that report line by line: + +* `rwsem write 0xffff888889adaa20` -- the lock was an `rw_semaphore` taken for + write, at kernel address `0xffff888889adaa20`. The address is what lets you + tell "the same lock over and over" from "many different locks"; repeated + reports at one address mean one object is the bottleneck. +* `hold=2549 us` -- the lock was held for 2549 microseconds in total, measured + from the acquiring call returning to the matching unlock. +* `reclaim=2072 us` -- of those 2549 us, 2072 us (81%) were spent inside memory + reclaim. That is the number that matters: the critical section itself was + short, and reclaim is what made it long. +* `reclaim_type=memcg` -- the reclaim was cgroup-limit reclaim rather than + global. It would read `global` for system-wide direct reclaim, or `both` if + the lock happened to be held across one of each. +* `pid=441946 tid=441946 process=dd thread=dd` -- who held it. `pid`/`process` + are the thread group; `tid`/`thread` are the specific thread, which differ + for multithreaded programs. +* `acquire stack` -- where the lock was taken. Here `btrfs_inode_lock` from + `btrfs_buffered_write`: this is the inode lock of the file being written. +* `reclaim-entry stack (longest episode)` -- where reclaim was entered while + the lock was held. Here the write needed a new page cache folio, + `filemap_add_folio` tried to charge it to the cgroup, the charge hit + `memory.max`, and `__mem_cgroup_charge` called into + `try_to_free_mem_cgroup_pages`. If the lock was held across several reclaim + episodes, this is the stack of the longest one. + +So the whole story is: `dd` grabbed the inode lock to do a buffered write, +needed a page for the page cache, hit the cgroup memory limit, and went off to +reclaim for 2 ms while still holding the inode lock. + +That run is not yet a problem, because nothing else wanted that inode. The +interesting case is when something does. Adding `--waiters_only=true` drops +every report where no one was waiting at release time, which is normally the +vast majority of them, and leaves only the locks that actually stalled another +task. With four `dd` processes appending to the *same* file, so they contend +for one inode lock: + +``` +# ./reclaimlockmonitor.bt -- --waiters_only=true +Attached 23 probes +>>> RECLAIM_LOCK: rwsem write 0xffff8887a2d8d220 [WAITERS] + hold=554690 us reclaim=551376 us reclaim_type=memcg + pid=412486 tid=412486 process=dd thread=dd + acquire stack: + + down_write+5 + btrfs_inode_lock+36 + btrfs_buffered_write+108 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 + + reclaim-entry stack (longest episode): + + try_to_free_mem_cgroup_pages+510 + try_to_free_mem_cgroup_pages+510 + __mem_cgroup_charge+1873 + filemap_add_folio+144 + __filemap_get_folio+745 + prepare_one_folio+76 + btrfs_buffered_write+637 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 +``` + +Same code path, much worse outcome. The `[WAITERS]` tag means at least one +other task was blocked on this lock at the moment it was released. The holder +kept the inode lock for 554 ms and spent 551 ms of that -- 99.4% -- in memcg +reclaim. The other three writers were stuck behind it essentially the entire +time. Nothing here is a slow filesystem or a hot lock; it is one cgroup's +memory limit being paid for inside a critical section that everyone else +needs. + +A report can also be tagged `[INFLIGHT]`, which means the lock was still held +when the script was stopped and so was reported by the `END` action instead of +by its unlock. For those, `hold` and `reclaim` are lower bounds -- both were +still growing when tracing ended. + +## Reproducing the examples + +Both runs above came from writing into a cgroup that is too small to hold the +page cache being dirtied, which forces memcg reclaim in the write path: + +``` +mkdir /sys/fs/cgroup/rlmtest +echo 268435456 > /sys/fs/cgroup/rlmtest/memory.max +echo 0 > /sys/fs/cgroup/rlmtest/memory.swap.max + +# first example: one writer, no contention +bash -c 'echo $$ > /sys/fs/cgroup/rlmtest/cgroup.procs + dd if=/dev/zero of=/tmp/work.dat bs=1M count=2500' + +# second example: four writers appending to one file, contending on its inode +bash -c 'echo $$ > /sys/fs/cgroup/rlmtest/cgroup.procs + for i in 1 2 3 4; do + dd if=/dev/zero of=/tmp/shared.dat bs=1M count=1500 \ + conv=notrunc oflag=append & + done + wait' +``` + +Start the tool first and let it finish attaching, then run the workload. + +## Notes and caveats + +* **Overhead is significant.** Every `mutex_lock`/`down_read`/`down_write` in + the system is probed, and a kernel stack is captured on each acquisition. + Use short run windows and do not leave this running on a busy machine. +* **Only the write side of percpu_rw_semaphore is traced.** + `percpu_down_read()`/`percpu_up_read()` are inlined per-CPU counter + increments with no symbol to attach to. The write side is the case worth + watching anyway, since an exclusive writer stalled in reclaim blocks all + readers and writers. +* **Up to 8 held locks are tracked per task.** Deeper nesting is ignored. + Unlocks out of acquisition order are handled. +* **Reclaim is only counted when the task is in a memory stall** + (`in_memstall`), which is what distinguishes an allocation blocked on reclaim + from background reclaim work. +* A lock reported without `[WAITERS]` delayed nobody at the moment it was + released; it is worth knowing about as a latent risk, but it is not an active + stall. Use `--waiters_only=true` to see only the ones that were. +* Requires `CONFIG_DEBUG_INFO_BTF=y`. + +## USAGE + +``` +USAGE: + ./reclaimlockmonitor.bt # all locks seen in reclaim + ./reclaimlockmonitor.bt -- --waiters_only=true # contended locks only +``` diff --git a/reclaimlockmonitor/reclaimlockmonitor.bt b/reclaimlockmonitor/reclaimlockmonitor.bt new file mode 100755 index 0000000..bd1473a --- /dev/null +++ b/reclaimlockmonitor/reclaimlockmonitor.bt @@ -0,0 +1,475 @@ +#!/usr/bin/env bpftrace +// SPDX-License-Identifier: GPL-2.0-or-later +/* + * reclaimlockmonitor.bt - Monitor sleeping locks held during memory reclaim. + * For Linux, uses bpftrace and eBPF. + * + * Tracks mutex, rw_semaphore, and percpu_rw_semaphore (write side) + * acquisitions/releases system-wide, against vmscan direct + memcg reclaim. + * + * On unlock of a lock held during reclaim, emits: reclaim time while held, + * hold time, waiter status, the acquire-site kstack, and the reclaim-entry + * kstack of the longest reclaim episode. + * + * In-flight holders: locks still held when the script stops (never reaching an + * unlock) are emitted by the END action, tagged [INFLIGHT]; their hold and + * reclaim times are lower bounds. A remote task's stack can't be sampled at + * END, so holder identity (pid/thread/process name) and the acquire stack are + * captured at the acquire site and stored in @held. + * + * percpu-rwsem: only the write side is traced -- percpu_down/up_read() are + * inlined per-CPU counter bumps with no symbol to probe. The write side is + * the high-value case anyway: an exclusive writer stalled in reclaim blocks + * all readers and writers. + * + * Nesting: up to 8 held locks per task, non-LIFO unlock via search-and-swap. + * Reclaim does not nest, so begin/end pairs are handled directly. + * + * USAGE: + * ./reclaimlockmonitor.bt # all locks seen in reclaim + * ./reclaimlockmonitor.bt -- --waiters_only=true # contended locks only + * + * --waiters_only=true suppresses reports for locks that had no waiter at + * release, which is usually most of them. A lock nobody was waiting on did + * not actually stall anyone, so this cuts the output down to the reports that + * represent real contention. + * + * WARNING: Tracing all mutex/rwsem ops system-wide has significant overhead; + * the per-acquire kstack capture adds to it. Keep run windows short. + * + * Requires: CONFIG_DEBUG_INFO_BTF=y + * + * Copyright (c) 2026 Shakeel Butt. + */ + +config = { + max_map_keys = 262144; + missing_probes = warn; +} + +let @lock_depth = lruhash(262144); + +macro waiters_only() { + getopt("waiters_only", false) +} + +/* + * pend_acquire - record a pending acquisition at kprobe entry. PID, thread + * name, and the kstack are captured here (call site, where the stack is intact + * -- a kretprobe trampoline can corrupt the unwind) and carried through @pend + * to @held. The process name is captured when the acquisition commits. + */ +macro pend_acquire(@pend, type) { + @pend[tid] = (lock = arg0, type = (uint64)type, + pid = pid, comm = comm, kstack = kstack); +} + +/* + * commit_acquire - at kretprobe, move the @pend record (with its acquire-site + * identity/stacks) onto @held, deleting @pend only when it was found. Call + * unconditionally for void-return locks; for failable locks, guard the call + * with `if (retval == 0)` and delete @pend in the else at the call site. + */ +macro commit_acquire(@pend, @held, @lock_depth) { + let $pend; + if (find(@pend, tid, $pend)) { + $d = @lock_depth[tid]; + if ($d < 8) { + @held[tid, $d] = (lock = $pend.lock, + type = $pend.type, + time = nsecs, + pid = $pend.pid, + comm = $pend.comm, + process_name = + str(curtask->group_leader->comm, 16), + kstack = $pend.kstack); + @lock_depth[tid] = $d + 1; + } + _ = delete(@pend, tid); + } +} + +/* taint_held_locks - OR a taint bit (1=global, 2=memcg) into all held locks. */ +macro taint_held_locks(@held, @lock_depth, @tainted, bit) { + $depth = @lock_depth[tid]; + $i = (int64)0; + unroll(8) { + if ($i < $depth) { + $lk = @held[tid, $i].lock; + @tainted[tid, $lk] = @tainted[tid, $lk] | bit; + } + $i++; + } +} + +/* + * report_reclaim_lock - report one lock held during reclaim. Shared by the + * unlock path (inflight=false) and the END walk (inflight=true); all inputs are + * passed explicitly so it can describe a task other than the current one, and + * untainted locks are skipped. Waiter status and the lock-type string come + * from the stored type (no per-call-site struct knowledge): + * mutex (1): MUTEX_FLAG_WAITERS = owner.counter bit 0 + * rwsem (2/3): RWSEM_FLAG_WAITERS = count.counter bit 1 + * percpu (4): sem->waiters non-empty, tested as (head.next - &head) so the + * (bool) cast has an integer operand (bpftrace rejects casting a + * bool "!=" result); &head via offsetof (spinlock size varies). + * Does not mutate @tainted/@reclaim_accum -- release_lock() clears them after, + * keeping the END for-each callback cheap. + */ +macro report_reclaim_lock(@reclaim_accum, @reclaim_start, @reclaim_kstack, + @reclaim_max, @tainted, + rtid, rlock, rtype_num, racq_ns, + rpid, rcomm, rprocess_name, rkstack, + inflight) { + let $taint_type; + if (find(@tainted, (rtid, rlock), $taint_type)) { + $reclaim_ns = (uint64)@reclaim_accum[rtid, rlock]; + if (@reclaim_start[rtid]) { + $partial = (int64)nsecs - (int64)@reclaim_start[rtid]; + $reclaim_ns += (uint64)$partial; + /* + * A reclaim still in progress is also an episode; let it + * compete for "longest" via its begin stack (folds in the + * ongoing episode for an in-flight holder at END too). + */ + if ($partial > @reclaim_max[rtid, rlock].time) { + @reclaim_max[rtid, rlock] = + (time = $partial, kstack = @reclaim_kstack[rtid]); + } + } + $reclaim_us = $reclaim_ns / (uint64)1000; + $hold_us = (uint64)((int64)nsecs - (int64)racq_ns) / (uint64)1000; + $waiters = rtype_num == 1 + ? (bool)(((struct mutex *)rlock)->owner.counter & 0x01) + : (rtype_num == 4 + ? (bool)((int64)(uint64)(((struct percpu_rw_semaphore *)rlock)->waiters.head.next) - + (int64)(rlock + + offsetof(struct percpu_rw_semaphore, waiters) + + offsetof(struct wait_queue_head, head))) + : (bool)(((struct rw_semaphore *)rlock)->count.counter & 0x02)); + $rtype = $taint_type == 1 ? "global" : + ($taint_type == 2 ? "memcg" : "both"); + $ltype = rtype_num == 1 ? "mutex" : + (rtype_num == 2 ? "rwsem read" : + (rtype_num == 3 ? "rwsem write" : "percpu-rwsem write")); + if ($waiters || !waiters_only()) { + printf(">>> RECLAIM_LOCK: %s %p%s%s\n", + $ltype, rlock, + $waiters ? " [WAITERS]" : "", + inflight ? " [INFLIGHT]" : ""); + printf(" hold=%llu us reclaim=%llu us reclaim_type=%s\n", + $hold_us, $reclaim_us, $rtype); + printf(" pid=%-8d tid=%-8d process=%s thread=%s\n", + rpid, rtid, rprocess_name, rcomm); + printf(" acquire stack:\n"); + print(rkstack); + printf(" reclaim-entry stack (longest episode):\n"); + print(@reclaim_max[rtid, rlock].kstack); + } + } +} + +/* + * release_lock - find the released lock in the held array (handles non-LIFO + * order), report it via report_reclaim_lock() (inflight=false), drop its + * reclaim bookkeeping, and compact the array. The reclaim-map deletes are + * unconditional (no-op if untainted) so report_reclaim_lock() stays delete-free + * and reusable in the END for-each callback. + */ +macro release_lock(@held, @lock_depth, @tainted, @reclaim_accum, + @reclaim_start, @reclaim_kstack, @reclaim_max) { + $lock = arg0; + $depth = @lock_depth[tid]; + + $found = (int64)-1; + $i = (int64)0; + unroll(8) { + if ($i < $depth && @held[tid, $i].lock == $lock) { + $found = $i; + } + $i++; + } + + if ($found >= 0) { + $e = @held[tid, $found]; + report_reclaim_lock(@reclaim_accum, @reclaim_start, @reclaim_kstack, + @reclaim_max, @tainted, + tid, $lock, $e.type, $e.time, + $e.pid, $e.comm, $e.process_name, $e.kstack, + false); + _ = delete(@tainted, (tid, $lock)); + _ = delete(@reclaim_accum, (tid, $lock)); + _ = delete(@reclaim_max, (tid, $lock)); + + $last = $depth - 1; + if ($found != $last) { + @held[tid, $found] = @held[tid, $last]; + } + _ = delete(@held, (tid, $last)); + @lock_depth[tid] = $last; + } +} + +/* + * ===================================================================== + * LOCK ACQUISITION + * + * Save the lock, type, holder identity, and acquire-site stacks into @pend at + * kprobe entry; commit (with acquire timestamp) at the kretprobe, where the + * lock is known held. + * + * Types: 1 = mutex, 2 = rwsem read, 3 = rwsem write, + * 4 = percpu-rwsem write + * ===================================================================== + */ + +/* --- mutex_lock (void return, always succeeds) --- */ + +kprobe:mutex_lock +{ + pend_acquire(@pend, 1); +} + +kretprobe:mutex_lock +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* --- mutex_lock_interruptible / mutex_lock_killable (return 0 on success) --- */ + +kprobe:mutex_lock_interruptible, +kprobe:mutex_lock_killable +{ + pend_acquire(@pend, 1); +} + +kretprobe:mutex_lock_interruptible, +kretprobe:mutex_lock_killable +{ + if (retval == 0) { + commit_acquire(@pend, @held, @lock_depth); + } else { + _ = delete(@pend, tid); + } +} + +/* --- down_read (void return) --- */ + +kprobe:down_read +{ + pend_acquire(@pend, 2); +} + +kretprobe:down_read +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* --- down_read_interruptible / down_read_killable (return 0 on success) --- */ + +kprobe:down_read_interruptible, +kprobe:down_read_killable +{ + pend_acquire(@pend, 2); +} + +kretprobe:down_read_interruptible, +kretprobe:down_read_killable +{ + if (retval == 0) { + commit_acquire(@pend, @held, @lock_depth); + } else { + _ = delete(@pend, tid); + } +} + +/* --- down_write (void return) --- */ + +kprobe:down_write +{ + pend_acquire(@pend, 3); +} + +kretprobe:down_write +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* --- down_write_killable (return 0 on success) --- */ + +kprobe:down_write_killable +{ + pend_acquire(@pend, 3); +} + +kretprobe:down_write_killable +{ + if (retval == 0) { + commit_acquire(@pend, @held, @lock_depth); + } else { + _ = delete(@pend, tid); + } +} + +/* --- percpu_down_write (void return; read side not traceable, see top) --- */ + +kprobe:percpu_down_write +{ + pend_acquire(@pend, 4); +} + +kretprobe:percpu_down_write +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* + * ===================================================================== + * RECLAIM TRACKING (vmscan tracepoints) + * + * Begin: record start time, capture the reclaim-entry kstack (if holding a + * lock), and taint all held locks (1=global, 2=memcg, OR'd). + * End: add elapsed to each tainted lock's @reclaim_accum and keep the longest + * episode in @reclaim_max[tid, lock] = (time, begin-kstack). + * No output here -- reported at unlock, or in END for a still-held lock. + * ===================================================================== + */ + +/* Global (direct) reclaim: taint type bit 0 */ +tracepoint:vmscan:mm_vmscan_direct_reclaim_begin +/ curtask->in_memstall / +{ + @reclaim_start[tid] = nsecs; + /* Stack of the allocation entering reclaim; only useful if we hold a lock. */ + if (@lock_depth[tid] > 0) { + @reclaim_kstack[tid] = kstack; + } + taint_held_locks(@held, @lock_depth, @tainted, 1); +} + +/* Memcg reclaim: taint type bit 1 */ +tracepoint:vmscan:mm_vmscan_memcg_reclaim_begin +/ curtask->in_memstall / +{ + @reclaim_start[tid] = nsecs; + /* Stack of the allocation entering reclaim; only useful if we hold a lock. */ + if (@lock_depth[tid] > 0) { + @reclaim_kstack[tid] = kstack; + } + taint_held_locks(@held, @lock_depth, @tainted, 2); +} + +tracepoint:vmscan:mm_vmscan_direct_reclaim_end, +tracepoint:vmscan:mm_vmscan_memcg_reclaim_end +/ curtask->in_memstall / +{ + /* Add elapsed to each tainted held lock; track the longest episode. */ + $elapsed = (int64)nsecs - (int64)@reclaim_start[tid]; + $depth = @lock_depth[tid]; + $i = (int64)0; + unroll(8) { + if ($i < $depth) { + $lk = @held[tid, $i].lock; + if (@tainted[tid, $lk]) { + @reclaim_accum[tid, $lk] += $elapsed; + if ($elapsed > @reclaim_max[tid, $lk].time) { + @reclaim_max[tid, $lk] = (time = $elapsed, kstack = @reclaim_kstack[tid]); + } + } + } + $i++; + } + _ = delete(@reclaim_start, tid); + _ = delete(@reclaim_kstack, tid); +} + +/* + * ===================================================================== + * LOCK RELEASE + * + * Each unlock handler delegates to release_lock(); waiter detection and the + * lock-type string come from the stored type in report_reclaim_lock(), so the + * unlock probes pass no per-lock struct details. + * ===================================================================== + */ + +kprobe:mutex_unlock +{ + release_lock(@held, @lock_depth, @tainted, @reclaim_accum, + @reclaim_start, @reclaim_kstack, @reclaim_max); +} + +kprobe:up_read +{ + release_lock(@held, @lock_depth, @tainted, @reclaim_accum, + @reclaim_start, @reclaim_kstack, @reclaim_max); +} + +kprobe:up_write +{ + release_lock(@held, @lock_depth, @tainted, @reclaim_accum, + @reclaim_start, @reclaim_kstack, @reclaim_max); +} + +kprobe:percpu_up_write +{ + release_lock(@held, @lock_depth, @tainted, @reclaim_accum, + @reclaim_start, @reclaim_kstack, @reclaim_max); +} + +/* + * ===================================================================== + * CLEANUP ON THREAD EXIT + * + * Drop residual map entries left by a task exiting mid-flight or by missed + * (inlined) lock/unlock probes. + * ===================================================================== + */ + +tracepoint:sched:sched_process_exit +{ + $depth = @lock_depth[tid]; + $i = (int64)0; + unroll(8) { + if ($i < $depth) { + $lock = @held[tid, $i].lock; + _ = delete(@tainted, (tid, $lock)); + _ = delete(@reclaim_accum, (tid, $lock)); + _ = delete(@reclaim_max, (tid, $lock)); + _ = delete(@held, (tid, $i)); + } + $i++; + } + _ = delete(@lock_depth, tid); + _ = delete(@pend, tid); + _ = delete(@reclaim_start, tid); + _ = delete(@reclaim_kstack, tid); +} + +END +{ + /* + * In-flight holders: locks still held at exit that saw reclaim. Hold and + * reclaim time is still growing, so emit with inflight=true using the + * acquire-site identity/stacks in @held (a remote stack can't be sampled + * here). report_reclaim_lock() skips untainted entries. + */ + for ($kv : @held) { + $rtid = $kv.0.0; + $e = $kv.1; + report_reclaim_lock(@reclaim_accum, @reclaim_start, @reclaim_kstack, + @reclaim_max, @tainted, + $rtid, $e.lock, $e.type, $e.time, + $e.pid, $e.comm, $e.process_name, $e.kstack, + true); + } + + clear(@pend); + clear(@held); + clear(@lock_depth); + clear(@tainted); + clear(@reclaim_accum); + clear(@reclaim_start); + clear(@reclaim_kstack); + clear(@reclaim_max); +} diff --git a/runnablelockmonitor/README.md b/runnablelockmonitor/README.md new file mode 100644 index 0000000..adba1e7 --- /dev/null +++ b/runnablelockmonitor/README.md @@ -0,0 +1,278 @@ +# runnablelockmonitor + +This traces sleeping locks (mutexes, rw_semaphores, and the write side of +percpu_rw_semaphores) that are held while the holder is not running on a CPU, +and splits that off-CPU time into two bands with separate stacks. + +When a lock is held for a long time, the interesting question is usually not +"what was the holder computing" but "was the holder even running". A holder can +stop running for two very different reasons: + +* **RUNNABLE** -- it is still on the run queue, ready to go, but not executing. + It lost the CPU to preemption, to CPU contention from other tasks, or to + `cpu.max` throttling. Nothing is wrong with the critical section; the holder + simply cannot get scheduled. +* **SLEEPING** -- it left the run queue because it blocked on something: a + nested lock, RCU, memory reclaim, I/O. Here the critical section really is + waiting on an event, and the block-site stack says which one. + +The distinction matters because the fixes are opposite. A RUNNABLE stall is a +scheduling or capacity problem -- the code is fine, the CPU allocation is not. +A SLEEPING stall is a code problem -- something blocking is being done inside a +critical section. Ordinary lock-contention tooling reports neither; it shows +long waits and leaves you to guess. + +`runnablelockmonitor` reports, for each lock that spent time off-CPU while +held: total hold time, the accumulated and largest-episode time in each band, +the stack where the lock was acquired, the stack where the holder was preempted +(RUNNABLE) and the stack where it blocked (SLEEPING), plus whether anyone was +waiting. + +## Output + +By default a lock is reported when either band exceeds 5000 us. Here four `dd` +processes append to the same file from inside a cgroup confined to 2 CPUs, so +they contend on one inode lock and cannot always get a CPU: + +``` +# ./runnablelockmonitor.bt +Attached 21 probes +>>> OFFCPU_LOCK: rwsem write 0xffff8901fa7c6a20 + hold=15407 us [WAITERS] + runnable=14900 us (max episode 14900 us) + sleeping=0 us (max episode 0 us) + pid=1501555 tid=1501555 process=dd thread=dd + allowed_cpus=2 of 316 system cpus + acquire stack: + + down_write+5 + btrfs_inode_lock+36 + btrfs_buffered_write+108 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 + + largest runnable-episode (preempt) stack: + + __traceiter_sched_switch+87 + __traceiter_sched_switch+87 + __schedule+2554 + __cond_resched+39 + btrfs_buffered_write+1217 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 +``` + +Reading that report line by line: + +* `rwsem write 0xffff8901fa7c6a20` -- an `rw_semaphore` taken for write, at + that kernel address. Repeated reports at one address mean a single object is + the bottleneck; a changing address means many different locks. +* `hold=15407 us` -- the lock was held for 15.4 ms end to end. +* `[WAITERS]` -- at least one other task was blocked on this lock when it was + released. Without this tag the lock delayed nobody. +* `runnable=14900 us (max episode 14900 us)` -- 14.9 ms of the 15.4 ms hold was + spent on the run queue *not executing*. The two numbers being equal means it + was one single 14.9 ms episode rather than many small ones. +* `sleeping=0 us` -- the holder never blocked. It was ready to run the whole + time. +* `allowed_cpus=2 of 316 system cpus` -- the holder was restricted to 2 CPUs + out of 316. This is the key context: a large RUNNABLE band with a small + `allowed_cpus` is affinity- or cgroup-limited scheduling, not system-wide CPU + starvation. +* `acquire stack` -- where the lock was taken: the inode lock of the file being + written. +* `largest runnable-episode (preempt) stack` -- where the holder was preempted. + `__cond_resched` inside `btrfs_buffered_write`: the write path voluntarily + offered the CPU up mid-write, and with only 2 CPUs for four writers plus + other load it did not get one back for 14.9 ms. + +So: the holder was not slow and was not blocked. It gave up the CPU inside a +critical section and then could not get scheduled again, while another writer +sat waiting on the inode lock for essentially the entire time. No amount of +filesystem or lock tuning helps here -- the cgroup needs more CPU. + +### Both bands at once + +When a lock accumulates time in both bands, each gets its own stack, and the +two usually tell different stories: + +``` +>>> OFFCPU_LOCK: rwsem write 0xffff8901fa7c6a20 + hold=56639324 us [WAITERS] + runnable=18700151 us (max episode 15282 us) + sleeping=31688233 us (max episode 208982 us) + pid=1501553 tid=1501553 process=dd thread=dd + allowed_cpus=2 of 316 system cpus + acquire stack: + + down_write+5 + btrfs_inode_lock+36 + btrfs_buffered_write+108 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 + + largest runnable-episode (preempt) stack: + + __traceiter_sched_switch+87 + __traceiter_sched_switch+87 + __schedule+2554 + __cond_resched+39 + shrink_node+741 + do_try_to_free_pages+197 + try_to_free_mem_cgroup_pages+331 + __mem_cgroup_charge+1873 + filemap_add_folio+144 + __filemap_get_folio+745 + prepare_one_folio+76 + btrfs_buffered_write+637 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 + + largest sleep-episode (block-site) stack: + + __traceiter_sched_switch+87 + __traceiter_sched_switch+87 + __schedule+2554 + schedule+67 + schedule_timeout+121 + io_schedule_timeout+72 + balance_dirty_pages_ratelimited_flags+2229 + btrfs_buffered_write+605 + btrfs_do_write_iter+128 + __x64_sys_write+724 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 +``` + +This holder kept the inode lock for 56 seconds: 18.7 s runnable-but-not-running +spread over many short episodes (largest 15 ms), and 31.7 s asleep in a few long +ones (largest 209 ms). The two stacks name two independent problems in the same +critical section. The RUNNABLE stack shows it was preempted inside memcg reclaim +(`shrink_node` under `try_to_free_mem_cgroup_pages`), so the write hit the +cgroup memory limit. The SLEEPING stack shows it also blocked in +`balance_dirty_pages_ratelimited_flags` -> `io_schedule_timeout`, dirty-page +throttling waiting on writeback. Meanwhile `[WAITERS]` means other writers were +queued behind the inode lock through all of it. + +### Throttled holders + +A RUNNABLE episode that began while the holder's CFS hierarchy was throttled by +`cpu.max` is tagged `[THROTTLED]` and its episode stack is labeled `throttle` +instead of `preempt`: + +``` +>>> OFFCPU_LOCK: rwsem write 0xffff8905a5820678 + hold=101750 us [WAITERS] [THROTTLED] + runnable=97865 us (max episode 97865 us) + sleeping=0 us (max episode 0 us) + pid=1533956 tid=1533956 process=bash thread=bash + allowed_cpus=2 of 316 system cpus + acquire stack: + + down_write_killable+5 + copy_process+5203 + kernel_clone+137 + __x64_sys_clone+197 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 + + largest runnable-episode (throttle) stack: + + __traceiter_sched_switch+87 + __traceiter_sched_switch+87 + __schedule+2554 + __cond_resched+39 + copy_page_range+2503 + copy_process+6114 + kernel_clone+137 + __x64_sys_clone+197 + do_syscall_64+84 + entry_SYSCALL_64_after_hwframe+108 +``` + +`bash` forked, took `mmap_lock` for write in `copy_process`, and ran out of +`cpu.max` quota partway through `copy_page_range`. It was thrown off the CPU +for 97 ms still holding the lock, with another thread waiting. This is the +worst version of the RUNNABLE case: throttling is self-inflicted by +configuration, and it stopped a task in the middle of a critical section. + +Note that this tag only appears on kernels that throttle inline. Kernels that +defer `cpu.max` throttling to exit-to-userspace (they have +`throttle_cfs_rq_work`) never throttle a holder mid-critical-section, so the +tool detects that symbol and suppresses the tag rather than reporting something +that cannot happen. + +A report can also carry `[INFLIGHT]`, meaning the lock was still held when the +script stopped and so was reported by the `END` action. For those, all the time +figures are lower bounds -- they were still growing when tracing ended. + +## Reproducing the examples + +The first two came from four writers appending to one file inside a cgroup +confined to 2 CPUs and a small memory limit, with spinners added to make those +CPUs genuinely scarce: + +``` +mkdir /sys/fs/cgroup/rlmtest +echo "0-1" > /sys/fs/cgroup/rlmtest/cpuset.cpus +echo 268435456 > /sys/fs/cgroup/rlmtest/memory.max +echo 0 > /sys/fs/cgroup/rlmtest/memory.swap.max + +bash -c 'echo $$ > /sys/fs/cgroup/rlmtest/cgroup.procs + for i in 1 2 3 4; do + dd if=/dev/zero of=/tmp/shared.dat bs=1M count=800 \ + conv=notrunc oflag=append & + done + for i in 1 2 3 4 5 6; do (while :; do :; done) & done + sleep 24; kill $(jobs -p)' +``` + +The throttled example added a quota to the same cgroup: + +``` +echo "10000 100000" > /sys/fs/cgroup/rlmtest/cpu.max # 10% of one CPU +``` + +Start the tool first and let it finish attaching, then run the workload. + +## Notes and caveats + +* **Overhead is significant.** `sched_switch` fires constantly, every + `mutex_lock`/`down_read`/`down_write` in the system is probed, and a kernel + stack is captured on each acquisition. Use short run windows and do not leave + this running on a busy machine. +* **The default thresholds are 5000 us for each band**, and a lock is reported + if *either* band crosses its own threshold. Lower them with + `--min_runnable_us` / `--min_sleep_us` to see shorter episodes, at the cost of + a lot more output. +* **`allowed_cpus` is captured at acquisition time** and is the size of the + holder's CPU affinity mask. Compare it against the system CPU count in the + same line to tell affinity-limited scheduling from global CPU contention. +* **Only the write side of percpu_rw_semaphore is traced.** + `percpu_down_read()`/`percpu_up_read()` are inlined per-CPU counter + increments with no symbol to attach to. An exclusive writer that loses the + CPU while holding the lock blocks all readers and writers. +* **Up to 8 held locks are tracked per task.** Deeper nesting is ignored. + Unlocks out of acquisition order are handled. +* A lock reported without `[WAITERS]` delayed nobody at the moment it was + released. Use `--waiters_only=true` to see only the ones that did. +* Requires `CONFIG_DEBUG_INFO_BTF=y`. + +## USAGE + +``` +USAGE: + ./runnablelockmonitor.bt # both bands >= 5000 us + ./runnablelockmonitor.bt -- --waiters_only=true # contended locks only + ./runnablelockmonitor.bt -- --min_runnable_us=500 # runnable >= 500 us + ./runnablelockmonitor.bt -- --min_sleep_us=500 # sleeping >= 500 us +A lock is reported if EITHER band crosses its threshold. +``` diff --git a/runnablelockmonitor/runnablelockmonitor.bt b/runnablelockmonitor/runnablelockmonitor.bt new file mode 100755 index 0000000..c7ffcf8 --- /dev/null +++ b/runnablelockmonitor/runnablelockmonitor.bt @@ -0,0 +1,629 @@ +#!/usr/bin/env bpftrace +// SPDX-License-Identifier: GPL-2.0-or-later +/* + * runnablelockmonitor.bt - Monitor sleeping locks held while off-CPU. + * For Linux, uses bpftrace and eBPF. + * + * Tracks mutex, rw_semaphore, and percpu_rw_semaphore (write side) + * acquisitions/releases system-wide. Uses sched_switch / sched_wakeup to + * split the time a lock is held off-CPU into two bands: + * + * RUNNABLE - holder on the run queue but not executing (lost the CPU to + * preemption, CPU contention, or throttling). + * SLEEPING - holder left the run queue blocked on an event (nested lock, + * RCU, reclaim, I/O, ...); the block-site kstack says what. + * + * prev_state from sched_switch (__trace_sched_switch_state()): 0 (voluntary + * schedule while TASK_RUNNING) and 256 (TASK_REPORT_MAX involuntary preempt / + * cond_resched) are RUNNABLE; &1 (S) / &2 (D) are SLEEPING. A lock holder + * preempted in kernel context reports 256, not 0. + * + * On unlock of a lock that spent time off-CPU, emits: accumulated RUNNABLE and + * SLEEPING time while held, the largest single episode of each band and its + * stack, waiter status, hold time, and the acquire-site kstack. + * + * THROTTLE tag: a RUNNABLE episode begun while the holder's CFS hierarchy is + * throttled (cfs_rq->throttle_count > 0) is tagged (@tainted & 4) and reported + * as [THROTTLED]. Only inline-throttle kernels dequeue a running lock holder; + * kernels that defer cpu.max throttling to exit-to-user (throttle_cfs_rq_work) + * never throttle a holder mid-critical-section, so that symbol's presence + * (kfunc_exist(), folded at compile time via deferred_throttle()) suppresses + * the tag. On inline kernels the symbol is absent so the builtin folds to + * false and the tag stays live. + * + * In-flight holders: locks still held when the script stops are emitted by the + * END action, tagged [INFLIGHT]; their off-CPU time is still accruing and a + * remote holder may be off-CPU right now. A remote task's stack can't be + * sampled at END, so holder identity (pid/thread/process name) and the acquire + * stack are captured at the acquire site and stored in @held. + * + * percpu-rwsem: only the write side is traced -- percpu_down/up_read() are + * inlined per-CPU counter bumps with no symbol to probe. An exclusive writer + * that loses the CPU while held blocks all readers and writers. + * + * Nesting: up to 8 held locks per task, non-LIFO unlock via search-and-swap. + * + * USAGE: + * ./runnablelockmonitor.bt # both bands >= 5000 us + * ./runnablelockmonitor.bt -- --waiters_only=true # contended locks only + * ./runnablelockmonitor.bt -- --min_runnable_us=500 # runnable >= 500 us + * ./runnablelockmonitor.bt -- --min_sleep_us=500 # sleeping >= 500 us + * A lock is reported if EITHER band crosses its threshold. + * + * WARNING: sched_switch fires very frequently, and the per-acquire kstack + * capture adds to it. Significant overhead -- keep runs short. + * + * Requires: CONFIG_DEBUG_INFO_BTF=y + * + * Copyright (c) 2026 Shakeel Butt. + */ + +config = { + max_map_keys = 262144; + missing_probes = warn; +} + +let @lock_depth = lruhash(262144); + +macro waiters_only() { + getopt("waiters_only", false) +} + +macro min_runnable_us() { + getopt("min_runnable_us", 5000) +} + +macro min_sleep_us() { + getopt("min_sleep_us", 5000) +} + +/* + * deferred_throttle - compile-time true on defer-throttle kernels, where + * cpu.max throttling is deferred to exit-to-userspace (throttle_cfs_rq_work) + * and a lock holder is never throttled off-CPU mid-critical-section. The + * throttle tag is suppressed there; on inline kernels the symbol is absent so + * kfunc_exist() folds to false and the tag stays live. + */ +macro deferred_throttle() { + kfunc_exist("throttle_cfs_rq_work") +} + +/* + * pend_acquire - record a pending acquisition at kprobe entry. PID, thread + * name, nr_cpus_allowed (size of the holder's CPU affinity mask), and the + * kstack are captured here (call site, where the stack is intact -- a kretprobe + * trampoline can corrupt the unwind) and carried through @pend to @held. The + * process name is captured when the acquisition commits. + */ +macro pend_acquire(@pend, type) { + @pend[tid] = (lock = arg0, type = (uint64)type, + pid = pid, comm = comm, + nr_cpus_allowed = curtask->nr_cpus_allowed, + kstack = kstack); +} + +/* + * commit_acquire - at kretprobe, move the @pend record (with its acquire-site + * identity/stack) onto @held, deleting @pend only when it was found. Call + * unconditionally for void-return locks; for failable locks, guard the call + * with `if (retval == 0)` and delete @pend in the else at the call site. + */ +macro commit_acquire(@pend, @held, @lock_depth) { + let $pend; + if (find(@pend, tid, $pend)) { + $d = @lock_depth[tid]; + if ($d < 8) { + @held[tid, $d] = (lock = $pend.lock, + type = $pend.type, + time = nsecs, + pid = $pend.pid, + comm = $pend.comm, + process_name = + str(curtask->group_leader->comm, 16), + nr_cpus_allowed = $pend.nr_cpus_allowed, + kstack = $pend.kstack); + @lock_depth[tid] = $d + 1; + } + _ = delete(@pend, tid); + } +} + +/* + * taint_held_locks - OR `bits` (1 = runnable, 2 = sleeping, 4 = throttled) into + * every held lock of target_tid (which may differ from the current task, e.g. a + * woken task). All bands share one @tainted map to keep the map footprint + * loadable. + */ +macro taint_held_locks(@held, @lock_depth, @tainted, target_tid, bits) { + let $td; + if (find(@lock_depth, target_tid, $td)) { + $depth = $td; + $i = (int64)0; + unroll(8) { + if ($i < $depth) { + $lk = @held[target_tid, $i].lock; + @tainted[target_tid, $lk] = + @tainted[target_tid, $lk] | bits; + } + $i++; + } + } +} + +/* + * report_offcpu_lock - report one lock that spent time off-CPU while held. + * Shared by the unlock path (inflight=false) and the END walk (inflight=true); + * all inputs are passed explicitly so it can describe a task other than the + * current one. Adds any still-open partial episode: a RUNNABLE one (@runnable + * _start, rare at unlock) and -- for a remote holder still sleeping at END -- a + * SLEEPING one (@sleep_info). Waiter status and the lock-type string come from + * the stored type (no per-call-site struct knowledge): + * mutex (1): MUTEX_FLAG_WAITERS = owner.counter bit 0 + * rwsem (2/3): RWSEM_FLAG_WAITERS = count.counter bit 1 + * percpu (4): sem->waiters non-empty, tested as (head.next - &head) so the + * (bool) cast has an integer operand (bpftrace rejects casting a + * bool "!=" result); &head via offsetof (spinlock size varies). + * Reports if EITHER band crosses its threshold. Does not mutate the accum/max + * maps beyond the partial-episode update; release_lock() clears them after. + */ +macro report_offcpu_lock(@runnable_accum, @runnable_start, @runnable_kstack, + @runnable_max, @sleep_accum, @sleep_max, @sleep_info, + @tainted, rtid, rlock, rtype_num, racq_ns, + rpid, rcomm, rprocess_name, rnr_cpus_allowed, + rkstack, inflight) { + let $taint; + if (find(@tainted, (rtid, rlock), $taint)) { + /* + * Add each band's still-open partial episode, clipped to this + * holding: counted only when it began at/after the acquire (racq_ns), + * so a stale runnable_start/sleep_info from an earlier holding of a + * reused lock address can't make a band exceed hold time. + */ + $runnable_ns = (uint64)@runnable_accum[rtid, rlock]; + if (@runnable_start[rtid] && + (int64)@runnable_start[rtid] >= (int64)racq_ns) { + $rpart = (int64)nsecs - (int64)@runnable_start[rtid]; + $runnable_ns += (uint64)$rpart; + if ($rpart > @runnable_max[rtid, rlock].time) { + @runnable_max[rtid, rlock] = (time = $rpart, kstack = @runnable_kstack[rtid]); + } + } + $runnable_us = $runnable_ns / (uint64)1000; + $max_runnable_us = (uint64)@runnable_max[rtid, rlock].time / (uint64)1000; + + $sleep_ns = (uint64)@sleep_accum[rtid, rlock]; + let $si_rec; + if (find(@sleep_info, rtid, $si_rec) && + $si_rec.time >= (int64)racq_ns) { + $spart = (int64)nsecs - $si_rec.time; + $sleep_ns += (uint64)$spart; + if ($spart > @sleep_max[rtid, rlock].time) { + @sleep_max[rtid, rlock] = (time = $spart, kstack = $si_rec.kstack); + } + } + $sleep_us = $sleep_ns / (uint64)1000; + $max_sleep_us = (uint64)@sleep_max[rtid, rlock].time / (uint64)1000; + + $hold_us = (uint64)((int64)nsecs - (int64)racq_ns) / (uint64)1000; + $waiters = rtype_num == 1 + ? (bool)(((struct mutex *)rlock)->owner.counter & 0x01) + : (rtype_num == 4 + ? (bool)((int64)(uint64)(((struct percpu_rw_semaphore *)rlock)->waiters.head.next) - + (int64)(rlock + + offsetof(struct percpu_rw_semaphore, waiters) + + offsetof(struct wait_queue_head, head))) + : (bool)(((struct rw_semaphore *)rlock)->count.counter & 0x02)); + $ltype = rtype_num == 1 ? "mutex" : + (rtype_num == 2 ? "rwsem read" : + (rtype_num == 3 ? "rwsem write" : "percpu-rwsem write")); + /* @tainted value for this held lock; & 4 = a throttle episode occurred */ + $is_throttle = $taint & 4; + if (($runnable_us >= min_runnable_us() || + $sleep_us >= min_sleep_us()) && + ($waiters || !waiters_only())) { + printf(">>> OFFCPU_LOCK: %s %p\n", $ltype, rlock); + printf(" hold=%llu us%s%s%s\n", + $hold_us, + $waiters ? " [WAITERS]" : "", + $is_throttle ? " [THROTTLED]" : "", + inflight ? " [INFLIGHT]" : ""); + printf(" runnable=%llu us (max episode %llu us)\n", + $runnable_us, $max_runnable_us); + printf(" sleeping=%llu us (max episode %llu us)\n", + $sleep_us, $max_sleep_us); + printf(" pid=%-8d tid=%-8d process=%s thread=%s\n", + rpid, rtid, rprocess_name, rcomm); + printf(" allowed_cpus=%d of %d system cpus\n", + rnr_cpus_allowed, ncpus); + printf(" acquire stack:\n"); + print(rkstack); + if ($max_runnable_us) { + printf(" largest runnable-episode (%s) stack:\n", + $is_throttle ? "throttle" : "preempt"); + print(@runnable_max[rtid, rlock].kstack); + } + if ($max_sleep_us) { + printf(" largest sleep-episode (block-site) stack:\n"); + print(@sleep_max[rtid, rlock].kstack); + } + } + } +} + +/* + * release_lock - find the released lock in the held array (handles non-LIFO + * order), report it via report_offcpu_lock() (inflight=false), drop its + * per-band bookkeeping, and compact the array. The map deletes are + * unconditional (no-op if untainted) so report_offcpu_lock() stays delete-free + * and reusable in the END for-each callback. + */ +macro release_lock(@held, @lock_depth, @tainted, @runnable_accum, + @runnable_start, @runnable_kstack, @runnable_max, + @sleep_accum, @sleep_max, @sleep_info) { + $lock = arg0; + $depth = @lock_depth[tid]; + + $found = (int64)-1; + $i = (int64)0; + unroll(8) { + if ($i < $depth && @held[tid, $i].lock == $lock) { + $found = $i; + } + $i++; + } + + if ($found >= 0) { + $e = @held[tid, $found]; + report_offcpu_lock(@runnable_accum, @runnable_start, @runnable_kstack, + @runnable_max, @sleep_accum, @sleep_max, @sleep_info, @tainted, + tid, $lock, $e.type, $e.time, + $e.pid, $e.comm, $e.process_name, $e.nr_cpus_allowed, + $e.kstack, false); + _ = delete(@tainted, (tid, $lock)); + _ = delete(@runnable_accum, (tid, $lock)); + _ = delete(@runnable_max, (tid, $lock)); + _ = delete(@sleep_accum, (tid, $lock)); + _ = delete(@sleep_max, (tid, $lock)); + + $last = $depth - 1; + if ($found != $last) { + @held[tid, $found] = @held[tid, $last]; + } + _ = delete(@held, (tid, $last)); + @lock_depth[tid] = $last; + } +} + +/* + * ===================================================================== + * LOCK ACQUISITION + * + * Save the lock, type, holder identity, and acquire-site stack into @pend at + * kprobe entry; commit (with acquire timestamp) at the kretprobe, where the + * lock is known held. + * + * Types: 1 = mutex, 2 = rwsem read, 3 = rwsem write, + * 4 = percpu-rwsem write + * ===================================================================== + */ + +/* --- mutex_lock (void return, always succeeds) --- */ + +kprobe:mutex_lock +{ + pend_acquire(@pend, 1); +} + +kretprobe:mutex_lock +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* --- mutex_lock_interruptible / mutex_lock_killable (return 0 on success) --- */ + +kprobe:mutex_lock_interruptible, +kprobe:mutex_lock_killable +{ + pend_acquire(@pend, 1); +} + +kretprobe:mutex_lock_interruptible, +kretprobe:mutex_lock_killable +{ + if (retval == 0) { + commit_acquire(@pend, @held, @lock_depth); + } else { + _ = delete(@pend, tid); + } +} + +/* --- down_read (void return) --- */ + +kprobe:down_read +{ + pend_acquire(@pend, 2); +} + +kretprobe:down_read +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* --- down_read_interruptible / down_read_killable (return 0 on success) --- */ + +kprobe:down_read_interruptible, +kprobe:down_read_killable +{ + pend_acquire(@pend, 2); +} + +kretprobe:down_read_interruptible, +kretprobe:down_read_killable +{ + if (retval == 0) { + commit_acquire(@pend, @held, @lock_depth); + } else { + _ = delete(@pend, tid); + } +} + +/* --- down_write (void return) --- */ + +kprobe:down_write +{ + pend_acquire(@pend, 3); +} + +kretprobe:down_write +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* --- down_write_killable (return 0 on success) --- */ + +kprobe:down_write_killable +{ + pend_acquire(@pend, 3); +} + +kretprobe:down_write_killable +{ + if (retval == 0) { + commit_acquire(@pend, @held, @lock_depth); + } else { + _ = delete(@pend, tid); + } +} + +/* --- percpu_down_write (void return; read side not traceable, see top) --- */ + +kprobe:percpu_down_write +{ + pend_acquire(@pend, 4); +} + +kretprobe:percpu_down_write +{ + commit_acquire(@pend, @held, @lock_depth); +} + +/* + * ===================================================================== + * OFF-CPU STATE TRACKING (sched_switch + sched_wakeup) + * + * A held lock's holder can lose the CPU as RUNNABLE (still queued: preempt / + * yield, or just woken and awaiting a CPU) or SLEEPING (off the queue, + * blocked). On band entry we record per-task timing and the holder's kstack + * (preempt point / block site) and taint held locks (@tainted 1 = runnable, + * 2 = sleeping, 4 = throttled; shared map to stay loadable). + * On exit -- a switch-in ends RUNNABLE, a sched_wakeup ends SLEEPING -- the + * elapsed time is added to each tainted lock and the largest episode kept in + * @runnable_max / @sleep_max = (time, kstack). + * ===================================================================== + */ + +/* + * sched_wakeup: the seam between bands -- ends a SLEEPING episode and begins a + * RUNNABLE one (woken task now queued). tid is the WAKER; use args->pid. + */ +tracepoint:sched:sched_wakeup +{ + $woken_tid = (uint32)args->pid; + let $wd; + if (find(@lock_depth, $woken_tid, $wd) && $wd > 0) { + /* + * Sleep exit: close the SLEEPING episode (entry time + block-site + * kstack from @sleep_info) into each held sleeping-tainted lock. + */ + let $si_rec; + if (find(@sleep_info, $woken_tid, $si_rec)) { + $elapsed = (int64)nsecs - $si_rec.time; + $sdepth = $wd; + $si = (int64)0; + unroll(8) { + if ($si < $sdepth) { + $slk = @held[$woken_tid, $si].lock; + if (@tainted[$woken_tid, $slk] & 2) { + @sleep_accum[$woken_tid, $slk] += $elapsed; + if ($elapsed > @sleep_max[$woken_tid, $slk].time) { + @sleep_max[$woken_tid, $slk] = (time = $elapsed, kstack = $si_rec.kstack); + } + } + } + $si++; + } + _ = delete(@sleep_info, $woken_tid); + } + + /* Runnable entry: now queued, waiting for a CPU. */ + if (!@runnable_start[$woken_tid]) { + @runnable_start[$woken_tid] = nsecs; + taint_held_locks(@held, @lock_depth, @tainted, $woken_tid, 1); + } + } +} + +tracepoint:sched:sched_switch +{ + /* Incoming task leaves RUNNABLE; use args->next_pid (tid is outgoing). */ + $next_tid = (uint32)args->next_pid; + let $rs; + if (find(@runnable_start, $next_tid, $rs)) { + $elapsed = (int64)nsecs - (int64)$rs; + let $nd; + if (find(@lock_depth, $next_tid, $nd)) { + $depth = $nd; + $i = (int64)0; + unroll(8) { + if ($i < $depth) { + $lk = @held[$next_tid, $i].lock; + if (@tainted[$next_tid, $lk] & 1) { + @runnable_accum[$next_tid, $lk] += $elapsed; + if ($elapsed > @runnable_max[$next_tid, $lk].time) { + @runnable_max[$next_tid, $lk] = (time = $elapsed, kstack = @runnable_kstack[$next_tid]); + } + } + } + $i++; + } + } + _ = delete(@runnable_start, $next_tid); + _ = delete(@runnable_kstack, $next_tid); + } + + /* + * Outgoing task lost the CPU while holding locks. prev_state 0/256 = + * RUNNABLE (voluntary / involuntary preempt); &1 (S) / &2 (D) = SLEEPING. + * The captured kstack is the holder's own: preempt point for RUNNABLE, + * block site for SLEEPING. + */ + $ps = args->prev_state; + $is_runnable = ($ps == 0 || $ps == 256); + $is_sleeping = (($ps & 0x3) != 0); + let $od; + if (($is_runnable || $is_sleeping) && find(@lock_depth, tid, $od) && + $od > 0) { + if ($is_runnable && !@runnable_start[tid]) { + @runnable_start[tid] = nsecs; + @runnable_kstack[tid] = kstack; + taint_held_locks(@held, @lock_depth, @tainted, tid, 1); + /* + * Throttle tag (@tainted & 4): holder left CPU while its CFS + * hierarchy is throttled (cfs_rq->throttle_count > 0); + * deferred_throttle() suppresses this on defer-throttle + * kernels. curtask == prev (outgoing) here. + */ + if (!deferred_throttle() && curtask->se.cfs_rq != 0 && + curtask->se.cfs_rq->throttle_count > 0) { + taint_held_locks(@held, @lock_depth, @tainted, + tid, 4); + } + } + if ($is_sleeping && !has_key(@sleep_info, tid)) { + /* Entry time + block site (what it waits for) per task. */ + @sleep_info[tid] = (time = (int64)nsecs, kstack = kstack); + taint_held_locks(@held, @lock_depth, @tainted, tid, 2); + } + } +} + +/* + * ===================================================================== + * LOCK RELEASE + * + * Each unlock handler delegates to release_lock(); waiter detection and the + * lock-type string come from the stored type in report_offcpu_lock(), so the + * unlock probes pass no per-lock struct details. + * ===================================================================== + */ + +kprobe:mutex_unlock +{ + release_lock(@held, @lock_depth, @tainted, @runnable_accum, + @runnable_start, @runnable_kstack, @runnable_max, + @sleep_accum, @sleep_max, @sleep_info); +} + +kprobe:up_read +{ + release_lock(@held, @lock_depth, @tainted, @runnable_accum, + @runnable_start, @runnable_kstack, @runnable_max, + @sleep_accum, @sleep_max, @sleep_info); +} + +kprobe:up_write +{ + release_lock(@held, @lock_depth, @tainted, @runnable_accum, + @runnable_start, @runnable_kstack, @runnable_max, + @sleep_accum, @sleep_max, @sleep_info); +} + +kprobe:percpu_up_write +{ + release_lock(@held, @lock_depth, @tainted, @runnable_accum, + @runnable_start, @runnable_kstack, @runnable_max, + @sleep_accum, @sleep_max, @sleep_info); +} + +/* + * ===================================================================== + * CLEANUP ON THREAD EXIT + * + * Drop residual map entries left by a task exiting mid-flight or by missed + * (inlined) lock/unlock probes. + * ===================================================================== + */ + +tracepoint:sched:sched_process_exit +{ + $depth = @lock_depth[tid]; + $i = (int64)0; + unroll(8) { + if ($i < $depth) { + $lock = @held[tid, $i].lock; + _ = delete(@tainted, (tid, $lock)); + _ = delete(@runnable_accum, (tid, $lock)); + _ = delete(@runnable_max, (tid, $lock)); + _ = delete(@sleep_accum, (tid, $lock)); + _ = delete(@sleep_max, (tid, $lock)); + _ = delete(@held, (tid, $i)); + } + $i++; + } + _ = delete(@lock_depth, tid); + _ = delete(@pend, tid); + _ = delete(@runnable_start, tid); + _ = delete(@runnable_kstack, tid); + _ = delete(@sleep_info, tid); +} + +END +{ + /* + * In-flight holders: locks still held at exit that spent time off-CPU. + * Off-CPU time is still growing (and the holder may be off-CPU now), so + * emit with inflight=true using the acquire-site identity/stack in @held + * (a remote stack can't be sampled here). Untainted entries are skipped. + */ + for ($kv : @held) { + $rtid = $kv.0.0; + $e = $kv.1; + report_offcpu_lock(@runnable_accum, @runnable_start, @runnable_kstack, + @runnable_max, @sleep_accum, @sleep_max, @sleep_info, @tainted, + $rtid, $e.lock, $e.type, $e.time, + $e.pid, $e.comm, $e.process_name, $e.nr_cpus_allowed, + $e.kstack, true); + } + + clear(@pend); + clear(@held); + clear(@lock_depth); + clear(@tainted); + clear(@runnable_accum); + clear(@runnable_start); + clear(@runnable_kstack); + clear(@runnable_max); + clear(@sleep_accum); + clear(@sleep_max); + clear(@sleep_info); +}