Skip to content

Commit

Permalink
libbpf-tools/klockstat: Print human friendly time stats
Browse files Browse the repository at this point in the history
Instead of nsec, it can show the time with unit like below:

  $ sudo klockstat -n 5
  Tracing mutex/sem lock events...  Hit Ctrl-C to end
  ^C

                               Caller  Avg Wait    Count   Max Wait   Total Wait
      iwl_mvm_mac_sta_statistics+0x6b  703.9 us        4     2.5 ms       2.8 ms
                i915_vma_pin_ww+0x6ff    1.0 us     5224     1.8 ms       5.2 ms
                  do_epoll_wait+0x1d5    1.9 us     8569   651.3 us      16.0 ms
           kernfs_dop_revalidate+0x35    1.1 us     1176   540.2 us       1.3 ms
           kernfs_iop_permission+0x2a    1.0 us     1512   528.6 us       1.5 ms

                               Caller  Avg Hold    Count   Max Hold   Total Hold
                     __fdget_pos+0x42   13.4 ms      201    19.7 ms       2.7 s
                        genl_rcv+0x15    1.8 ms        8     6.3 ms      14.3 ms
                nl80211_pre_doit+0xdb    1.9 ms        4     6.2 ms       7.4 ms
           ieee80211_get_station+0x2a    1.8 ms        4     6.2 ms       7.1 ms
        bpf_tracing_prog_attach+0x264    2.9 ms       15     3.8 ms      43.4 ms
  Exiting trace of mutex/sem locks
  • Loading branch information
namhyung authored and yonghong-song committed Jun 9, 2022
1 parent 67b8cfb commit bfccfe6
Showing 1 changed file with 40 additions and 8 deletions.
48 changes: 40 additions & 8 deletions libbpf-tools/klockstat.c
Original file line number Diff line number Diff line change
Expand Up @@ -327,6 +327,32 @@ static char *symname(struct ksyms *ksyms, uint64_t pc, char *buf, size_t n)
return buf;
}

static char *print_time(char *buf, int size, uint64_t nsec)
{
struct {
float base;
char *unit;
} table[] = {
{ 1e9 * 3600, "h " },
{ 1e9 * 60, "m " },
{ 1e9, "s " },
{ 1e6, "ms" },
{ 1e3, "us" },
{ 0, NULL },
};

for (int i = 0; table[i].base; i++) {
if (nsec < table[i].base)
continue;

snprintf(buf, size, "%.1f %s", nsec / table[i].base, table[i].unit);
return buf;
}

snprintf(buf, size, "%u ns", (unsigned)nsec);
return buf;
}

static void print_acq_header(void)
{
printf("\n Caller Avg Wait Count Max Wait Total Wait\n");
Expand All @@ -336,14 +362,17 @@ static void print_acq_stat(struct ksyms *ksyms, struct stack_stat *ss,
int nr_stack_entries)
{
char buf[40];
char avg[40];
char max[40];
char tot[40];
int i;

printf("%37s %9llu %8llu %10llu %12llu\n",
printf("%37s %9s %8llu %10s %12s\n",
symname(ksyms, ss->bt[0], buf, sizeof(buf)),
ss->ls.acq_total_time / ss->ls.acq_count,
print_time(avg, sizeof(avg), ss->ls.acq_total_time / ss->ls.acq_count),
ss->ls.acq_count,
ss->ls.acq_max_time,
ss->ls.acq_total_time);
print_time(max, sizeof(max), ss->ls.acq_max_time),
print_time(tot, sizeof(tot), ss->ls.acq_total_time));
for (i = 1; i < nr_stack_entries; i++) {
if (!ss->bt[i])
break;
Expand All @@ -364,14 +393,17 @@ static void print_hld_stat(struct ksyms *ksyms, struct stack_stat *ss,
int nr_stack_entries)
{
char buf[40];
char avg[40];
char max[40];
char tot[40];
int i;

printf("%37s %9llu %8llu %10llu %12llu\n",
printf("%37s %9s %8llu %10s %12s\n",
symname(ksyms, ss->bt[0], buf, sizeof(buf)),
ss->ls.hld_total_time / ss->ls.hld_count,
print_time(avg, sizeof(avg), ss->ls.hld_total_time / ss->ls.hld_count),
ss->ls.hld_count,
ss->ls.hld_max_time,
ss->ls.hld_total_time);
print_time(max, sizeof(max), ss->ls.hld_max_time),
print_time(tot, sizeof(tot), ss->ls.hld_total_time));
for (i = 1; i < nr_stack_entries; i++) {
if (!ss->bt[i])
break;
Expand Down

0 comments on commit bfccfe6

Please sign in to comment.