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