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