From 857cf5048e9aafda931d5ab002864eb9e7dde546 Mon Sep 17 00:00:00 2001 From: Ivan Babrou Date: Wed, 17 Aug 2022 11:31:19 -0700 Subject: [PATCH] libbpf-tools/klockstat: accept lock addr as well as lock name The following PR added printing for lock addr and name in max acq/hold times: * https://github.com/iovisor/bcc/pull/4188 This is how it looks like: ``` $ sudo ./klockstat -d 5 -c down_ -n 2 -s 2 -S hld_total -p 39643 Tracing mutex/sem lock events... Hit Ctrl-C to end Caller Avg Wait Count Max Wait Total Wait down_read+0x5 8.0 us 10685 83.2 ms 85.0 ms kernfs_iop_permission+0x27 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Caller Avg Wait Count Max Wait Total Wait down_read+0x5 2.1 us 36025 71.1 ms 76.8 ms kernfs_iop_permission+0x27 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Caller Avg Hold Count Max Hold Total Hold down_read_killable+0x5 8.2 us 19386 297.7 us 158.1 ms iterate_dir+0x52 Max PID 39643, COMM cadvisor, Lock no-ksym (0xffff9477eec5f1a8) Caller Avg Hold Count Max Hold Total Hold down_read+0x5 209 ns 82630 8.9 us 17.3 ms kernfs_fop_readdir+0x115 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) ``` Previously it was possible to filter on lock name only: ``` $ sudo ./klockstat -d 5 -c down_ -n 2 -s 2 -S hld_total -p 39643 -L kernfs_rwsem Tracing mutex/sem lock events... Hit Ctrl-C to end Caller Avg Wait Count Max Wait Total Wait down_read+0x5 1.5 us 32126 41.3 ms 46.9 ms kernfs_iop_permission+0x27 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Caller Avg Wait Count Max Wait Total Wait down_read+0x5 156 ns 66104 94.6 us 10.3 ms kernfs_fop_readdir+0x115 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Caller Avg Hold Count Max Hold Total Hold down_read+0x5 305 ns 66104 97.8 us 20.2 ms kernfs_fop_readdir+0x115 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Caller Avg Hold Count Max Hold Total Hold down_read+0x5 115 ns 32126 5.5 us 3.7 ms kernfs_iop_permission+0x27 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Exiting trace of mutex/sem locks ``` Now it's also possible to filter on lock addr: ``` $ sudo ./klockstat -d 5 -c down_ -n 2 -s 2 -S hld_total -p 39643 -L 0xffff9477eec5f1a8 Tracing mutex/sem lock events... Hit Ctrl-C to end Caller Avg Wait Count Max Wait Total Wait down_read_killable+0x5 227 ns 68 1.0 us 15.4 us iterate_dir+0x52 Max PID 39643, COMM cadvisor, Lock no-ksym (0xffff9477eec5f1a8) Caller Avg Hold Count Max Hold Total Hold down_read_killable+0x5 191.5 us 68 238.3 us 13.0 ms iterate_dir+0x52 Max PID 39643, COMM cadvisor, Lock no-ksym (0xffff9477eec5f1a8) ``` This is useful for locks that are per process, like `mmap_lock`. --- libbpf-tools/klockstat.c | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/libbpf-tools/klockstat.c b/libbpf-tools/klockstat.c index 2029f2817a96..e3252f9af41c 100644 --- a/libbpf-tools/klockstat.c +++ b/libbpf-tools/klockstat.c @@ -83,7 +83,7 @@ static const char program_doc[] = " klockstat -t 181 # trace thread 181 only\n" " klockstat -c pipe_ # print only for lock callers with 'pipe_'\n" " # prefix\n" -" klockstat -L cgroup_mutex # trace the cgroup_mutex lock only\n" +" klockstat -L cgroup_mutex # trace the cgroup_mutex lock only (accepts addr too)\n" " klockstat -S acq_count # sort lock acquired results by acquire count\n" " klockstat -S hld_total # sort lock held results by total held time\n" " klockstat -S acq_count,hld_total # combination of above\n" @@ -114,11 +114,17 @@ static const struct argp_option opts[] = { {}, }; +static void *parse_lock_addr(const char *lock_name) { + unsigned long lock_addr; + + return sscanf(lock_name, "0x%lx", &lock_addr) ? (void*)lock_addr : NULL; +} + static void *get_lock_addr(struct ksyms *ksyms, const char *lock_name) { const struct ksym *ksym = ksyms__get_symbol(ksyms, lock_name); - return ksym ? (void*)ksym->addr : NULL; + return ksym ? (void*)ksym->addr : parse_lock_addr(lock_name); } const char *get_lock_name(struct ksyms *ksyms, unsigned long addr)