From 23f16da743c03891ac2499601afe10d42381aa31 Mon Sep 17 00:00:00 2001 From: Ivan Babrou Date: Wed, 17 Aug 2022 10:57:26 -0700 Subject: [PATCH] libbpf-tools/klockstat: print the lock info for max acq/hold times This is handy if you want to look at a specific lock: ``` $ sudo ./klockstat -d 5 -c down_ -n 2 -s 2 -S hld_total Tracing mutex/sem lock events... Hit Ctrl-C to end Caller Avg Wait Count Max Wait Total Wait down_read+0x5 155 ns 33052 115.5 us 5.1 ms kernfs_fop_readdir+0x115 Max PID 39643, COMM cadvisor, Lock kernfs_rwsem (0xffffffff89f87e00) Caller Avg Wait Count Max Wait Total Wait down_read+0x5 161 ns 14438 66.7 us 2.3 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.3 us 7751 373.9 us 64.3 ms iterate_dir+0x52 Max PID 39643, COMM cadvisor, Lock no-ksym (0xffff9477eec5f1a8) Caller Avg Hold Count Max Hold Total Hold down_read_trylock+0x5 2.1 us 4066 50.8 us 8.5 ms do_user_addr_fault+0x11c Max PID 40402, COMM flb-pipeline, Lock no-ksym (0xffff9496c8231168) ``` --- libbpf-tools/klockstat.bpf.c | 4 ++++ libbpf-tools/klockstat.c | 33 ++++++++++++++++++++++----------- libbpf-tools/klockstat.h | 2 ++ 3 files changed, 28 insertions(+), 11 deletions(-) diff --git a/libbpf-tools/klockstat.bpf.c b/libbpf-tools/klockstat.bpf.c index 26371c6846c4..d003859f2d1b 100644 --- a/libbpf-tools/klockstat.bpf.c +++ b/libbpf-tools/klockstat.bpf.c @@ -38,6 +38,7 @@ struct lockholder_info { u64 try_at; u64 acq_at; u64 rel_at; + u64 lock_ptr; }; struct { @@ -86,6 +87,7 @@ static void lock_contended(void *ctx, void *lock) return; li->task_id = task_id; + li->lock_ptr = (u64)lock; /* * Skip 4 frames, e.g.: * __this_module+0x34ef @@ -181,6 +183,7 @@ static void account(struct lockholder_info *li) if (delta > READ_ONCE(ls->acq_max_time)) { WRITE_ONCE(ls->acq_max_time, delta); WRITE_ONCE(ls->acq_max_id, li->task_id); + WRITE_ONCE(ls->acq_max_lock_ptr, li->lock_ptr); /* * Potentially racy, if multiple threads think they are the max, * so you may get a clobbered write. @@ -195,6 +198,7 @@ static void account(struct lockholder_info *li) if (delta > READ_ONCE(ls->hld_max_time)) { WRITE_ONCE(ls->hld_max_time, delta); WRITE_ONCE(ls->hld_max_id, li->task_id); + WRITE_ONCE(ls->hld_max_lock_ptr, li->lock_ptr); if (!per_thread) bpf_get_current_comm(ls->hld_max_comm, TASK_COMM_LEN); } diff --git a/libbpf-tools/klockstat.c b/libbpf-tools/klockstat.c index 6b5f377f96ea..2029f2817a96 100644 --- a/libbpf-tools/klockstat.c +++ b/libbpf-tools/klockstat.c @@ -114,6 +114,20 @@ static const struct argp_option opts[] = { {}, }; +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; +} + +const char *get_lock_name(struct ksyms *ksyms, unsigned long addr) +{ + const struct ksym *ksym = ksyms__map_addr(ksyms, addr); + + return (ksym && ksym->addr == addr) ? ksym->name : "no-ksym"; +} + static bool parse_one_sort(struct prog_env *env, const char *sort) { const char *field = sort + 4; @@ -400,9 +414,11 @@ static void print_acq_stat(struct ksyms *ksyms, struct stack_stat *ss, printf("%37s\n", symname(ksyms, ss->bt[i], buf, sizeof(buf))); } if (nr_stack_entries > 1 && !env.per_thread) - printf(" Max PID %llu, COMM %s\n", + printf(" Max PID %llu, COMM %s, Lock %s (0x%llx)\n", ss->ls.acq_max_id >> 32, - ss->ls.acq_max_comm); + ss->ls.acq_max_comm, + get_lock_name(ksyms, ss->ls.acq_max_lock_ptr), + ss->ls.acq_max_lock_ptr); } static void print_acq_task(struct stack_stat *ss) @@ -451,9 +467,11 @@ static void print_hld_stat(struct ksyms *ksyms, struct stack_stat *ss, printf("%37s\n", symname(ksyms, ss->bt[i], buf, sizeof(buf))); } if (nr_stack_entries > 1 && !env.per_thread) - printf(" Max PID %llu, COMM %s\n", + printf(" Max PID %llu, COMM %s, Lock %s (0x%llx)\n", ss->ls.hld_max_id >> 32, - ss->ls.hld_max_comm); + ss->ls.hld_max_comm, + get_lock_name(ksyms, ss->ls.hld_max_lock_ptr), + ss->ls.hld_max_lock_ptr); } static void print_hld_task(struct stack_stat *ss) @@ -557,13 +575,6 @@ static int print_stats(struct ksyms *ksyms, int stack_map, int stat_map) return 0; } -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; -} - static volatile bool exiting; static void sig_hand(int signr) diff --git a/libbpf-tools/klockstat.h b/libbpf-tools/klockstat.h index 01c9ad9ad76f..d95e43a6af3b 100644 --- a/libbpf-tools/klockstat.h +++ b/libbpf-tools/klockstat.h @@ -10,11 +10,13 @@ struct lock_stat { __u64 acq_total_time; __u64 acq_max_time; __u64 acq_max_id; + __u64 acq_max_lock_ptr; char acq_max_comm[TASK_COMM_LEN]; __u64 hld_count; __u64 hld_total_time; __u64 hld_max_time; __u64 hld_max_id; + __u64 hld_max_lock_ptr; char hld_max_comm[TASK_COMM_LEN]; };