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
sig_handler(int sig __maybe_unused)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 */
ftrace__workload_exec_failed_signal(int signo __maybe_unused,siginfo_t * info __maybe_unused,void * ucontext __maybe_unused)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
check_ftrace_capable(void)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
is_ftrace_supported(void)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 */
get_tracing_instance_file(const char * name)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
__write_tracing_file(const char * name,const char * val,bool append)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
write_tracing_file(const char * name,const char * val)185 static int write_tracing_file(const char *name, const char *val)
186 {
187 return __write_tracing_file(name, val, false);
188 }
189
append_tracing_file(const char * name,const char * val)190 static int append_tracing_file(const char *name, const char *val)
191 {
192 return __write_tracing_file(name, val, true);
193 }
194
read_tracing_file_to_stdout(const char * name)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
read_tracing_file_by_line(const char * name,void (* cb)(char * str,void * arg),void * cb_arg)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
write_tracing_file_int(const char * name,int value)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
write_tracing_option_file(const char * name,const char * val)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
reset_tracing_options(struct perf_ftrace * ftrace __maybe_unused)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
reset_tracing_files(struct perf_ftrace * ftrace __maybe_unused)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 */
exit_tracing_instance(void)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 */
init_tracing_instance(void)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
set_tracing_pid(struct perf_ftrace * ftrace)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
set_tracing_cpumask(struct perf_cpu_map * cpumap)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
set_tracing_cpu(struct perf_ftrace * ftrace)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
set_tracing_func_stack_trace(struct perf_ftrace * ftrace)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
set_tracing_func_irqinfo(struct perf_ftrace * ftrace)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
reset_tracing_cpu(void)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
__set_tracing_filter(const char * filter_file,struct list_head * funcs)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
set_tracing_filters(struct perf_ftrace * ftrace)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
reset_tracing_filters(void)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
set_tracing_depth(struct perf_ftrace * ftrace)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
set_tracing_percpu_buffer_size(struct perf_ftrace * ftrace)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
set_tracing_trace_inherit(struct perf_ftrace * ftrace)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
set_tracing_sleep_time(struct perf_ftrace * ftrace)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
set_tracing_funcgraph_args(struct perf_ftrace * ftrace)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
set_tracing_funcgraph_retval(struct perf_ftrace * ftrace)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
set_tracing_funcgraph_retaddr(struct perf_ftrace * ftrace)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
set_tracing_funcgraph_irqs(struct perf_ftrace * ftrace)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
set_tracing_funcgraph_verbose(struct perf_ftrace * ftrace)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
set_tracing_funcgraph_tail(struct perf_ftrace * ftrace)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
set_tracing_thresh(struct perf_ftrace * ftrace)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
set_tracing_options(struct perf_ftrace * ftrace)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
select_tracer(struct perf_ftrace * ftrace)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
__cmd_ftrace(struct perf_ftrace * ftrace)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
make_histogram(struct perf_ftrace * ftrace,int buckets[],char * buf,size_t len,char * linebuf)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
display_histogram(struct perf_ftrace * ftrace,int buckets[])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
prepare_func_latency(struct perf_ftrace * ftrace)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
start_func_latency(struct perf_ftrace * ftrace)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
stop_func_latency(struct perf_ftrace * ftrace)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
read_func_latency(struct perf_ftrace * ftrace,int buckets[])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
cleanup_func_latency(struct perf_ftrace * ftrace)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
__cmd_latency(struct perf_ftrace * ftrace)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
profile_hash(long func,void * ctx __maybe_unused)1196 static size_t profile_hash(long func, void *ctx __maybe_unused)
1197 {
1198 return str_hash((char *)func);
1199 }
1200
profile_equal(long func1,long func2,void * ctx __maybe_unused)1201 static bool profile_equal(long func1, long func2, void *ctx __maybe_unused)
1202 {
1203 return !strcmp((char *)func1, (char *)func2);
1204 }
1205
prepare_func_profile(struct perf_ftrace * ftrace)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
add_func_duration(struct perf_ftrace * ftrace,char * func,double time_ns)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 */
parse_func_duration(struct perf_ftrace * ftrace,char * line,size_t len)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
cmp_profile_data(const void * a,const void * b)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
print_profile_result(struct perf_ftrace * ftrace)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
__cmd_profile(struct perf_ftrace * ftrace)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
perf_ftrace_config(const char * var,const char * value,void * cb)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
list_function_cb(char * str,void * arg)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
opt_list_avail_functions(const struct option * opt __maybe_unused,const char * str,int unset)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
parse_filter_func(const struct option * opt,const char * str,int unset __maybe_unused)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
delete_filter_func(struct list_head * head)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
parse_filter_event(const struct option * opt,const char * str,int unset __maybe_unused)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
parse_buffer_size(const struct option * opt,const char * str,int unset)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
parse_func_tracer_opts(const struct option * opt,const char * str,int unset)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
parse_graph_tracer_opts(const struct option * opt,const char * str,int unset)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
parse_sort_key(const struct option * opt,const char * str,int unset)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
cmd_ftrace(int argc,const char ** argv)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