1 // SPDX-License-Identifier: GPL-2.0-only 2 /* 3 * builtin-ftrace.c 4 * 5 * Copyright (c) 2013 LG Electronics, Namhyung Kim <namhyung@kernel.org> 6 * Copyright (c) 2020 Changbin Du <changbin.du@gmail.com>, significant enhancement. 7 */ 8 9 #include "builtin.h" 10 11 #include <errno.h> 12 #include <unistd.h> 13 #include <signal.h> 14 #include <stdlib.h> 15 #include <fcntl.h> 16 #include <inttypes.h> 17 #include <math.h> 18 #include <poll.h> 19 #include <ctype.h> 20 #include <linux/capability.h> 21 #include <linux/err.h> 22 #include <linux/string.h> 23 #include <linux/zalloc.h> 24 #include <sys/stat.h> 25 26 #include "debug.h" 27 #include <subcmd/pager.h> 28 #include <subcmd/parse-options.h> 29 #include <api/io.h> 30 #include <api/fs/tracing_path.h> 31 #include "evlist.h" 32 #include "target.h" 33 #include "cpumap.h" 34 #include "hashmap.h" 35 #include "thread_map.h" 36 #include "strfilter.h" 37 #include "util/cap.h" 38 #include "util/config.h" 39 #include "util/ftrace.h" 40 #include "util/stat.h" 41 #include "util/units.h" 42 #include "util/parse-sublevel-options.h" 43 44 #define DEFAULT_TRACER "function_graph" 45 46 static volatile sig_atomic_t workload_exec_errno; 47 static volatile sig_atomic_t done; 48 49 static struct stats latency_stats; /* for tracepoints */ 50 51 static char tracing_instance[PATH_MAX]; /* Trace instance directory */ 52 53 static void sig_handler(int sig __maybe_unused) 54 { 55 done = true; 56 } 57 58 /* 59 * evlist__prepare_workload will send a SIGUSR1 if the fork fails, since 60 * we asked by setting its exec_error to the function below, 61 * ftrace__workload_exec_failed_signal. 62 * 63 * XXX We need to handle this more appropriately, emitting an error, etc. 64 */ 65 static void ftrace__workload_exec_failed_signal(int signo __maybe_unused, 66 siginfo_t *info __maybe_unused, 67 void *ucontext __maybe_unused) 68 { 69 workload_exec_errno = info->si_value.sival_int; 70 done = true; 71 } 72 73 static bool check_ftrace_capable(void) 74 { 75 bool used_root; 76 77 if (perf_cap__capable(CAP_PERFMON, &used_root)) 78 return true; 79 80 if (!used_root && perf_cap__capable(CAP_SYS_ADMIN, &used_root)) 81 return true; 82 83 pr_err("ftrace only works for %s!\n", 84 used_root ? "root" 85 : "users with the CAP_PERFMON or CAP_SYS_ADMIN capability" 86 ); 87 return false; 88 } 89 90 static bool is_ftrace_supported(void) 91 { 92 char *file; 93 bool supported = false; 94 95 file = get_tracing_file("set_ftrace_pid"); 96 if (!file) { 97 pr_debug("cannot get tracing file set_ftrace_pid\n"); 98 return false; 99 } 100 101 if (!access(file, F_OK)) 102 supported = true; 103 104 put_tracing_file(file); 105 return supported; 106 } 107 108 /* 109 * Wrapper to test if a file in directory .../tracing/instances/XXX 110 * exists. If so return the .../tracing/instances/XXX file for use. 111 * Otherwise the file exists only in directory .../tracing and 112 * is applicable to all instances, for example file available_filter_functions. 113 * Return that file name in this case. 114 * 115 * This functions works similar to get_tracing_file() and expects its caller 116 * to free the returned file name. 117 * 118 * The global variable tracing_instance is set in init_tracing_instance() 119 * called at the beginning to a process specific tracing subdirectory. 120 */ 121 static char *get_tracing_instance_file(const char *name) 122 { 123 char *file; 124 125 if (asprintf(&file, "%s/%s", tracing_instance, name) < 0) 126 return NULL; 127 128 if (!access(file, F_OK)) 129 return file; 130 131 free(file); 132 file = get_tracing_file(name); 133 return file; 134 } 135 136 static int __write_tracing_file(const char *name, const char *val, bool append) 137 { 138 char *file; 139 int fd, ret = -1; 140 ssize_t size = strlen(val); 141 int flags = O_WRONLY; 142 char errbuf[512]; 143 char *val_copy; 144 145 file = get_tracing_instance_file(name); 146 if (!file) { 147 pr_debug("cannot get tracing file: %s\n", name); 148 return -1; 149 } 150 151 if (append) 152 flags |= O_APPEND; 153 else 154 flags |= O_TRUNC; 155 156 fd = open(file, flags); 157 if (fd < 0) { 158 pr_debug("cannot open tracing file: %s: %s\n", 159 name, str_error_r(errno, errbuf, sizeof(errbuf))); 160 goto out; 161 } 162 163 /* 164 * Copy the original value and append a '\n'. Without this, 165 * the kernel can hide possible errors. 166 */ 167 val_copy = strdup(val); 168 if (!val_copy) 169 goto out_close; 170 val_copy[size] = '\n'; 171 172 if (write(fd, val_copy, size + 1) == size + 1) 173 ret = 0; 174 else 175 pr_debug("write '%s' to tracing/%s failed: %s\n", 176 val, name, str_error_r(errno, errbuf, sizeof(errbuf))); 177 178 free(val_copy); 179 out_close: 180 close(fd); 181 out: 182 put_tracing_file(file); 183 return ret; 184 } 185 186 static int write_tracing_file(const char *name, const char *val) 187 { 188 return __write_tracing_file(name, val, false); 189 } 190 191 static int append_tracing_file(const char *name, const char *val) 192 { 193 return __write_tracing_file(name, val, true); 194 } 195 196 static int read_tracing_file_to_stdout(const char *name) 197 { 198 char buf[4096]; 199 char *file; 200 int fd; 201 int ret = -1; 202 203 file = get_tracing_instance_file(name); 204 if (!file) { 205 pr_debug("cannot get tracing file: %s\n", name); 206 return -1; 207 } 208 209 fd = open(file, O_RDONLY); 210 if (fd < 0) { 211 pr_debug("cannot open tracing file: %s: %s\n", 212 name, str_error_r(errno, buf, sizeof(buf))); 213 goto out; 214 } 215 216 /* read contents to stdout */ 217 while (true) { 218 int n = read(fd, buf, sizeof(buf)); 219 if (n == 0) 220 break; 221 else if (n < 0) 222 goto out_close; 223 224 if (fwrite(buf, n, 1, stdout) != 1) 225 goto out_close; 226 } 227 ret = 0; 228 229 out_close: 230 close(fd); 231 out: 232 put_tracing_file(file); 233 return ret; 234 } 235 236 static int read_tracing_file_by_line(const char *name, 237 void (*cb)(char *str, void *arg), 238 void *cb_arg) 239 { 240 char *line = NULL; 241 size_t len = 0; 242 char *file; 243 FILE *fp; 244 245 file = get_tracing_instance_file(name); 246 if (!file) { 247 pr_debug("cannot get tracing file: %s\n", name); 248 return -1; 249 } 250 251 fp = fopen(file, "r"); 252 if (fp == NULL) { 253 pr_debug("cannot open tracing file: %s\n", name); 254 put_tracing_file(file); 255 return -1; 256 } 257 258 while (getline(&line, &len, fp) != -1) { 259 cb(line, cb_arg); 260 } 261 262 if (line) 263 free(line); 264 265 fclose(fp); 266 put_tracing_file(file); 267 return 0; 268 } 269 270 static int write_tracing_file_int(const char *name, int value) 271 { 272 char buf[16]; 273 274 snprintf(buf, sizeof(buf), "%d", value); 275 if (write_tracing_file(name, buf) < 0) 276 return -1; 277 278 return 0; 279 } 280 281 static int write_tracing_option_file(const char *name, const char *val) 282 { 283 char *file; 284 int ret; 285 286 if (asprintf(&file, "options/%s", name) < 0) 287 return -1; 288 289 ret = __write_tracing_file(file, val, false); 290 free(file); 291 return ret; 292 } 293 294 static int reset_tracing_cpu(void); 295 static void reset_tracing_filters(void); 296 297 static void reset_tracing_options(struct perf_ftrace *ftrace __maybe_unused) 298 { 299 write_tracing_option_file("function-fork", "0"); 300 write_tracing_option_file("func_stack_trace", "0"); 301 write_tracing_option_file("sleep-time", "1"); 302 write_tracing_option_file("funcgraph-irqs", "1"); 303 write_tracing_option_file("funcgraph-proc", "0"); 304 write_tracing_option_file("funcgraph-abstime", "0"); 305 write_tracing_option_file("funcgraph-tail", "0"); 306 write_tracing_option_file("funcgraph-args", "0"); 307 write_tracing_option_file("funcgraph-retval", "0"); 308 write_tracing_option_file("funcgraph-retval-hex", "0"); 309 write_tracing_option_file("funcgraph-retaddr", "0"); 310 write_tracing_option_file("latency-format", "0"); 311 write_tracing_option_file("irq-info", "0"); 312 } 313 314 static int reset_tracing_files(struct perf_ftrace *ftrace __maybe_unused) 315 { 316 if (write_tracing_file("tracing_on", "0") < 0) 317 return -1; 318 319 if (write_tracing_file("current_tracer", "nop") < 0) 320 return -1; 321 322 if (write_tracing_file("set_ftrace_pid", " ") < 0) 323 return -1; 324 325 if (reset_tracing_cpu() < 0) 326 return -1; 327 328 if (write_tracing_file("max_graph_depth", "0") < 0) 329 return -1; 330 331 if (write_tracing_file("tracing_thresh", "0") < 0) 332 return -1; 333 334 reset_tracing_filters(); 335 reset_tracing_options(ftrace); 336 return 0; 337 } 338 339 /* Remove .../tracing/instances/XXX subdirectory created with 340 * init_tracing_instance(). 341 */ 342 static void exit_tracing_instance(void) 343 { 344 if (rmdir(tracing_instance)) 345 pr_err("failed to delete tracing/instances directory\n"); 346 } 347 348 /* Create subdirectory within .../tracing/instances/XXX to have session 349 * or process specific setup. To delete this setup, simply remove the 350 * subdirectory. 351 */ 352 static int init_tracing_instance(void) 353 { 354 char dirname[] = "instances/perf-ftrace-XXXXXX"; 355 char *path; 356 357 path = get_tracing_file(dirname); 358 if (!path) 359 goto error; 360 strncpy(tracing_instance, path, sizeof(tracing_instance) - 1); 361 put_tracing_file(path); 362 path = mkdtemp(tracing_instance); 363 if (!path) 364 goto error; 365 return 0; 366 367 error: 368 pr_err("failed to create tracing/instances directory\n"); 369 return -1; 370 } 371 372 static int set_tracing_pid(struct perf_ftrace *ftrace) 373 { 374 int i; 375 char buf[16]; 376 377 if (target__has_cpu(&ftrace->target)) 378 return 0; 379 380 for (i = 0; i < perf_thread_map__nr(ftrace->evlist->core.threads); i++) { 381 scnprintf(buf, sizeof(buf), "%d", 382 perf_thread_map__pid(ftrace->evlist->core.threads, i)); 383 if (append_tracing_file("set_ftrace_pid", buf) < 0) 384 return -1; 385 } 386 return 0; 387 } 388 389 static int set_tracing_cpumask(struct perf_cpu_map *cpumap) 390 { 391 char *cpumask; 392 size_t mask_size; 393 int ret; 394 int last_cpu; 395 396 last_cpu = perf_cpu_map__cpu(cpumap, perf_cpu_map__nr(cpumap) - 1).cpu; 397 mask_size = last_cpu / 4 + 2; /* one more byte for EOS */ 398 mask_size += last_cpu / 32; /* ',' is needed for every 32th cpus */ 399 400 cpumask = malloc(mask_size); 401 if (cpumask == NULL) { 402 pr_debug("failed to allocate cpu mask\n"); 403 return -1; 404 } 405 406 cpu_map__snprint_mask(cpumap, cpumask, mask_size); 407 408 ret = write_tracing_file("tracing_cpumask", cpumask); 409 410 free(cpumask); 411 return ret; 412 } 413 414 static int set_tracing_cpu(struct perf_ftrace *ftrace) 415 { 416 struct perf_cpu_map *cpumap = ftrace->evlist->core.user_requested_cpus; 417 418 if (!target__has_cpu(&ftrace->target)) 419 return 0; 420 421 return set_tracing_cpumask(cpumap); 422 } 423 424 static int set_tracing_func_stack_trace(struct perf_ftrace *ftrace) 425 { 426 if (!ftrace->func_stack_trace) 427 return 0; 428 429 if (write_tracing_option_file("func_stack_trace", "1") < 0) 430 return -1; 431 432 return 0; 433 } 434 435 static int set_tracing_func_irqinfo(struct perf_ftrace *ftrace) 436 { 437 if (!ftrace->func_irq_info) 438 return 0; 439 440 if (write_tracing_option_file("irq-info", "1") < 0) 441 return -1; 442 443 return 0; 444 } 445 446 static int reset_tracing_cpu(void) 447 { 448 struct perf_cpu_map *cpumap = perf_cpu_map__new_online_cpus(); 449 int ret; 450 451 ret = set_tracing_cpumask(cpumap); 452 perf_cpu_map__put(cpumap); 453 return ret; 454 } 455 456 static int __set_tracing_filter(const char *filter_file, struct list_head *funcs) 457 { 458 struct filter_entry *pos; 459 460 list_for_each_entry(pos, funcs, list) { 461 if (append_tracing_file(filter_file, pos->name) < 0) 462 return -1; 463 } 464 465 return 0; 466 } 467 468 static int set_tracing_filters(struct perf_ftrace *ftrace) 469 { 470 int ret; 471 472 ret = __set_tracing_filter("set_ftrace_filter", &ftrace->filters); 473 if (ret < 0) 474 return ret; 475 476 ret = __set_tracing_filter("set_ftrace_notrace", &ftrace->notrace); 477 if (ret < 0) 478 return ret; 479 480 ret = __set_tracing_filter("set_graph_function", &ftrace->graph_funcs); 481 if (ret < 0) 482 return ret; 483 484 /* old kernels do not have this filter */ 485 __set_tracing_filter("set_graph_notrace", &ftrace->nograph_funcs); 486 487 return ret; 488 } 489 490 static void reset_tracing_filters(void) 491 { 492 write_tracing_file("set_ftrace_filter", " "); 493 write_tracing_file("set_ftrace_notrace", " "); 494 write_tracing_file("set_graph_function", " "); 495 write_tracing_file("set_graph_notrace", " "); 496 } 497 498 static int set_tracing_depth(struct perf_ftrace *ftrace) 499 { 500 if (ftrace->graph_depth == 0) 501 return 0; 502 503 if (ftrace->graph_depth < 0) { 504 pr_err("invalid graph depth: %d\n", ftrace->graph_depth); 505 return -1; 506 } 507 508 if (write_tracing_file_int("max_graph_depth", ftrace->graph_depth) < 0) 509 return -1; 510 511 return 0; 512 } 513 514 static int set_tracing_percpu_buffer_size(struct perf_ftrace *ftrace) 515 { 516 int ret; 517 518 if (ftrace->percpu_buffer_size == 0) 519 return 0; 520 521 ret = write_tracing_file_int("buffer_size_kb", 522 ftrace->percpu_buffer_size / 1024); 523 if (ret < 0) 524 return ret; 525 526 return 0; 527 } 528 529 static int set_tracing_trace_inherit(struct perf_ftrace *ftrace) 530 { 531 if (!ftrace->inherit) 532 return 0; 533 534 if (write_tracing_option_file("function-fork", "1") < 0) 535 return -1; 536 537 return 0; 538 } 539 540 static int set_tracing_sleep_time(struct perf_ftrace *ftrace) 541 { 542 if (!ftrace->graph_nosleep_time) 543 return 0; 544 545 if (write_tracing_option_file("sleep-time", "0") < 0) 546 return -1; 547 548 return 0; 549 } 550 551 static int set_tracing_funcgraph_args(struct perf_ftrace *ftrace) 552 { 553 if (ftrace->graph_args) { 554 if (write_tracing_option_file("funcgraph-args", "1") < 0) 555 return -1; 556 } 557 558 return 0; 559 } 560 561 static int set_tracing_funcgraph_retval(struct perf_ftrace *ftrace) 562 { 563 if (ftrace->graph_retval || ftrace->graph_retval_hex) { 564 if (write_tracing_option_file("funcgraph-retval", "1") < 0) 565 return -1; 566 } 567 568 if (ftrace->graph_retval_hex) { 569 if (write_tracing_option_file("funcgraph-retval-hex", "1") < 0) 570 return -1; 571 } 572 573 return 0; 574 } 575 576 static int set_tracing_funcgraph_retaddr(struct perf_ftrace *ftrace) 577 { 578 if (ftrace->graph_retaddr) { 579 if (write_tracing_option_file("funcgraph-retaddr", "1") < 0) 580 return -1; 581 } 582 583 return 0; 584 } 585 586 static int set_tracing_funcgraph_irqs(struct perf_ftrace *ftrace) 587 { 588 if (!ftrace->graph_noirqs) 589 return 0; 590 591 if (write_tracing_option_file("funcgraph-irqs", "0") < 0) 592 return -1; 593 594 return 0; 595 } 596 597 static int set_tracing_funcgraph_verbose(struct perf_ftrace *ftrace) 598 { 599 if (!ftrace->graph_verbose) 600 return 0; 601 602 if (write_tracing_option_file("funcgraph-proc", "1") < 0) 603 return -1; 604 605 if (write_tracing_option_file("funcgraph-abstime", "1") < 0) 606 return -1; 607 608 if (write_tracing_option_file("latency-format", "1") < 0) 609 return -1; 610 611 return 0; 612 } 613 614 static int set_tracing_funcgraph_tail(struct perf_ftrace *ftrace) 615 { 616 if (!ftrace->graph_tail) 617 return 0; 618 619 if (write_tracing_option_file("funcgraph-tail", "1") < 0) 620 return -1; 621 622 return 0; 623 } 624 625 static int set_tracing_thresh(struct perf_ftrace *ftrace) 626 { 627 int ret; 628 629 if (ftrace->graph_thresh == 0) 630 return 0; 631 632 ret = write_tracing_file_int("tracing_thresh", ftrace->graph_thresh); 633 if (ret < 0) 634 return ret; 635 636 return 0; 637 } 638 639 static int set_tracing_options(struct perf_ftrace *ftrace) 640 { 641 if (set_tracing_pid(ftrace) < 0) { 642 pr_err("failed to set ftrace pid\n"); 643 return -1; 644 } 645 646 if (set_tracing_cpu(ftrace) < 0) { 647 pr_err("failed to set tracing cpumask\n"); 648 return -1; 649 } 650 651 if (set_tracing_func_stack_trace(ftrace) < 0) { 652 pr_err("failed to set tracing option func_stack_trace\n"); 653 return -1; 654 } 655 656 if (set_tracing_func_irqinfo(ftrace) < 0) { 657 pr_err("failed to set tracing option irq-info\n"); 658 return -1; 659 } 660 661 if (set_tracing_filters(ftrace) < 0) { 662 pr_err("failed to set tracing filters\n"); 663 return -1; 664 } 665 666 if (set_tracing_depth(ftrace) < 0) { 667 pr_err("failed to set graph depth\n"); 668 return -1; 669 } 670 671 if (set_tracing_percpu_buffer_size(ftrace) < 0) { 672 pr_err("failed to set tracing per-cpu buffer size\n"); 673 return -1; 674 } 675 676 if (set_tracing_trace_inherit(ftrace) < 0) { 677 pr_err("failed to set tracing option function-fork\n"); 678 return -1; 679 } 680 681 if (set_tracing_sleep_time(ftrace) < 0) { 682 pr_err("failed to set tracing option sleep-time\n"); 683 return -1; 684 } 685 686 if (set_tracing_funcgraph_args(ftrace) < 0) { 687 pr_err("failed to set tracing option funcgraph-args\n"); 688 return -1; 689 } 690 691 if (set_tracing_funcgraph_retval(ftrace) < 0) { 692 pr_err("failed to set tracing option funcgraph-retval\n"); 693 return -1; 694 } 695 696 if (set_tracing_funcgraph_retaddr(ftrace) < 0) { 697 pr_err("failed to set tracing option funcgraph-retaddr\n"); 698 return -1; 699 } 700 701 if (set_tracing_funcgraph_irqs(ftrace) < 0) { 702 pr_err("failed to set tracing option funcgraph-irqs\n"); 703 return -1; 704 } 705 706 if (set_tracing_funcgraph_verbose(ftrace) < 0) { 707 pr_err("failed to set tracing option funcgraph-proc/funcgraph-abstime\n"); 708 return -1; 709 } 710 711 if (set_tracing_thresh(ftrace) < 0) { 712 pr_err("failed to set tracing thresh\n"); 713 return -1; 714 } 715 716 if (set_tracing_funcgraph_tail(ftrace) < 0) { 717 pr_err("failed to set tracing option funcgraph-tail\n"); 718 return -1; 719 } 720 721 return 0; 722 } 723 724 static void select_tracer(struct perf_ftrace *ftrace) 725 { 726 bool graph = !list_empty(&ftrace->graph_funcs) || 727 !list_empty(&ftrace->nograph_funcs); 728 bool func = !list_empty(&ftrace->filters) || 729 !list_empty(&ftrace->notrace); 730 731 /* The function_graph has priority over function tracer. */ 732 if (graph) 733 ftrace->tracer = "function_graph"; 734 else if (func) 735 ftrace->tracer = "function"; 736 /* Otherwise, the default tracer is used. */ 737 738 pr_debug("%s tracer is used\n", ftrace->tracer); 739 } 740 741 static int __cmd_ftrace(struct perf_ftrace *ftrace) 742 { 743 char *trace_file; 744 int trace_fd; 745 char buf[4096]; 746 struct pollfd pollfd = { 747 .events = POLLIN, 748 }; 749 750 select_tracer(ftrace); 751 752 if (init_tracing_instance() < 0) 753 goto out; 754 755 if (reset_tracing_files(ftrace) < 0) { 756 pr_err("failed to reset ftrace\n"); 757 goto out_reset; 758 } 759 760 /* reset ftrace buffer */ 761 if (write_tracing_file("trace", "0") < 0) 762 goto out_reset; 763 764 if (set_tracing_options(ftrace) < 0) 765 goto out_reset; 766 767 if (write_tracing_file("current_tracer", ftrace->tracer) < 0) { 768 pr_err("failed to set current_tracer to %s\n", ftrace->tracer); 769 goto out_reset; 770 } 771 772 setup_pager(); 773 774 trace_file = get_tracing_instance_file("trace_pipe"); 775 if (!trace_file) { 776 pr_err("failed to open trace_pipe\n"); 777 goto out_reset; 778 } 779 780 trace_fd = open(trace_file, O_RDONLY); 781 782 put_tracing_file(trace_file); 783 784 if (trace_fd < 0) { 785 pr_err("failed to open trace_pipe\n"); 786 goto out_reset; 787 } 788 789 fcntl(trace_fd, F_SETFL, O_NONBLOCK); 790 pollfd.fd = trace_fd; 791 792 /* display column headers */ 793 read_tracing_file_to_stdout("trace"); 794 795 if (!ftrace->target.initial_delay) { 796 if (write_tracing_file("tracing_on", "1") < 0) { 797 pr_err("can't enable tracing\n"); 798 goto out_close_fd; 799 } 800 } 801 802 evlist__start_workload(ftrace->evlist); 803 804 if (ftrace->target.initial_delay > 0) { 805 usleep(ftrace->target.initial_delay * 1000); 806 if (write_tracing_file("tracing_on", "1") < 0) { 807 pr_err("can't enable tracing\n"); 808 goto out_close_fd; 809 } 810 } 811 812 while (!done) { 813 if (poll(&pollfd, 1, -1) < 0) 814 break; 815 816 if (pollfd.revents & POLLIN) { 817 int n = read(trace_fd, buf, sizeof(buf)); 818 if (n < 0) 819 break; 820 if (fwrite(buf, n, 1, stdout) != 1) 821 break; 822 /* flush output since stdout is in full buffering mode due to pager */ 823 fflush(stdout); 824 } 825 } 826 827 write_tracing_file("tracing_on", "0"); 828 829 if (workload_exec_errno) { 830 const char *emsg = str_error_r(workload_exec_errno, buf, sizeof(buf)); 831 /* flush stdout first so below error msg appears at the end. */ 832 fflush(stdout); 833 pr_err("workload failed: %s\n", emsg); 834 goto out_close_fd; 835 } 836 837 /* read remaining buffer contents */ 838 while (true) { 839 int n = read(trace_fd, buf, sizeof(buf)); 840 if (n <= 0) 841 break; 842 if (fwrite(buf, n, 1, stdout) != 1) 843 break; 844 } 845 846 out_close_fd: 847 close(trace_fd); 848 out_reset: 849 exit_tracing_instance(); 850 out: 851 return (done && !workload_exec_errno) ? 0 : -1; 852 } 853 854 static void make_histogram(struct perf_ftrace *ftrace, int buckets[], 855 char *buf, size_t len, char *linebuf) 856 { 857 int min_latency = ftrace->min_latency; 858 int max_latency = ftrace->max_latency; 859 unsigned int bucket_num = ftrace->bucket_num; 860 char *p, *q; 861 char *unit; 862 double num; 863 int i; 864 865 /* ensure NUL termination */ 866 buf[len] = '\0'; 867 868 /* handle data line by line */ 869 for (p = buf; (q = strchr(p, '\n')) != NULL; p = q + 1) { 870 *q = '\0'; 871 /* move it to the line buffer */ 872 strcat(linebuf, p); 873 874 /* 875 * parse trace output to get function duration like in 876 * 877 * # tracer: function_graph 878 * # 879 * # CPU DURATION FUNCTION CALLS 880 * # | | | | | | | 881 * 1) + 10.291 us | do_filp_open(); 882 * 1) 4.889 us | do_filp_open(); 883 * 1) 6.086 us | do_filp_open(); 884 * 885 */ 886 if (linebuf[0] == '#') 887 goto next; 888 889 /* ignore CPU */ 890 p = strchr(linebuf, ')'); 891 if (p == NULL) 892 p = linebuf; 893 894 while (*p && !isdigit(*p) && (*p != '|')) 895 p++; 896 897 /* no duration */ 898 if (*p == '\0' || *p == '|') 899 goto next; 900 901 num = strtod(p, &unit); 902 if (!unit || strncmp(unit, " us", 3)) 903 goto next; 904 905 if (ftrace->use_nsec) 906 num *= 1000; 907 908 i = 0; 909 if (num < min_latency) 910 goto do_inc; 911 912 num -= min_latency; 913 914 if (!ftrace->bucket_range) { 915 i = log2(num); 916 if (i < 0) 917 i = 0; 918 } else { 919 // Less than 1 unit (ms or ns), or, in the future, 920 // than the min latency desired. 921 if (num > 0) // 1st entry: [ 1 unit .. bucket_range units ] 922 i = num / ftrace->bucket_range + 1; 923 if (num >= max_latency - min_latency) 924 i = bucket_num -1; 925 } 926 if ((unsigned)i >= bucket_num) 927 i = bucket_num - 1; 928 929 num += min_latency; 930 do_inc: 931 buckets[i]++; 932 update_stats(&latency_stats, num); 933 934 next: 935 /* empty the line buffer for the next output */ 936 linebuf[0] = '\0'; 937 } 938 939 /* preserve any remaining output (before newline) */ 940 strcat(linebuf, p); 941 } 942 943 static void display_histogram(struct perf_ftrace *ftrace, int buckets[]) 944 { 945 int min_latency = ftrace->min_latency; 946 bool use_nsec = ftrace->use_nsec; 947 unsigned int bucket_num = ftrace->bucket_num; 948 unsigned int i; 949 int total = 0; 950 int bar_total = 46; /* to fit in 80 column */ 951 char bar[] = "###############################################"; 952 int bar_len; 953 954 for (i = 0; i < bucket_num; i++) 955 total += buckets[i]; 956 957 if (total == 0) { 958 printf("No data found\n"); 959 return; 960 } 961 962 printf("# %14s | %10s | %-*s |\n", 963 " DURATION ", "COUNT", bar_total, "GRAPH"); 964 965 bar_len = buckets[0] * bar_total / total; 966 967 if (!ftrace->hide_empty || buckets[0]) 968 printf(" %4d - %4d %s | %10d | %.*s%*s |\n", 969 0, min_latency ?: 1, use_nsec ? "ns" : "us", 970 buckets[0], bar_len, bar, bar_total - bar_len, ""); 971 972 for (i = 1; i < bucket_num - 1; i++) { 973 unsigned int start, stop; 974 const char *unit = use_nsec ? "ns" : "us"; 975 976 if (ftrace->hide_empty && !buckets[i]) 977 continue; 978 if (!ftrace->bucket_range) { 979 start = (1 << (i - 1)); 980 stop = 1 << i; 981 982 if (start >= 1024) { 983 start >>= 10; 984 stop >>= 10; 985 unit = use_nsec ? "us" : "ms"; 986 } 987 } else { 988 start = (i - 1) * ftrace->bucket_range + min_latency; 989 stop = i * ftrace->bucket_range + min_latency; 990 991 if (start >= ftrace->max_latency) 992 break; 993 if (stop > ftrace->max_latency) 994 stop = ftrace->max_latency; 995 996 if (start >= 1000) { 997 double dstart = start / 1000.0, 998 dstop = stop / 1000.0; 999 printf(" %4.2f - %-4.2f", dstart, dstop); 1000 unit = use_nsec ? "us" : "ms"; 1001 goto print_bucket_info; 1002 } 1003 } 1004 1005 printf(" %4d - %4d", start, stop); 1006 print_bucket_info: 1007 bar_len = buckets[i] * bar_total / total; 1008 printf(" %s | %10d | %.*s%*s |\n", unit, buckets[i], bar_len, bar, 1009 bar_total - bar_len, ""); 1010 } 1011 1012 bar_len = buckets[bucket_num - 1] * bar_total / total; 1013 if (ftrace->hide_empty && !buckets[bucket_num - 1]) 1014 goto print_stats; 1015 if (!ftrace->bucket_range) { 1016 printf(" %4d - %-4s %s", 1, "...", use_nsec ? "ms" : "s "); 1017 } else { 1018 unsigned int upper_outlier = (bucket_num - 2) * ftrace->bucket_range + min_latency; 1019 if (upper_outlier > ftrace->max_latency) 1020 upper_outlier = ftrace->max_latency; 1021 1022 if (upper_outlier >= 1000) { 1023 double dstart = upper_outlier / 1000.0; 1024 1025 printf(" %4.2f - %-4s %s", dstart, "...", use_nsec ? "us" : "ms"); 1026 } else { 1027 printf(" %4d - %4s %s", upper_outlier, "...", use_nsec ? "ns" : "us"); 1028 } 1029 } 1030 printf(" | %10d | %.*s%*s |\n", buckets[bucket_num - 1], 1031 bar_len, bar, bar_total - bar_len, ""); 1032 1033 print_stats: 1034 printf("\n# statistics (in %s)\n", ftrace->use_nsec ? "nsec" : "usec"); 1035 printf(" total time: %20.0f\n", latency_stats.mean * latency_stats.n); 1036 printf(" avg time: %20.0f\n", latency_stats.mean); 1037 printf(" max time: %20"PRIu64"\n", latency_stats.max); 1038 printf(" min time: %20"PRIu64"\n", latency_stats.min); 1039 printf(" count: %20.0f\n", latency_stats.n); 1040 } 1041 1042 static int prepare_func_latency(struct perf_ftrace *ftrace) 1043 { 1044 char *trace_file; 1045 int fd; 1046 1047 if (ftrace->target.use_bpf) 1048 return perf_ftrace__latency_prepare_bpf(ftrace); 1049 1050 if (init_tracing_instance() < 0) 1051 return -1; 1052 1053 if (reset_tracing_files(ftrace) < 0) { 1054 pr_err("failed to reset ftrace\n"); 1055 return -1; 1056 } 1057 1058 /* reset ftrace buffer */ 1059 if (write_tracing_file("trace", "0") < 0) 1060 return -1; 1061 1062 if (set_tracing_options(ftrace) < 0) 1063 return -1; 1064 1065 /* force to use the function_graph tracer to track duration */ 1066 if (write_tracing_file("current_tracer", "function_graph") < 0) { 1067 pr_err("failed to set current_tracer to function_graph\n"); 1068 return -1; 1069 } 1070 1071 trace_file = get_tracing_instance_file("trace_pipe"); 1072 if (!trace_file) { 1073 pr_err("failed to open trace_pipe\n"); 1074 return -1; 1075 } 1076 1077 fd = open(trace_file, O_RDONLY); 1078 if (fd < 0) 1079 pr_err("failed to open trace_pipe\n"); 1080 1081 init_stats(&latency_stats); 1082 1083 put_tracing_file(trace_file); 1084 return fd; 1085 } 1086 1087 static int start_func_latency(struct perf_ftrace *ftrace) 1088 { 1089 if (ftrace->target.use_bpf) 1090 return perf_ftrace__latency_start_bpf(ftrace); 1091 1092 if (write_tracing_file("tracing_on", "1") < 0) { 1093 pr_err("can't enable tracing\n"); 1094 return -1; 1095 } 1096 1097 return 0; 1098 } 1099 1100 static int stop_func_latency(struct perf_ftrace *ftrace) 1101 { 1102 if (ftrace->target.use_bpf) 1103 return perf_ftrace__latency_stop_bpf(ftrace); 1104 1105 write_tracing_file("tracing_on", "0"); 1106 return 0; 1107 } 1108 1109 static int read_func_latency(struct perf_ftrace *ftrace, int buckets[]) 1110 { 1111 if (ftrace->target.use_bpf) 1112 return perf_ftrace__latency_read_bpf(ftrace, buckets, &latency_stats); 1113 1114 return 0; 1115 } 1116 1117 static int cleanup_func_latency(struct perf_ftrace *ftrace) 1118 { 1119 if (ftrace->target.use_bpf) 1120 return perf_ftrace__latency_cleanup_bpf(ftrace); 1121 1122 exit_tracing_instance(); 1123 return 0; 1124 } 1125 1126 static int __cmd_latency(struct perf_ftrace *ftrace) 1127 { 1128 int trace_fd; 1129 char buf[4096]; 1130 char line[256]; 1131 struct pollfd pollfd = { 1132 .events = POLLIN, 1133 }; 1134 int *buckets; 1135 1136 trace_fd = prepare_func_latency(ftrace); 1137 if (trace_fd < 0) 1138 goto out; 1139 1140 fcntl(trace_fd, F_SETFL, O_NONBLOCK); 1141 pollfd.fd = trace_fd; 1142 1143 if (start_func_latency(ftrace) < 0) 1144 goto out; 1145 1146 evlist__start_workload(ftrace->evlist); 1147 1148 buckets = calloc(ftrace->bucket_num, sizeof(*buckets)); 1149 if (buckets == NULL) { 1150 pr_err("failed to allocate memory for the buckets\n"); 1151 goto out; 1152 } 1153 1154 line[0] = '\0'; 1155 while (!done) { 1156 if (poll(&pollfd, 1, -1) < 0) 1157 break; 1158 1159 if (pollfd.revents & POLLIN) { 1160 int n = read(trace_fd, buf, sizeof(buf) - 1); 1161 if (n < 0) 1162 break; 1163 1164 make_histogram(ftrace, buckets, buf, n, line); 1165 } 1166 } 1167 1168 stop_func_latency(ftrace); 1169 1170 if (workload_exec_errno) { 1171 const char *emsg = str_error_r(workload_exec_errno, buf, sizeof(buf)); 1172 pr_err("workload failed: %s\n", emsg); 1173 goto out_free_buckets; 1174 } 1175 1176 /* read remaining buffer contents */ 1177 while (!ftrace->target.use_bpf) { 1178 int n = read(trace_fd, buf, sizeof(buf) - 1); 1179 if (n <= 0) 1180 break; 1181 make_histogram(ftrace, buckets, buf, n, line); 1182 } 1183 1184 read_func_latency(ftrace, buckets); 1185 1186 display_histogram(ftrace, buckets); 1187 1188 out_free_buckets: 1189 free(buckets); 1190 out: 1191 close(trace_fd); 1192 cleanup_func_latency(ftrace); 1193 1194 return (done && !workload_exec_errno) ? 0 : -1; 1195 } 1196 1197 static size_t profile_hash(long func, void *ctx __maybe_unused) 1198 { 1199 return str_hash((char *)func); 1200 } 1201 1202 static bool profile_equal(long func1, long func2, void *ctx __maybe_unused) 1203 { 1204 return !strcmp((char *)func1, (char *)func2); 1205 } 1206 1207 static int prepare_func_profile(struct perf_ftrace *ftrace) 1208 { 1209 ftrace->tracer = "function_graph"; 1210 ftrace->graph_tail = 1; 1211 ftrace->graph_verbose = 0; 1212 1213 ftrace->profile_hash = hashmap__new(profile_hash, profile_equal, NULL); 1214 if (IS_ERR(ftrace->profile_hash)) { 1215 int err = PTR_ERR(ftrace->profile_hash); 1216 1217 ftrace->profile_hash = NULL; 1218 return err; 1219 } 1220 1221 return 0; 1222 } 1223 1224 /* This is saved in a hashmap keyed by the function name */ 1225 struct ftrace_profile_data { 1226 struct stats st; 1227 }; 1228 1229 static int add_func_duration(struct perf_ftrace *ftrace, char *func, double time_ns) 1230 { 1231 struct ftrace_profile_data *prof = NULL; 1232 1233 if (!hashmap__find(ftrace->profile_hash, func, &prof)) { 1234 char *key = strdup(func); 1235 1236 if (key == NULL) 1237 return -ENOMEM; 1238 1239 prof = zalloc(sizeof(*prof)); 1240 if (prof == NULL) { 1241 free(key); 1242 return -ENOMEM; 1243 } 1244 1245 init_stats(&prof->st); 1246 hashmap__add(ftrace->profile_hash, key, prof); 1247 } 1248 1249 update_stats(&prof->st, time_ns); 1250 return 0; 1251 } 1252 1253 /* 1254 * The ftrace function_graph text output normally looks like below: 1255 * 1256 * CPU DURATION FUNCTION 1257 * 1258 * 0) | syscall_trace_enter.isra.0() { 1259 * 0) | __audit_syscall_entry() { 1260 * 0) | auditd_test_task() { 1261 * 0) 0.271 us | __rcu_read_lock(); 1262 * 0) 0.275 us | __rcu_read_unlock(); 1263 * 0) 1.254 us | } /\* auditd_test_task *\/ 1264 * 0) 0.279 us | ktime_get_coarse_real_ts64(); 1265 * 0) 2.227 us | } /\* __audit_syscall_entry *\/ 1266 * 0) 2.713 us | } /\* syscall_trace_enter.isra.0 *\/ 1267 * 1268 * Parse the line and get the duration and function name. 1269 */ 1270 static int parse_func_duration(struct perf_ftrace *ftrace, char *line, size_t len) 1271 { 1272 char *p; 1273 char *func; 1274 double duration; 1275 1276 /* skip CPU */ 1277 p = strchr(line, ')'); 1278 if (p == NULL) 1279 return 0; 1280 1281 /* get duration */ 1282 p = skip_spaces(p + 1); 1283 1284 /* no duration? */ 1285 if (p == NULL || *p == '|') 1286 return 0; 1287 1288 /* skip markers like '*' or '!' for longer than ms */ 1289 if (!isdigit(*p)) 1290 p++; 1291 1292 duration = strtod(p, &p); 1293 1294 if (strncmp(p, " us", 3)) { 1295 pr_debug("non-usec time found.. ignoring\n"); 1296 return 0; 1297 } 1298 1299 /* 1300 * profile stat keeps the max and min values as integer, 1301 * convert to nsec time so that we can have accurate max. 1302 */ 1303 duration *= 1000; 1304 1305 /* skip to the pipe */ 1306 while (p < line + len && *p != '|') 1307 p++; 1308 1309 if (*p++ != '|') 1310 return -EINVAL; 1311 1312 /* get function name */ 1313 func = skip_spaces(p); 1314 1315 /* skip the closing bracket and the start of comment */ 1316 if (*func == '}') 1317 func += 5; 1318 1319 /* remove semi-colon or end of comment at the end */ 1320 p = line + len - 1; 1321 while (!isalnum(*p) && *p != ']') { 1322 *p = '\0'; 1323 --p; 1324 } 1325 1326 return add_func_duration(ftrace, func, duration); 1327 } 1328 1329 enum perf_ftrace_profile_sort_key { 1330 PFP_SORT_TOTAL = 0, 1331 PFP_SORT_AVG, 1332 PFP_SORT_MAX, 1333 PFP_SORT_COUNT, 1334 PFP_SORT_NAME, 1335 }; 1336 1337 static enum perf_ftrace_profile_sort_key profile_sort = PFP_SORT_TOTAL; 1338 1339 static int cmp_profile_data(const void *a, const void *b) 1340 { 1341 const struct hashmap_entry *e1 = *(const struct hashmap_entry **)a; 1342 const struct hashmap_entry *e2 = *(const struct hashmap_entry **)b; 1343 struct ftrace_profile_data *p1 = e1->pvalue; 1344 struct ftrace_profile_data *p2 = e2->pvalue; 1345 double v1, v2; 1346 1347 switch (profile_sort) { 1348 case PFP_SORT_NAME: 1349 return strcmp(e1->pkey, e2->pkey); 1350 case PFP_SORT_AVG: 1351 v1 = p1->st.mean; 1352 v2 = p2->st.mean; 1353 break; 1354 case PFP_SORT_MAX: 1355 v1 = p1->st.max; 1356 v2 = p2->st.max; 1357 break; 1358 case PFP_SORT_COUNT: 1359 v1 = p1->st.n; 1360 v2 = p2->st.n; 1361 break; 1362 case PFP_SORT_TOTAL: 1363 default: 1364 v1 = p1->st.n * p1->st.mean; 1365 v2 = p2->st.n * p2->st.mean; 1366 break; 1367 } 1368 1369 if (v1 > v2) 1370 return -1; 1371 if (v1 < v2) 1372 return 1; 1373 return 0; 1374 } 1375 1376 static void print_profile_result(struct perf_ftrace *ftrace) 1377 { 1378 struct hashmap_entry *entry, **profile; 1379 size_t i, nr, bkt; 1380 1381 nr = hashmap__size(ftrace->profile_hash); 1382 if (nr == 0) 1383 return; 1384 1385 profile = calloc(nr, sizeof(*profile)); 1386 if (profile == NULL) { 1387 pr_err("failed to allocate memory for the result\n"); 1388 return; 1389 } 1390 1391 i = 0; 1392 hashmap__for_each_entry(ftrace->profile_hash, entry, bkt) 1393 profile[i++] = entry; 1394 1395 assert(i == nr); 1396 1397 //cmp_profile_data(profile[0], profile[1]); 1398 qsort(profile, nr, sizeof(*profile), cmp_profile_data); 1399 1400 printf("# %10s %10s %10s %10s %s\n", 1401 "Total (us)", "Avg (us)", "Max (us)", "Count", "Function"); 1402 1403 for (i = 0; i < nr; i++) { 1404 const char *name = profile[i]->pkey; 1405 struct ftrace_profile_data *p = profile[i]->pvalue; 1406 1407 printf("%12.3f %10.3f %6"PRIu64".%03"PRIu64" %10.0f %s\n", 1408 p->st.n * p->st.mean / 1000, p->st.mean / 1000, 1409 p->st.max / 1000, p->st.max % 1000, p->st.n, name); 1410 } 1411 1412 free(profile); 1413 1414 hashmap__for_each_entry(ftrace->profile_hash, entry, bkt) { 1415 free((char *)entry->pkey); 1416 free(entry->pvalue); 1417 } 1418 1419 hashmap__free(ftrace->profile_hash); 1420 ftrace->profile_hash = NULL; 1421 } 1422 1423 static int __cmd_profile(struct perf_ftrace *ftrace) 1424 { 1425 char *trace_file; 1426 int trace_fd; 1427 char buf[4096]; 1428 struct io io; 1429 char *line = NULL; 1430 size_t line_len = 0; 1431 1432 if (prepare_func_profile(ftrace) < 0) { 1433 pr_err("failed to prepare func profiler\n"); 1434 goto out; 1435 } 1436 1437 if (init_tracing_instance() < 0) 1438 goto out; 1439 1440 if (reset_tracing_files(ftrace) < 0) { 1441 pr_err("failed to reset ftrace\n"); 1442 goto out_reset; 1443 } 1444 1445 /* reset ftrace buffer */ 1446 if (write_tracing_file("trace", "0") < 0) 1447 goto out_reset; 1448 1449 if (set_tracing_options(ftrace) < 0) 1450 goto out_reset; 1451 1452 if (write_tracing_file("current_tracer", ftrace->tracer) < 0) { 1453 pr_err("failed to set current_tracer to %s\n", ftrace->tracer); 1454 goto out_reset; 1455 } 1456 1457 setup_pager(); 1458 1459 trace_file = get_tracing_instance_file("trace_pipe"); 1460 if (!trace_file) { 1461 pr_err("failed to open trace_pipe\n"); 1462 goto out_reset; 1463 } 1464 1465 trace_fd = open(trace_file, O_RDONLY); 1466 1467 put_tracing_file(trace_file); 1468 1469 if (trace_fd < 0) { 1470 pr_err("failed to open trace_pipe\n"); 1471 goto out_reset; 1472 } 1473 1474 fcntl(trace_fd, F_SETFL, O_NONBLOCK); 1475 1476 if (write_tracing_file("tracing_on", "1") < 0) { 1477 pr_err("can't enable tracing\n"); 1478 goto out_close_fd; 1479 } 1480 1481 evlist__start_workload(ftrace->evlist); 1482 1483 io__init(&io, trace_fd, buf, sizeof(buf)); 1484 io.timeout_ms = -1; 1485 1486 while (!done && !io.eof) { 1487 if (io__getline(&io, &line, &line_len) < 0) 1488 break; 1489 1490 if (parse_func_duration(ftrace, line, line_len) < 0) 1491 break; 1492 } 1493 1494 write_tracing_file("tracing_on", "0"); 1495 1496 if (workload_exec_errno) { 1497 const char *emsg = str_error_r(workload_exec_errno, buf, sizeof(buf)); 1498 /* flush stdout first so below error msg appears at the end. */ 1499 fflush(stdout); 1500 pr_err("workload failed: %s\n", emsg); 1501 goto out_free_line; 1502 } 1503 1504 /* read remaining buffer contents */ 1505 io.timeout_ms = 0; 1506 while (!io.eof) { 1507 if (io__getline(&io, &line, &line_len) < 0) 1508 break; 1509 1510 if (parse_func_duration(ftrace, line, line_len) < 0) 1511 break; 1512 } 1513 1514 print_profile_result(ftrace); 1515 1516 out_free_line: 1517 free(line); 1518 out_close_fd: 1519 close(trace_fd); 1520 out_reset: 1521 exit_tracing_instance(); 1522 out: 1523 return (done && !workload_exec_errno) ? 0 : -1; 1524 } 1525 1526 static int perf_ftrace_config(const char *var, const char *value, void *cb) 1527 { 1528 struct perf_ftrace *ftrace = cb; 1529 1530 if (!strstarts(var, "ftrace.")) 1531 return 0; 1532 1533 if (strcmp(var, "ftrace.tracer")) 1534 return -1; 1535 1536 if (!strcmp(value, "function_graph") || 1537 !strcmp(value, "function")) { 1538 ftrace->tracer = value; 1539 return 0; 1540 } 1541 1542 pr_err("Please select \"function_graph\" (default) or \"function\"\n"); 1543 return -1; 1544 } 1545 1546 static void list_function_cb(char *str, void *arg) 1547 { 1548 struct strfilter *filter = (struct strfilter *)arg; 1549 1550 if (strfilter__compare(filter, str)) 1551 printf("%s", str); 1552 } 1553 1554 static int opt_list_avail_functions(const struct option *opt __maybe_unused, 1555 const char *str, int unset) 1556 { 1557 struct strfilter *filter; 1558 const char *err = NULL; 1559 int ret; 1560 1561 if (unset || !str) 1562 return -1; 1563 1564 filter = strfilter__new(str, &err); 1565 if (!filter) 1566 return err ? -EINVAL : -ENOMEM; 1567 1568 ret = strfilter__or(filter, str, &err); 1569 if (ret == -EINVAL) { 1570 pr_err("Filter parse error at %td.\n", err - str + 1); 1571 pr_err("Source: \"%s\"\n", str); 1572 pr_err(" %*c\n", (int)(err - str + 1), '^'); 1573 strfilter__delete(filter); 1574 return ret; 1575 } 1576 1577 ret = read_tracing_file_by_line("available_filter_functions", 1578 list_function_cb, filter); 1579 strfilter__delete(filter); 1580 if (ret < 0) 1581 return ret; 1582 1583 exit(0); 1584 } 1585 1586 static int parse_filter_func(const struct option *opt, const char *str, 1587 int unset __maybe_unused) 1588 { 1589 struct list_head *head = opt->value; 1590 struct filter_entry *entry; 1591 1592 entry = malloc(sizeof(*entry) + strlen(str) + 1); 1593 if (entry == NULL) 1594 return -ENOMEM; 1595 1596 strcpy(entry->name, str); 1597 list_add_tail(&entry->list, head); 1598 1599 return 0; 1600 } 1601 1602 static void delete_filter_func(struct list_head *head) 1603 { 1604 struct filter_entry *pos, *tmp; 1605 1606 list_for_each_entry_safe(pos, tmp, head, list) { 1607 list_del_init(&pos->list); 1608 free(pos); 1609 } 1610 } 1611 1612 static int parse_filter_event(const struct option *opt, const char *str, 1613 int unset __maybe_unused) 1614 { 1615 struct list_head *head = opt->value; 1616 struct filter_entry *entry; 1617 char *s, *p; 1618 int ret = -ENOMEM; 1619 1620 s = strdup(str); 1621 if (s == NULL) 1622 return -ENOMEM; 1623 1624 while ((p = strsep(&s, ",")) != NULL) { 1625 entry = malloc(sizeof(*entry) + strlen(p) + 1); 1626 if (entry == NULL) 1627 goto out; 1628 1629 strcpy(entry->name, p); 1630 list_add_tail(&entry->list, head); 1631 } 1632 ret = 0; 1633 1634 out: 1635 free(s); 1636 return ret; 1637 } 1638 1639 static int parse_buffer_size(const struct option *opt, 1640 const char *str, int unset) 1641 { 1642 unsigned long *s = (unsigned long *)opt->value; 1643 static struct parse_tag tags_size[] = { 1644 { .tag = 'B', .mult = 1 }, 1645 { .tag = 'K', .mult = 1 << 10 }, 1646 { .tag = 'M', .mult = 1 << 20 }, 1647 { .tag = 'G', .mult = 1 << 30 }, 1648 { .tag = 0 }, 1649 }; 1650 unsigned long val; 1651 1652 if (unset) { 1653 *s = 0; 1654 return 0; 1655 } 1656 1657 val = parse_tag_value(str, tags_size); 1658 if (val != (unsigned long) -1) { 1659 if (val < 1024) { 1660 pr_err("buffer size too small, must larger than 1KB."); 1661 return -1; 1662 } 1663 *s = val; 1664 return 0; 1665 } 1666 1667 return -1; 1668 } 1669 1670 static int parse_func_tracer_opts(const struct option *opt, 1671 const char *str, int unset) 1672 { 1673 int ret; 1674 struct perf_ftrace *ftrace = (struct perf_ftrace *) opt->value; 1675 struct sublevel_option func_tracer_opts[] = { 1676 { .name = "call-graph", .value_ptr = &ftrace->func_stack_trace }, 1677 { .name = "irq-info", .value_ptr = &ftrace->func_irq_info }, 1678 { .name = NULL, } 1679 }; 1680 1681 if (unset) 1682 return 0; 1683 1684 ret = perf_parse_sublevel_options(str, func_tracer_opts); 1685 if (ret) 1686 return ret; 1687 1688 return 0; 1689 } 1690 1691 static int parse_graph_tracer_opts(const struct option *opt, 1692 const char *str, int unset) 1693 { 1694 int ret; 1695 struct perf_ftrace *ftrace = (struct perf_ftrace *) opt->value; 1696 struct sublevel_option graph_tracer_opts[] = { 1697 { .name = "args", .value_ptr = &ftrace->graph_args }, 1698 { .name = "retval", .value_ptr = &ftrace->graph_retval }, 1699 { .name = "retval-hex", .value_ptr = &ftrace->graph_retval_hex }, 1700 { .name = "retaddr", .value_ptr = &ftrace->graph_retaddr }, 1701 { .name = "nosleep-time", .value_ptr = &ftrace->graph_nosleep_time }, 1702 { .name = "noirqs", .value_ptr = &ftrace->graph_noirqs }, 1703 { .name = "verbose", .value_ptr = &ftrace->graph_verbose }, 1704 { .name = "thresh", .value_ptr = &ftrace->graph_thresh }, 1705 { .name = "depth", .value_ptr = &ftrace->graph_depth }, 1706 { .name = "tail", .value_ptr = &ftrace->graph_tail }, 1707 { .name = NULL, } 1708 }; 1709 1710 if (unset) 1711 return 0; 1712 1713 ret = perf_parse_sublevel_options(str, graph_tracer_opts); 1714 if (ret) 1715 return ret; 1716 1717 return 0; 1718 } 1719 1720 static int parse_sort_key(const struct option *opt, const char *str, int unset) 1721 { 1722 enum perf_ftrace_profile_sort_key *key = (void *)opt->value; 1723 1724 if (unset) 1725 return 0; 1726 1727 if (!strcmp(str, "total")) 1728 *key = PFP_SORT_TOTAL; 1729 else if (!strcmp(str, "avg")) 1730 *key = PFP_SORT_AVG; 1731 else if (!strcmp(str, "max")) 1732 *key = PFP_SORT_MAX; 1733 else if (!strcmp(str, "count")) 1734 *key = PFP_SORT_COUNT; 1735 else if (!strcmp(str, "name")) 1736 *key = PFP_SORT_NAME; 1737 else { 1738 pr_err("Unknown sort key: %s\n", str); 1739 return -1; 1740 } 1741 return 0; 1742 } 1743 1744 enum perf_ftrace_subcommand { 1745 PERF_FTRACE_NONE, 1746 PERF_FTRACE_TRACE, 1747 PERF_FTRACE_LATENCY, 1748 PERF_FTRACE_PROFILE, 1749 }; 1750 1751 int cmd_ftrace(int argc, const char **argv) 1752 { 1753 int ret; 1754 int (*cmd_func)(struct perf_ftrace *) = NULL; 1755 struct perf_ftrace ftrace = { 1756 .tracer = DEFAULT_TRACER, 1757 }; 1758 const struct option common_options[] = { 1759 OPT_STRING('p', "pid", &ftrace.target.pid, "pid", 1760 "Trace on existing process id"), 1761 /* TODO: Add short option -t after -t/--tracer can be removed. */ 1762 OPT_STRING(0, "tid", &ftrace.target.tid, "tid", 1763 "Trace on existing thread id (exclusive to --pid)"), 1764 OPT_INCR('v', "verbose", &verbose, 1765 "Be more verbose"), 1766 OPT_BOOLEAN('a', "all-cpus", &ftrace.target.system_wide, 1767 "System-wide collection from all CPUs"), 1768 OPT_STRING('C', "cpu", &ftrace.target.cpu_list, "cpu", 1769 "List of cpus to monitor"), 1770 OPT_END() 1771 }; 1772 const struct option ftrace_options[] = { 1773 OPT_STRING('t', "tracer", &ftrace.tracer, "tracer", 1774 "Tracer to use: function_graph(default) or function"), 1775 OPT_CALLBACK_DEFAULT('F', "funcs", NULL, "[FILTER]", 1776 "Show available functions to filter", 1777 opt_list_avail_functions, "*"), 1778 OPT_CALLBACK('T', "trace-funcs", &ftrace.filters, "func", 1779 "Trace given functions using function tracer", 1780 parse_filter_func), 1781 OPT_CALLBACK('N', "notrace-funcs", &ftrace.notrace, "func", 1782 "Do not trace given functions", parse_filter_func), 1783 OPT_CALLBACK(0, "func-opts", &ftrace, "options", 1784 "Function tracer options, available options: call-graph,irq-info", 1785 parse_func_tracer_opts), 1786 OPT_CALLBACK('G', "graph-funcs", &ftrace.graph_funcs, "func", 1787 "Trace given functions using function_graph tracer", 1788 parse_filter_func), 1789 OPT_CALLBACK('g', "nograph-funcs", &ftrace.nograph_funcs, "func", 1790 "Set nograph filter on given functions", parse_filter_func), 1791 OPT_CALLBACK(0, "graph-opts", &ftrace, "options", 1792 "Graph tracer options, available options: args,retval,retval-hex,retaddr,nosleep-time,noirqs,verbose,thresh=<n>,depth=<n>", 1793 parse_graph_tracer_opts), 1794 OPT_CALLBACK('m', "buffer-size", &ftrace.percpu_buffer_size, "size", 1795 "Size of per cpu buffer, needs to use a B, K, M or G suffix.", parse_buffer_size), 1796 OPT_BOOLEAN(0, "inherit", &ftrace.inherit, 1797 "Trace children processes"), 1798 OPT_INTEGER('D', "delay", &ftrace.target.initial_delay, 1799 "Number of milliseconds to wait before starting tracing after program start"), 1800 OPT_PARENT(common_options), 1801 }; 1802 const struct option latency_options[] = { 1803 OPT_CALLBACK('T', "trace-funcs", &ftrace.filters, "func", 1804 "Show latency of given function", parse_filter_func), 1805 OPT_CALLBACK('e', "events", &ftrace.event_pair, "event1,event2", 1806 "Show latency between the two events", parse_filter_event), 1807 #ifdef HAVE_BPF_SKEL 1808 OPT_BOOLEAN('b', "use-bpf", &ftrace.target.use_bpf, 1809 "Use BPF to measure function latency"), 1810 #endif 1811 OPT_BOOLEAN('n', "use-nsec", &ftrace.use_nsec, 1812 "Use nano-second histogram"), 1813 OPT_UINTEGER(0, "bucket-range", &ftrace.bucket_range, 1814 "Bucket range in ms or ns (-n/--use-nsec), default is log2() mode"), 1815 OPT_UINTEGER(0, "min-latency", &ftrace.min_latency, 1816 "Minimum latency (1st bucket). Works only with --bucket-range."), 1817 OPT_UINTEGER(0, "max-latency", &ftrace.max_latency, 1818 "Maximum latency (last bucket). Works only with --bucket-range."), 1819 OPT_BOOLEAN(0, "hide-empty", &ftrace.hide_empty, 1820 "Hide empty buckets in the histogram"), 1821 OPT_PARENT(common_options), 1822 }; 1823 const struct option profile_options[] = { 1824 OPT_CALLBACK('T', "trace-funcs", &ftrace.filters, "func", 1825 "Trace given functions using function tracer", 1826 parse_filter_func), 1827 OPT_CALLBACK('N', "notrace-funcs", &ftrace.notrace, "func", 1828 "Do not trace given functions", parse_filter_func), 1829 OPT_CALLBACK('G', "graph-funcs", &ftrace.graph_funcs, "func", 1830 "Trace given functions using function_graph tracer", 1831 parse_filter_func), 1832 OPT_CALLBACK('g', "nograph-funcs", &ftrace.nograph_funcs, "func", 1833 "Set nograph filter on given functions", parse_filter_func), 1834 OPT_CALLBACK('m', "buffer-size", &ftrace.percpu_buffer_size, "size", 1835 "Size of per cpu buffer, needs to use a B, K, M or G suffix.", parse_buffer_size), 1836 OPT_CALLBACK('s', "sort", &profile_sort, "key", 1837 "Sort result by key: total (default), avg, max, count, name.", 1838 parse_sort_key), 1839 OPT_CALLBACK(0, "graph-opts", &ftrace, "options", 1840 "Graph tracer options, available options: nosleep-time,noirqs,thresh=<n>,depth=<n>", 1841 parse_graph_tracer_opts), 1842 OPT_PARENT(common_options), 1843 }; 1844 const struct option *options = ftrace_options; 1845 1846 const char * const ftrace_usage[] = { 1847 "perf ftrace [<options>] [<command>]", 1848 "perf ftrace [<options>] -- [<command>] [<options>]", 1849 "perf ftrace {trace|latency|profile} [<options>] [<command>]", 1850 "perf ftrace {trace|latency|profile} [<options>] -- [<command>] [<options>]", 1851 NULL 1852 }; 1853 enum perf_ftrace_subcommand subcmd = PERF_FTRACE_NONE; 1854 1855 INIT_LIST_HEAD(&ftrace.filters); 1856 INIT_LIST_HEAD(&ftrace.notrace); 1857 INIT_LIST_HEAD(&ftrace.graph_funcs); 1858 INIT_LIST_HEAD(&ftrace.nograph_funcs); 1859 INIT_LIST_HEAD(&ftrace.event_pair); 1860 1861 signal(SIGINT, sig_handler); 1862 signal(SIGUSR1, sig_handler); 1863 signal(SIGCHLD, sig_handler); 1864 signal(SIGPIPE, sig_handler); 1865 1866 if (!check_ftrace_capable()) 1867 return -1; 1868 1869 if (!is_ftrace_supported()) { 1870 pr_err("ftrace is not supported on this system\n"); 1871 return -ENOTSUP; 1872 } 1873 1874 ret = perf_config(perf_ftrace_config, &ftrace); 1875 if (ret < 0) 1876 return -1; 1877 1878 if (argc > 1) { 1879 if (!strcmp(argv[1], "trace")) { 1880 subcmd = PERF_FTRACE_TRACE; 1881 } else if (!strcmp(argv[1], "latency")) { 1882 subcmd = PERF_FTRACE_LATENCY; 1883 options = latency_options; 1884 } else if (!strcmp(argv[1], "profile")) { 1885 subcmd = PERF_FTRACE_PROFILE; 1886 options = profile_options; 1887 } 1888 1889 if (subcmd != PERF_FTRACE_NONE) { 1890 argc--; 1891 argv++; 1892 } 1893 } 1894 /* for backward compatibility */ 1895 if (subcmd == PERF_FTRACE_NONE) 1896 subcmd = PERF_FTRACE_TRACE; 1897 1898 argc = parse_options(argc, argv, options, ftrace_usage, 1899 PARSE_OPT_STOP_AT_NON_OPTION); 1900 if (argc < 0) { 1901 ret = -EINVAL; 1902 goto out_delete_filters; 1903 } 1904 1905 /* Make system wide (-a) the default target. */ 1906 if (!argc && target__none(&ftrace.target)) 1907 ftrace.target.system_wide = true; 1908 1909 switch (subcmd) { 1910 case PERF_FTRACE_TRACE: 1911 cmd_func = __cmd_ftrace; 1912 break; 1913 case PERF_FTRACE_LATENCY: 1914 if (list_empty(&ftrace.filters) && list_empty(&ftrace.event_pair)) { 1915 pr_err("Should provide a function or events to measure\n"); 1916 parse_options_usage(ftrace_usage, options, "T", 1); 1917 parse_options_usage(NULL, options, "e", 1); 1918 ret = -EINVAL; 1919 goto out_delete_filters; 1920 } 1921 if (!list_empty(&ftrace.filters) && !list_empty(&ftrace.event_pair)) { 1922 pr_err("Please specify either of function or events\n"); 1923 parse_options_usage(ftrace_usage, options, "T", 1); 1924 parse_options_usage(NULL, options, "e", 1); 1925 ret = -EINVAL; 1926 goto out_delete_filters; 1927 } 1928 if (!list_empty(&ftrace.event_pair) && !ftrace.target.use_bpf) { 1929 pr_err("Event processing needs BPF\n"); 1930 parse_options_usage(ftrace_usage, options, "b", 1); 1931 parse_options_usage(NULL, options, "e", 1); 1932 ret = -EINVAL; 1933 goto out_delete_filters; 1934 } 1935 if (!ftrace.bucket_range && ftrace.min_latency) { 1936 pr_err("--min-latency works only with --bucket-range\n"); 1937 parse_options_usage(ftrace_usage, options, 1938 "min-latency", /*short_opt=*/false); 1939 ret = -EINVAL; 1940 goto out_delete_filters; 1941 } 1942 if (ftrace.bucket_range && !ftrace.min_latency) { 1943 /* default min latency should be the bucket range */ 1944 ftrace.min_latency = ftrace.bucket_range; 1945 } 1946 if (!ftrace.bucket_range && ftrace.max_latency) { 1947 pr_err("--max-latency works only with --bucket-range\n"); 1948 parse_options_usage(ftrace_usage, options, 1949 "max-latency", /*short_opt=*/false); 1950 ret = -EINVAL; 1951 goto out_delete_filters; 1952 } 1953 if (ftrace.bucket_range && ftrace.max_latency && 1954 ftrace.max_latency < ftrace.min_latency + ftrace.bucket_range) { 1955 /* we need at least 1 bucket excluding min and max buckets */ 1956 pr_err("--max-latency must be larger than min-latency + bucket-range\n"); 1957 parse_options_usage(ftrace_usage, options, 1958 "max-latency", /*short_opt=*/false); 1959 ret = -EINVAL; 1960 goto out_delete_filters; 1961 } 1962 /* set default unless max_latency is set and valid */ 1963 ftrace.bucket_num = NUM_BUCKET; 1964 if (ftrace.bucket_range) { 1965 if (ftrace.max_latency) 1966 ftrace.bucket_num = (ftrace.max_latency - ftrace.min_latency) / 1967 ftrace.bucket_range + 2; 1968 else 1969 /* default max latency should depend on bucket range and num_buckets */ 1970 ftrace.max_latency = (NUM_BUCKET - 2) * ftrace.bucket_range + 1971 ftrace.min_latency; 1972 } 1973 cmd_func = __cmd_latency; 1974 break; 1975 case PERF_FTRACE_PROFILE: 1976 cmd_func = __cmd_profile; 1977 break; 1978 case PERF_FTRACE_NONE: 1979 default: 1980 pr_err("Invalid subcommand\n"); 1981 ret = -EINVAL; 1982 goto out_delete_filters; 1983 } 1984 1985 ret = target__validate(&ftrace.target); 1986 if (ret) { 1987 char errbuf[512]; 1988 1989 target__strerror(&ftrace.target, ret, errbuf, 512); 1990 pr_err("%s\n", errbuf); 1991 goto out_delete_filters; 1992 } 1993 1994 ftrace.evlist = evlist__new(); 1995 if (ftrace.evlist == NULL) { 1996 ret = -ENOMEM; 1997 goto out_delete_filters; 1998 } 1999 2000 ret = evlist__create_maps(ftrace.evlist, &ftrace.target); 2001 if (ret < 0) 2002 goto out_delete_evlist; 2003 2004 if (argc) { 2005 ret = evlist__prepare_workload(ftrace.evlist, &ftrace.target, 2006 argv, false, 2007 ftrace__workload_exec_failed_signal); 2008 if (ret < 0) 2009 goto out_delete_evlist; 2010 } 2011 2012 ret = cmd_func(&ftrace); 2013 2014 out_delete_evlist: 2015 evlist__delete(ftrace.evlist); 2016 2017 out_delete_filters: 2018 delete_filter_func(&ftrace.filters); 2019 delete_filter_func(&ftrace.notrace); 2020 delete_filter_func(&ftrace.graph_funcs); 2021 delete_filter_func(&ftrace.nograph_funcs); 2022 delete_filter_func(&ftrace.event_pair); 2023 2024 return ret; 2025 } 2026