libbpf-tools/klockstat: Print human friendly time stats

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

Author: namhyung

libbpf-tools/klockstat.c

@@ -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");
@@ -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;
@@ -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;