Skip to content

Commit

Permalink
libbpf-tools/klockstat: print the lock info for max acq/hold times
Browse files Browse the repository at this point in the history
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)
```
  • Loading branch information
bobrik authored and yonghong-song committed Sep 6, 2022
1 parent c110a4d commit 23f16da
Show file tree
Hide file tree
Showing 3 changed files with 28 additions and 11 deletions.
4 changes: 4 additions & 0 deletions libbpf-tools/klockstat.bpf.c
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ struct lockholder_info {
u64 try_at;
u64 acq_at;
u64 rel_at;
u64 lock_ptr;
};

struct {
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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.
Expand All @@ -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);
}
Expand Down
33 changes: 22 additions & 11 deletions libbpf-tools/klockstat.c
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down
2 changes: 2 additions & 0 deletions libbpf-tools/klockstat.h
Original file line number Diff line number Diff line change
Expand Up @@ -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];
};

Expand Down

0 comments on commit 23f16da

Please sign in to comment.