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