libbpf-tools/klockstat.c

   1 // SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
   2 /* Copyright (c) 2021 Google LLC.
   3  *
   4  * Based on klockstat from BCC by Jiri Olsa and others
   5  * 2021-10-26   Barret Rhoden   Created this.
   6  */
   7 /* Differences from BCC python tool:
   8  * - can specify a lock by ksym name, using '-L'
   9  * - tracks whichever task had the max time for acquire and hold, outputted
  10  *     when '-s' > 1 (otherwise it's cluttered).
  11  * - does not reset stats each interval by default. Can request with -R.
  12  */
  13 #include <argp.h>
  14 #include <errno.h>
  15 #include <signal.h>
  16 #include <stdio.h>
  17 #ifndef _GNU_SOURCE
  18 #define _GNU_SOURCE
  19 #endif
  20 #include <stdlib.h>
  21 #include <string.h>
  22 #include <time.h>
  23 #include <unistd.h>
  24 #include <sys/param.h>
  25
  26 #include <bpf/libbpf.h>
  27 #include <bpf/bpf.h>
  28 #include "klockstat.h"
  29 #include "klockstat.skel.h"
  30 #include "trace_helpers.h"
  31
  32 #define warn(...) fprintf(stderr, __VA_ARGS__)
  33
  34 enum {
  35         SORT_ACQ_MAX,
  36         SORT_ACQ_COUNT,
  37         SORT_ACQ_TOTAL,
  38         SORT_HLD_MAX,
  39         SORT_HLD_COUNT,
  40         SORT_HLD_TOTAL,
  41 };
  42
  43 static struct prog_env {
  44         pid_t pid;
  45         pid_t tid;
  46         char *caller;
  47         char *lock_name;
  48         unsigned int nr_locks;
  49         unsigned int nr_stack_entries;
  50         unsigned int sort_acq;
  51         unsigned int sort_hld;
  52         unsigned int duration;
  53         unsigned int interval;
  54         unsigned int iterations;
  55         bool reset;
  56         bool timestamp;
  57 } env = {
  58         .nr_locks = 99999999,
  59         .nr_stack_entries = 1,
  60         .sort_acq = SORT_ACQ_MAX,
  61         .sort_hld = SORT_HLD_MAX,
  62         .interval = 99999999,
  63         .iterations = 99999999,
  64 };
  65
  66 const char *argp_program_version = "klockstat 0.1";
  67 const char *argp_program_bug_address =
  68         "https://github.com/iovisor/bcc/tree/master/libbpf-tools";
  69 static const char args_doc[] = "FUNCTION";
  70 static const char program_doc[] =
  71 "Trace mutex lock acquisition and hold times, in nsec\n"
  72 "\n"
  73 "Usage: klockstat [-hRT] [-p PID] [-t TID] [-c FUNC] [-L LOCK] [-n NR_LOCKS]\n"
  74 "                 [-s NR_STACKS] [-S SORT] [-d DURATION] [-i INTERVAL]\n"
  75 "\v"
  76 "Examples:\n"
  77 "  klockstat                     # trace system wide until ctrl-c\n"
  78 "  klockstat -d 5                # trace for 5 seconds\n"
  79 "  klockstat -i 5                # print stats every 5 seconds\n"
  80 "  klockstat -p 181              # trace process 181 only\n"
  81 "  klockstat -t 181              # trace thread 181 only\n"
  82 "  klockstat -c pipe_            # print only for lock callers with 'pipe_'\n"
  83 "                                # prefix\n"
  84 "  klockstat -L cgroup_mutex     # trace the cgroup_mutex lock only\n"
  85 "  klockstat -S acq_count        # sort lock acquired results by acquire count\n"
  86 "  klockstat -S hld_total        # sort lock held results by total held time\n"
  87 "  klockstat -S acq_count,hld_total  # combination of above\n"
  88 "  klockstat -n 3                # display top 3 locks\n"
  89 "  klockstat -s 6                # display 6 stack entries per lock\n"
  90 ;
  91
  92 static const struct argp_option opts[] = {
  93         { "pid", 'p', "PID", 0, "Filter by process ID" },
  94         { "tid", 't', "TID", 0, "Filter by thread ID" },
  95         { 0, 0, 0, 0, "" },
  96         { "caller", 'c', "FUNC", 0, "Filter by caller string prefix" },
  97         { "lock", 'L', "LOCK", 0, "Filter by specific ksym lock name" },
  98         { 0, 0, 0, 0, "" },
  99         { "locks", 'n', "NR_LOCKS", 0, "Number of locks to print" },
 100         { "stacks", 's', "NR_STACKS", 0, "Number of stack entries to print per lock" },
 101         { "sort", 'S', "SORT", 0, "Sort by field:\n  acq_[max|total|count]\n  hld_[max|total|count]" },
 102         { 0, 0, 0, 0, "" },
 103         { "duration", 'd', "SECONDS", 0, "Duration to trace" },
 104         { "interval", 'i', "SECONDS", 0, "Print interval" },
 105         { "reset", 'R', NULL, 0, "Reset stats each interval" },
 106         { "timestamp", 'T', NULL, 0, "Print timestamp" },
 107
 108         { NULL, 'h', NULL, OPTION_HIDDEN, "Show the full help" },
 109         {},
 110 };
 111
 112 static bool parse_one_sort(struct prog_env *env, const char *sort)
 113 {
 114         const char *field = sort + 4;
 115
 116         if (!strncmp(sort, "acq_", 4)) {
 117                 if (!strcmp(field, "max")) {
 118                         env->sort_acq = SORT_ACQ_MAX;
 119                         return true;
 120                 } else if (!strcmp(field, "total")) {
 121                         env->sort_acq = SORT_ACQ_TOTAL;
 122                         return true;
 123                 } else if (!strcmp(field, "count")) {
 124                         env->sort_acq = SORT_ACQ_COUNT;
 125                         return true;
 126                 }
 127         } else if (!strncmp(sort, "hld_", 4)) {
 128                 if (!strcmp(field, "max")) {
 129                         env->sort_hld = SORT_HLD_MAX;
 130                         return true;
 131                 } else if (!strcmp(field, "total")) {
 132                         env->sort_hld = SORT_HLD_TOTAL;
 133                         return true;
 134                 } else if (!strcmp(field, "count")) {
 135                         env->sort_hld = SORT_HLD_COUNT;
 136                         return true;
 137                 }
 138         }
 139
 140         return false;
 141 }
 142
 143 static bool parse_sorts(struct prog_env *env, char *arg)
 144 {
 145         char *comma = strchr(arg, ',');
 146
 147         if (comma) {
 148                 *comma = '\0';
 149                 comma++;
 150                 if (!parse_one_sort(env, comma))
 151                         return false;
 152         }
 153         return parse_one_sort(env, arg);
 154 }
 155
 156 static error_t parse_arg(int key, char *arg, struct argp_state *state)
 157 {
 158         struct prog_env *env = state->input;
 159         long duration, interval;
 160
 161         switch (key) {
 162         case 'p':
 163                 errno = 0;
 164                 env->pid = strtol(arg, NULL, 10);
 165                 if (errno || env->pid <= 0) {
 166                         warn("Invalid PID: %s\n", arg);
 167                         argp_usage(state);
 168                 }
 169                 break;
 170         case 't':
 171                 errno = 0;
 172                 env->tid = strtol(arg, NULL, 10);
 173                 if (errno || env->tid <= 0) {
 174                         warn("Invalid TID: %s\n", arg);
 175                         argp_usage(state);
 176                 }
 177                 break;
 178         case 'c':
 179                 env->caller = arg;
 180                 break;
 181         case 'L':
 182                 env->lock_name = arg;
 183                 break;
 184         case 'n':
 185                 errno = 0;
 186                 env->nr_locks = strtol(arg, NULL, 10);
 187                 if (errno || env->nr_locks <= 0) {
 188                         warn("Invalid NR_LOCKS: %s\n", arg);
 189                         argp_usage(state);
 190                 }
 191                 break;
 192         case 's':
 193                 errno = 0;
 194                 env->nr_stack_entries = strtol(arg, NULL, 10);
 195                 if (errno || env->nr_stack_entries <= 0) {
 196                         warn("Invalid NR_STACKS: %s\n", arg);
 197                         argp_usage(state);
 198                 }
 199                 break;
 200         case 'S':
 201                 if (!parse_sorts(env, arg)) {
 202                         warn("Bad sort string: %s\n", arg);
 203                         argp_usage(state);
 204                 }
 205                 break;
 206         case 'd':
 207                 errno = 0;
 208                 duration = strtol(arg, NULL, 10);
 209                 if (errno || duration <= 0) {
 210                         warn("Invalid duration: %s\n", arg);
 211                         argp_usage(state);
 212                 }
 213                 env->duration = duration;
 214                 break;
 215         case 'i':
 216                 errno = 0;
 217                 interval = strtol(arg, NULL, 10);
 218                 if (errno || interval <= 0) {
 219                         warn("Invalid interval: %s\n", arg);
 220                         argp_usage(state);
 221                 }
 222                 env->interval = interval;
 223                 break;
 224         case 'R':
 225                 env->reset = true;
 226                 break;
 227         case 'T':
 228                 env->timestamp = true;
 229                 break;
 230         case 'h':
 231                 argp_state_help(state, stderr, ARGP_HELP_STD_HELP);
 232                 break;
 233         case ARGP_KEY_END:
 234                 if (env->duration) {
 235                         if (env->interval > env->duration)
 236                                 env->interval = env->duration;
 237                         env->iterations = env->duration / env->interval;
 238                 }
 239                 break;
 240         default:
 241                 return ARGP_ERR_UNKNOWN;
 242         }
 243         return 0;
 244 }
 245
 246 struct stack_stat {
 247         uint32_t stack_id;
 248         struct lock_stat ls;
 249         uint64_t bt[PERF_MAX_STACK_DEPTH];
 250 };
 251
 252 static bool caller_is_traced(struct ksyms *ksyms, uint64_t caller_pc)
 253 {
 254         const struct ksym *ksym;
 255
 256         if (!env.caller)
 257                 return true;
 258         ksym = ksyms__map_addr(ksyms, caller_pc);
 259         if (!ksym)
 260                 return true;
 261         return strncmp(env.caller, ksym->name, strlen(env.caller)) == 0;
 262 }
 263
 264 static int larger_first(uint64_t x, uint64_t y)
 265 {
 266         if (x > y)
 267                 return -1;
 268         if (x == y)
 269                 return 0;
 270         return 1;
 271 }
 272
 273 static int sort_by_acq(const void *x, const void *y)
 274 {
 275         struct stack_stat *ss_x = *(struct stack_stat**)x;
 276         struct stack_stat *ss_y = *(struct stack_stat**)y;
 277
 278         switch (env.sort_acq) {
 279         case SORT_ACQ_MAX:
 280                 return larger_first(ss_x->ls.acq_max_time,
 281                                     ss_y->ls.acq_max_time);
 282         case SORT_ACQ_COUNT:
 283                 return larger_first(ss_x->ls.acq_count,
 284                                     ss_y->ls.acq_count);
 285         case SORT_ACQ_TOTAL:
 286                 return larger_first(ss_x->ls.acq_total_time,
 287                                     ss_y->ls.acq_total_time);
 288         }
 289
 290         warn("bad sort_acq %d\n", env.sort_acq);
 291         return -1;
 292 }
 293
 294 static int sort_by_hld(const void *x, const void *y)
 295 {
 296         struct stack_stat *ss_x = *(struct stack_stat**)x;
 297         struct stack_stat *ss_y = *(struct stack_stat**)y;
 298
 299         switch (env.sort_hld) {
 300         case SORT_HLD_MAX:
 301                 return larger_first(ss_x->ls.hld_max_time,
 302                                     ss_y->ls.hld_max_time);
 303         case SORT_HLD_COUNT:
 304                 return larger_first(ss_x->ls.hld_count,
 305                                     ss_y->ls.hld_count);
 306         case SORT_HLD_TOTAL:
 307                 return larger_first(ss_x->ls.hld_total_time,
 308                                     ss_y->ls.hld_total_time);
 309         }
 310
 311         warn("bad sort_hld %d\n", env.sort_hld);
 312         return -1;
 313 }
 314
 315 static char *symname(struct ksyms *ksyms, uint64_t pc, char *buf, size_t n)
 316 {
 317         const struct ksym *ksym = ksyms__map_addr(ksyms, pc);
 318
 319         if (!ksym)
 320                 return "Unknown";
 321         snprintf(buf, n, "%s+0x%lx", ksym->name, pc - ksym->addr);
 322         return buf;
 323 }
 324
 325 static void print_acq_header(void)
 326 {
 327         printf("\n                               Caller  Avg Spin    Count   Max Spin   Total Spin\n");
 328 }
 329
 330 static void print_acq_stat(struct ksyms *ksyms, struct stack_stat *ss,
 331                            int nr_stack_entries)
 332 {
 333         char buf[40];
 334         int i;
 335
 336         printf("%37s %9llu %8llu %10llu %12llu\n",
 337                symname(ksyms, ss->bt[0], buf, sizeof(buf)),
 338                ss->ls.acq_total_time / ss->ls.acq_count,
 339                ss->ls.acq_count,
 340                ss->ls.acq_max_time,
 341                ss->ls.acq_total_time);
 342         for (i = 1; i < nr_stack_entries; i++) {
 343                 if (!ss->bt[i])
 344                         break;
 345                 printf("%37s\n", symname(ksyms, ss->bt[i], buf, sizeof(buf)));
 346         }
 347         if (nr_stack_entries > 1)
 348                 printf("                              Max PID %llu, COMM %s\n",
 349                        ss->ls.acq_max_id >> 32,
 350                        ss->ls.acq_max_comm);
 351 }
 352
 353 static void print_hld_header(void)
 354 {
 355         printf("\n                               Caller  Avg Hold    Count   Max Hold   Total Hold\n");
 356 }
 357
 358 static void print_hld_stat(struct ksyms *ksyms, struct stack_stat *ss,
 359                            int nr_stack_entries)
 360 {
 361         char buf[40];
 362         int i;
 363
 364         printf("%37s %9llu %8llu %10llu %12llu\n",
 365                symname(ksyms, ss->bt[0], buf, sizeof(buf)),
 366                ss->ls.hld_total_time / ss->ls.hld_count,
 367                ss->ls.hld_count,
 368                ss->ls.hld_max_time,
 369                ss->ls.hld_total_time);
 370         for (i = 1; i < nr_stack_entries; i++) {
 371                 if (!ss->bt[i])
 372                         break;
 373                 printf("%37s\n", symname(ksyms, ss->bt[i], buf, sizeof(buf)));
 374         }
 375         if (nr_stack_entries > 1)
 376                 printf("                              Max PID %llu, COMM %s\n",
 377                        ss->ls.hld_max_id >> 32,
 378                        ss->ls.hld_max_comm);
 379 }
 380
 381 static int print_stats(struct ksyms *ksyms, int stack_map, int stat_map)
 382 {
 383         struct stack_stat **stats, *ss;
 384         size_t stat_idx = 0;
 385         size_t stats_sz = 1;
 386         uint32_t lookup_key = 0;
 387         uint32_t stack_id;
 388         int ret, i;
 389
 390         stats = calloc(stats_sz, sizeof(void *));
 391         if (!stats) {
 392                 warn("Out of memory\n");
 393                 return -1;
 394         }
 395
 396         while (bpf_map_get_next_key(stat_map, &lookup_key, &stack_id) == 0) {
 397                 if (stat_idx == stats_sz) {
 398                         stats_sz *= 2;
 399                         stats = reallocarray(stats, stats_sz, sizeof(void *));
 400                         if (!stats) {
 401                                 warn("Out of memory\n");
 402                                 return -1;
 403                         }
 404                 }
 405                 ss = malloc(sizeof(struct stack_stat));
 406                 if (!ss) {
 407                         warn("Out of memory\n");
 408                         return -1;
 409                 }
 410                 ss->stack_id = stack_id;
 411                 if (env.reset) {
 412                         ret = bpf_map_lookup_and_delete_elem(stat_map,
 413                                                              &stack_id,
 414                                                              &ss->ls);
 415                         lookup_key = 0;
 416                 } else {
 417                         ret = bpf_map_lookup_elem(stat_map, &stack_id, &ss->ls);
 418                         lookup_key = stack_id;
 419                 }
 420                 if (ret) {
 421                         free(ss);
 422                         continue;
 423                 }
 424                 if (bpf_map_lookup_elem(stack_map, &stack_id, &ss->bt)) {
 425                         /* Can still report the results without a backtrace. */
 426                         warn("failed to lookup stack_id %u\n", stack_id);
 427                 }
 428                 if (!caller_is_traced(ksyms, ss->bt[0])) {
 429                         free(ss);
 430                         continue;
 431                 }
 432                 stats[stat_idx++] = ss;
 433         }
 434
 435         qsort(stats, stat_idx, sizeof(void*), sort_by_acq);
 436         for (i = 0; i < MIN(env.nr_locks, stat_idx); i++) {
 437                 if (i == 0 || env.nr_stack_entries > 1)
 438                         print_acq_header();
 439                 print_acq_stat(ksyms, stats[i],
 440                                MIN(env.nr_stack_entries, PERF_MAX_STACK_DEPTH));
 441         }
 442
 443         qsort(stats, stat_idx, sizeof(void*), sort_by_hld);
 444         for (i = 0; i < MIN(env.nr_locks, stat_idx); i++) {
 445                 if (i == 0 || env.nr_stack_entries > 1)
 446                         print_hld_header();
 447                 print_hld_stat(ksyms, stats[i],
 448                                MIN(env.nr_stack_entries, PERF_MAX_STACK_DEPTH));
 449         }
 450
 451         for (i = 0; i < stat_idx; i++)
 452                 free(stats[i]);
 453         free(stats);
 454
 455         return 0;
 456 }
 457
 458 static void *get_lock_addr(struct ksyms *ksyms, const char *lock_name)
 459 {
 460         const struct ksym *ksym = ksyms__get_symbol(ksyms, lock_name);
 461
 462         return ksym ? (void*)ksym->addr : NULL;
 463 }
 464
 465 static volatile bool exiting;
 466
 467 static void sig_hand(int signr)
 468 {
 469         exiting = true;
 470 }
 471
 472 static struct sigaction sigact = {.sa_handler = sig_hand};
 473
 474 int main(int argc, char **argv)
 475 {
 476         static const struct argp argp = {
 477                 .options = opts,
 478                 .parser = parse_arg,
 479                 .args_doc = args_doc,
 480                 .doc = program_doc,
 481         };
 482         struct klockstat_bpf *obj = NULL;
 483         struct ksyms *ksyms = NULL;
 484         int i, err;
 485         struct tm *tm;
 486         char ts[32];
 487         time_t t;
 488         void *lock_addr = NULL;
 489
 490         err = argp_parse(&argp, argc, argv, 0, NULL, &env);
 491         if (err)
 492                 return err;
 493
 494         sigaction(SIGINT, &sigact, 0);
 495
 496         libbpf_set_strict_mode(LIBBPF_STRICT_ALL);
 497
 498         ksyms = ksyms__load();
 499         if (!ksyms) {
 500                 warn("failed to load kallsyms\n");
 501                 err = 1;
 502                 goto cleanup;
 503         }
 504         if (env.lock_name) {
 505                 lock_addr = get_lock_addr(ksyms, env.lock_name);
 506                 if (!lock_addr) {
 507                         warn("failed to find lock %s\n", env.lock_name);
 508                         err = 1;
 509                         goto cleanup;
 510                 }
 511         }
 512
 513         obj = klockstat_bpf__open();
 514         if (!obj) {
 515                 warn("failed to open BPF object\n");
 516                 err = 1;
 517                 goto cleanup;
 518         }
 519
 520         obj->rodata->targ_tgid = env.pid;
 521         obj->rodata->targ_pid = env.tid;
 522         obj->rodata->targ_lock = lock_addr;
 523
 524         err = klockstat_bpf__load(obj);
 525         if (err) {
 526                 warn("failed to load BPF object\n");
 527                 return 1;
 528         }
 529         err = klockstat_bpf__attach(obj);
 530         if (err) {
 531                 warn("failed to attach BPF object\n");
 532                 goto cleanup;
 533         }
 534
 535         printf("Tracing mutex lock events...  Hit Ctrl-C to end\n");
 536
 537         for (i = 0; i < env.iterations && !exiting; i++) {
 538                 sleep(env.interval);
 539
 540                 printf("\n");
 541                 if (env.timestamp) {
 542                         time(&t);
 543                         tm = localtime(&t);
 544                         strftime(ts, sizeof(ts), "%H:%M:%S", tm);
 545                         printf("%-8s\n", ts);
 546                 }
 547
 548                 if (print_stats(ksyms, bpf_map__fd(obj->maps.stack_map),
 549                                 bpf_map__fd(obj->maps.stat_map))) {
 550                         warn("print_stats error, aborting.\n");
 551                         break;
 552                 }
 553         }
 554
 555         printf("Exiting trace of mutex locks\n");
 556
 557 cleanup:
 558         klockstat_bpf__destroy(obj);
 559         ksyms__free(ksyms);
 560
 561         return err != 0;
 562 }