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 <math.h> |
17 | #include <poll.h> |
18 | #include <ctype.h> |
19 | #include <linux/capability.h> |
20 | #include <linux/string.h> |
21 | |
22 | #include "debug.h" |
23 | #include <subcmd/pager.h> |
24 | #include <subcmd/parse-options.h> |
25 | #include <api/fs/tracing_path.h> |
26 | #include "evlist.h" |
27 | #include "target.h" |
28 | #include "cpumap.h" |
29 | #include "thread_map.h" |
30 | #include "strfilter.h" |
31 | #include "util/cap.h" |
32 | #include "util/config.h" |
33 | #include "util/ftrace.h" |
34 | #include "util/units.h" |
35 | #include "util/parse-sublevel-options.h" |
36 | |
37 | #define DEFAULT_TRACER "function_graph" |
38 | |
39 | static volatile sig_atomic_t workload_exec_errno; |
40 | static volatile sig_atomic_t done; |
41 | |
42 | static void sig_handler(int sig __maybe_unused) |
43 | { |
44 | done = true; |
45 | } |
46 | |
47 | /* |
48 | * evlist__prepare_workload will send a SIGUSR1 if the fork fails, since |
49 | * we asked by setting its exec_error to the function below, |
50 | * ftrace__workload_exec_failed_signal. |
51 | * |
52 | * XXX We need to handle this more appropriately, emitting an error, etc. |
53 | */ |
54 | static void ftrace__workload_exec_failed_signal(int signo __maybe_unused, |
55 | siginfo_t *info __maybe_unused, |
56 | void *ucontext __maybe_unused) |
57 | { |
58 | workload_exec_errno = info->si_value.sival_int; |
59 | done = true; |
60 | } |
61 | |
62 | static int __write_tracing_file(const char *name, const char *val, bool append) |
63 | { |
64 | char *file; |
65 | int fd, ret = -1; |
66 | ssize_t size = strlen(val); |
67 | int flags = O_WRONLY; |
68 | char errbuf[512]; |
69 | char *val_copy; |
70 | |
71 | file = get_tracing_file(name); |
72 | if (!file) { |
73 | pr_debug("cannot get tracing file: %s\n" , name); |
74 | return -1; |
75 | } |
76 | |
77 | if (append) |
78 | flags |= O_APPEND; |
79 | else |
80 | flags |= O_TRUNC; |
81 | |
82 | fd = open(file, flags); |
83 | if (fd < 0) { |
84 | pr_debug("cannot open tracing file: %s: %s\n" , |
85 | name, str_error_r(errno, errbuf, sizeof(errbuf))); |
86 | goto out; |
87 | } |
88 | |
89 | /* |
90 | * Copy the original value and append a '\n'. Without this, |
91 | * the kernel can hide possible errors. |
92 | */ |
93 | val_copy = strdup(val); |
94 | if (!val_copy) |
95 | goto out_close; |
96 | val_copy[size] = '\n'; |
97 | |
98 | if (write(fd, val_copy, size + 1) == size + 1) |
99 | ret = 0; |
100 | else |
101 | pr_debug("write '%s' to tracing/%s failed: %s\n" , |
102 | val, name, str_error_r(errno, errbuf, sizeof(errbuf))); |
103 | |
104 | free(val_copy); |
105 | out_close: |
106 | close(fd); |
107 | out: |
108 | put_tracing_file(file); |
109 | return ret; |
110 | } |
111 | |
112 | static int write_tracing_file(const char *name, const char *val) |
113 | { |
114 | return __write_tracing_file(name, val, append: false); |
115 | } |
116 | |
117 | static int append_tracing_file(const char *name, const char *val) |
118 | { |
119 | return __write_tracing_file(name, val, append: true); |
120 | } |
121 | |
122 | static int read_tracing_file_to_stdout(const char *name) |
123 | { |
124 | char buf[4096]; |
125 | char *file; |
126 | int fd; |
127 | int ret = -1; |
128 | |
129 | file = get_tracing_file(name); |
130 | if (!file) { |
131 | pr_debug("cannot get tracing file: %s\n" , name); |
132 | return -1; |
133 | } |
134 | |
135 | fd = open(file, O_RDONLY); |
136 | if (fd < 0) { |
137 | pr_debug("cannot open tracing file: %s: %s\n" , |
138 | name, str_error_r(errno, buf, sizeof(buf))); |
139 | goto out; |
140 | } |
141 | |
142 | /* read contents to stdout */ |
143 | while (true) { |
144 | int n = read(fd, buf, sizeof(buf)); |
145 | if (n == 0) |
146 | break; |
147 | else if (n < 0) |
148 | goto out_close; |
149 | |
150 | if (fwrite(buf, n, 1, stdout) != 1) |
151 | goto out_close; |
152 | } |
153 | ret = 0; |
154 | |
155 | out_close: |
156 | close(fd); |
157 | out: |
158 | put_tracing_file(file); |
159 | return ret; |
160 | } |
161 | |
162 | static int read_tracing_file_by_line(const char *name, |
163 | void (*cb)(char *str, void *arg), |
164 | void *cb_arg) |
165 | { |
166 | char *line = NULL; |
167 | size_t len = 0; |
168 | char *file; |
169 | FILE *fp; |
170 | |
171 | file = get_tracing_file(name); |
172 | if (!file) { |
173 | pr_debug("cannot get tracing file: %s\n" , name); |
174 | return -1; |
175 | } |
176 | |
177 | fp = fopen(file, "r" ); |
178 | if (fp == NULL) { |
179 | pr_debug("cannot open tracing file: %s\n" , name); |
180 | put_tracing_file(file); |
181 | return -1; |
182 | } |
183 | |
184 | while (getline(&line, &len, fp) != -1) { |
185 | cb(line, cb_arg); |
186 | } |
187 | |
188 | if (line) |
189 | free(line); |
190 | |
191 | fclose(fp); |
192 | put_tracing_file(file); |
193 | return 0; |
194 | } |
195 | |
196 | static int write_tracing_file_int(const char *name, int value) |
197 | { |
198 | char buf[16]; |
199 | |
200 | snprintf(buf, sizeof(buf), "%d" , value); |
201 | if (write_tracing_file(name, val: buf) < 0) |
202 | return -1; |
203 | |
204 | return 0; |
205 | } |
206 | |
207 | static int write_tracing_option_file(const char *name, const char *val) |
208 | { |
209 | char *file; |
210 | int ret; |
211 | |
212 | if (asprintf(&file, "options/%s" , name) < 0) |
213 | return -1; |
214 | |
215 | ret = __write_tracing_file(name: file, val, append: false); |
216 | free(file); |
217 | return ret; |
218 | } |
219 | |
220 | static int reset_tracing_cpu(void); |
221 | static void reset_tracing_filters(void); |
222 | |
223 | static void reset_tracing_options(struct perf_ftrace *ftrace __maybe_unused) |
224 | { |
225 | write_tracing_option_file(name: "function-fork" , val: "0" ); |
226 | write_tracing_option_file(name: "func_stack_trace" , val: "0" ); |
227 | write_tracing_option_file(name: "sleep-time" , val: "1" ); |
228 | write_tracing_option_file(name: "funcgraph-irqs" , val: "1" ); |
229 | write_tracing_option_file(name: "funcgraph-proc" , val: "0" ); |
230 | write_tracing_option_file(name: "funcgraph-abstime" , val: "0" ); |
231 | write_tracing_option_file(name: "latency-format" , val: "0" ); |
232 | write_tracing_option_file(name: "irq-info" , val: "0" ); |
233 | } |
234 | |
235 | static int reset_tracing_files(struct perf_ftrace *ftrace __maybe_unused) |
236 | { |
237 | if (write_tracing_file(name: "tracing_on" , val: "0" ) < 0) |
238 | return -1; |
239 | |
240 | if (write_tracing_file(name: "current_tracer" , val: "nop" ) < 0) |
241 | return -1; |
242 | |
243 | if (write_tracing_file(name: "set_ftrace_pid" , val: " " ) < 0) |
244 | return -1; |
245 | |
246 | if (reset_tracing_cpu() < 0) |
247 | return -1; |
248 | |
249 | if (write_tracing_file(name: "max_graph_depth" , val: "0" ) < 0) |
250 | return -1; |
251 | |
252 | if (write_tracing_file(name: "tracing_thresh" , val: "0" ) < 0) |
253 | return -1; |
254 | |
255 | reset_tracing_filters(); |
256 | reset_tracing_options(ftrace); |
257 | return 0; |
258 | } |
259 | |
260 | static int set_tracing_pid(struct perf_ftrace *ftrace) |
261 | { |
262 | int i; |
263 | char buf[16]; |
264 | |
265 | if (target__has_cpu(target: &ftrace->target)) |
266 | return 0; |
267 | |
268 | for (i = 0; i < perf_thread_map__nr(ftrace->evlist->core.threads); i++) { |
269 | scnprintf(buf, sizeof(buf), "%d" , |
270 | perf_thread_map__pid(ftrace->evlist->core.threads, i)); |
271 | if (append_tracing_file(name: "set_ftrace_pid" , val: buf) < 0) |
272 | return -1; |
273 | } |
274 | return 0; |
275 | } |
276 | |
277 | static int set_tracing_cpumask(struct perf_cpu_map *cpumap) |
278 | { |
279 | char *cpumask; |
280 | size_t mask_size; |
281 | int ret; |
282 | int last_cpu; |
283 | |
284 | last_cpu = perf_cpu_map__cpu(cpumap, perf_cpu_map__nr(cpumap) - 1).cpu; |
285 | mask_size = last_cpu / 4 + 2; /* one more byte for EOS */ |
286 | mask_size += last_cpu / 32; /* ',' is needed for every 32th cpus */ |
287 | |
288 | cpumask = malloc(mask_size); |
289 | if (cpumask == NULL) { |
290 | pr_debug("failed to allocate cpu mask\n" ); |
291 | return -1; |
292 | } |
293 | |
294 | cpu_map__snprint_mask(cpumap, cpumask, mask_size); |
295 | |
296 | ret = write_tracing_file(name: "tracing_cpumask" , val: cpumask); |
297 | |
298 | free(cpumask); |
299 | return ret; |
300 | } |
301 | |
302 | static int set_tracing_cpu(struct perf_ftrace *ftrace) |
303 | { |
304 | struct perf_cpu_map *cpumap = ftrace->evlist->core.user_requested_cpus; |
305 | |
306 | if (!target__has_cpu(target: &ftrace->target)) |
307 | return 0; |
308 | |
309 | return set_tracing_cpumask(cpumap); |
310 | } |
311 | |
312 | static int set_tracing_func_stack_trace(struct perf_ftrace *ftrace) |
313 | { |
314 | if (!ftrace->func_stack_trace) |
315 | return 0; |
316 | |
317 | if (write_tracing_option_file(name: "func_stack_trace" , val: "1" ) < 0) |
318 | return -1; |
319 | |
320 | return 0; |
321 | } |
322 | |
323 | static int set_tracing_func_irqinfo(struct perf_ftrace *ftrace) |
324 | { |
325 | if (!ftrace->func_irq_info) |
326 | return 0; |
327 | |
328 | if (write_tracing_option_file(name: "irq-info" , val: "1" ) < 0) |
329 | return -1; |
330 | |
331 | return 0; |
332 | } |
333 | |
334 | static int reset_tracing_cpu(void) |
335 | { |
336 | struct perf_cpu_map *cpumap = perf_cpu_map__new_online_cpus(); |
337 | int ret; |
338 | |
339 | ret = set_tracing_cpumask(cpumap); |
340 | perf_cpu_map__put(cpumap); |
341 | return ret; |
342 | } |
343 | |
344 | static int __set_tracing_filter(const char *filter_file, struct list_head *funcs) |
345 | { |
346 | struct filter_entry *pos; |
347 | |
348 | list_for_each_entry(pos, funcs, list) { |
349 | if (append_tracing_file(name: filter_file, val: pos->name) < 0) |
350 | return -1; |
351 | } |
352 | |
353 | return 0; |
354 | } |
355 | |
356 | static int set_tracing_filters(struct perf_ftrace *ftrace) |
357 | { |
358 | int ret; |
359 | |
360 | ret = __set_tracing_filter(filter_file: "set_ftrace_filter" , funcs: &ftrace->filters); |
361 | if (ret < 0) |
362 | return ret; |
363 | |
364 | ret = __set_tracing_filter("set_ftrace_notrace" , &ftrace->notrace); |
365 | if (ret < 0) |
366 | return ret; |
367 | |
368 | ret = __set_tracing_filter(filter_file: "set_graph_function" , funcs: &ftrace->graph_funcs); |
369 | if (ret < 0) |
370 | return ret; |
371 | |
372 | /* old kernels do not have this filter */ |
373 | __set_tracing_filter(filter_file: "set_graph_notrace" , funcs: &ftrace->nograph_funcs); |
374 | |
375 | return ret; |
376 | } |
377 | |
378 | static void reset_tracing_filters(void) |
379 | { |
380 | write_tracing_file(name: "set_ftrace_filter" , val: " " ); |
381 | write_tracing_file(name: "set_ftrace_notrace" , val: " " ); |
382 | write_tracing_file(name: "set_graph_function" , val: " " ); |
383 | write_tracing_file(name: "set_graph_notrace" , val: " " ); |
384 | } |
385 | |
386 | static int set_tracing_depth(struct perf_ftrace *ftrace) |
387 | { |
388 | if (ftrace->graph_depth == 0) |
389 | return 0; |
390 | |
391 | if (ftrace->graph_depth < 0) { |
392 | pr_err("invalid graph depth: %d\n" , ftrace->graph_depth); |
393 | return -1; |
394 | } |
395 | |
396 | if (write_tracing_file_int(name: "max_graph_depth" , value: ftrace->graph_depth) < 0) |
397 | return -1; |
398 | |
399 | return 0; |
400 | } |
401 | |
402 | static int set_tracing_percpu_buffer_size(struct perf_ftrace *ftrace) |
403 | { |
404 | int ret; |
405 | |
406 | if (ftrace->percpu_buffer_size == 0) |
407 | return 0; |
408 | |
409 | ret = write_tracing_file_int(name: "buffer_size_kb" , |
410 | value: ftrace->percpu_buffer_size / 1024); |
411 | if (ret < 0) |
412 | return ret; |
413 | |
414 | return 0; |
415 | } |
416 | |
417 | static int set_tracing_trace_inherit(struct perf_ftrace *ftrace) |
418 | { |
419 | if (!ftrace->inherit) |
420 | return 0; |
421 | |
422 | if (write_tracing_option_file(name: "function-fork" , val: "1" ) < 0) |
423 | return -1; |
424 | |
425 | return 0; |
426 | } |
427 | |
428 | static int set_tracing_sleep_time(struct perf_ftrace *ftrace) |
429 | { |
430 | if (!ftrace->graph_nosleep_time) |
431 | return 0; |
432 | |
433 | if (write_tracing_option_file(name: "sleep-time" , val: "0" ) < 0) |
434 | return -1; |
435 | |
436 | return 0; |
437 | } |
438 | |
439 | static int set_tracing_funcgraph_irqs(struct perf_ftrace *ftrace) |
440 | { |
441 | if (!ftrace->graph_noirqs) |
442 | return 0; |
443 | |
444 | if (write_tracing_option_file(name: "funcgraph-irqs" , val: "0" ) < 0) |
445 | return -1; |
446 | |
447 | return 0; |
448 | } |
449 | |
450 | static int set_tracing_funcgraph_verbose(struct perf_ftrace *ftrace) |
451 | { |
452 | if (!ftrace->graph_verbose) |
453 | return 0; |
454 | |
455 | if (write_tracing_option_file(name: "funcgraph-proc" , val: "1" ) < 0) |
456 | return -1; |
457 | |
458 | if (write_tracing_option_file(name: "funcgraph-abstime" , val: "1" ) < 0) |
459 | return -1; |
460 | |
461 | if (write_tracing_option_file(name: "latency-format" , val: "1" ) < 0) |
462 | return -1; |
463 | |
464 | return 0; |
465 | } |
466 | |
467 | static int set_tracing_thresh(struct perf_ftrace *ftrace) |
468 | { |
469 | int ret; |
470 | |
471 | if (ftrace->graph_thresh == 0) |
472 | return 0; |
473 | |
474 | ret = write_tracing_file_int(name: "tracing_thresh" , value: ftrace->graph_thresh); |
475 | if (ret < 0) |
476 | return ret; |
477 | |
478 | return 0; |
479 | } |
480 | |
481 | static int set_tracing_options(struct perf_ftrace *ftrace) |
482 | { |
483 | if (set_tracing_pid(ftrace) < 0) { |
484 | pr_err("failed to set ftrace pid\n" ); |
485 | return -1; |
486 | } |
487 | |
488 | if (set_tracing_cpu(ftrace) < 0) { |
489 | pr_err("failed to set tracing cpumask\n" ); |
490 | return -1; |
491 | } |
492 | |
493 | if (set_tracing_func_stack_trace(ftrace) < 0) { |
494 | pr_err("failed to set tracing option func_stack_trace\n" ); |
495 | return -1; |
496 | } |
497 | |
498 | if (set_tracing_func_irqinfo(ftrace) < 0) { |
499 | pr_err("failed to set tracing option irq-info\n" ); |
500 | return -1; |
501 | } |
502 | |
503 | if (set_tracing_filters(ftrace) < 0) { |
504 | pr_err("failed to set tracing filters\n" ); |
505 | return -1; |
506 | } |
507 | |
508 | if (set_tracing_depth(ftrace) < 0) { |
509 | pr_err("failed to set graph depth\n" ); |
510 | return -1; |
511 | } |
512 | |
513 | if (set_tracing_percpu_buffer_size(ftrace) < 0) { |
514 | pr_err("failed to set tracing per-cpu buffer size\n" ); |
515 | return -1; |
516 | } |
517 | |
518 | if (set_tracing_trace_inherit(ftrace) < 0) { |
519 | pr_err("failed to set tracing option function-fork\n" ); |
520 | return -1; |
521 | } |
522 | |
523 | if (set_tracing_sleep_time(ftrace) < 0) { |
524 | pr_err("failed to set tracing option sleep-time\n" ); |
525 | return -1; |
526 | } |
527 | |
528 | if (set_tracing_funcgraph_irqs(ftrace) < 0) { |
529 | pr_err("failed to set tracing option funcgraph-irqs\n" ); |
530 | return -1; |
531 | } |
532 | |
533 | if (set_tracing_funcgraph_verbose(ftrace) < 0) { |
534 | pr_err("failed to set tracing option funcgraph-proc/funcgraph-abstime\n" ); |
535 | return -1; |
536 | } |
537 | |
538 | if (set_tracing_thresh(ftrace) < 0) { |
539 | pr_err("failed to set tracing thresh\n" ); |
540 | return -1; |
541 | } |
542 | |
543 | return 0; |
544 | } |
545 | |
546 | static void select_tracer(struct perf_ftrace *ftrace) |
547 | { |
548 | bool graph = !list_empty(head: &ftrace->graph_funcs) || |
549 | !list_empty(head: &ftrace->nograph_funcs); |
550 | bool func = !list_empty(&ftrace->filters) || |
551 | !list_empty(&ftrace->notrace); |
552 | |
553 | /* The function_graph has priority over function tracer. */ |
554 | if (graph) |
555 | ftrace->tracer = "function_graph" ; |
556 | else if (func) |
557 | ftrace->tracer = "function" ; |
558 | /* Otherwise, the default tracer is used. */ |
559 | |
560 | pr_debug("%s tracer is used\n" , ftrace->tracer); |
561 | } |
562 | |
563 | static int __cmd_ftrace(struct perf_ftrace *ftrace) |
564 | { |
565 | char *trace_file; |
566 | int trace_fd; |
567 | char buf[4096]; |
568 | struct pollfd pollfd = { |
569 | .events = POLLIN, |
570 | }; |
571 | |
572 | if (!(perf_cap__capable(CAP_PERFMON) || |
573 | perf_cap__capable(CAP_SYS_ADMIN))) { |
574 | pr_err("ftrace only works for %s!\n" , |
575 | #ifdef HAVE_LIBCAP_SUPPORT |
576 | "users with the CAP_PERFMON or CAP_SYS_ADMIN capability" |
577 | #else |
578 | "root" |
579 | #endif |
580 | ); |
581 | return -1; |
582 | } |
583 | |
584 | select_tracer(ftrace); |
585 | |
586 | if (reset_tracing_files(ftrace) < 0) { |
587 | pr_err("failed to reset ftrace\n" ); |
588 | goto out; |
589 | } |
590 | |
591 | /* reset ftrace buffer */ |
592 | if (write_tracing_file(name: "trace" , val: "0" ) < 0) |
593 | goto out; |
594 | |
595 | if (set_tracing_options(ftrace) < 0) |
596 | goto out_reset; |
597 | |
598 | if (write_tracing_file(name: "current_tracer" , val: ftrace->tracer) < 0) { |
599 | pr_err("failed to set current_tracer to %s\n" , ftrace->tracer); |
600 | goto out_reset; |
601 | } |
602 | |
603 | setup_pager(); |
604 | |
605 | trace_file = get_tracing_file("trace_pipe" ); |
606 | if (!trace_file) { |
607 | pr_err("failed to open trace_pipe\n" ); |
608 | goto out_reset; |
609 | } |
610 | |
611 | trace_fd = open(trace_file, O_RDONLY); |
612 | |
613 | put_tracing_file(trace_file); |
614 | |
615 | if (trace_fd < 0) { |
616 | pr_err("failed to open trace_pipe\n" ); |
617 | goto out_reset; |
618 | } |
619 | |
620 | fcntl(trace_fd, F_SETFL, O_NONBLOCK); |
621 | pollfd.fd = trace_fd; |
622 | |
623 | /* display column headers */ |
624 | read_tracing_file_to_stdout(name: "trace" ); |
625 | |
626 | if (!ftrace->target.initial_delay) { |
627 | if (write_tracing_file(name: "tracing_on" , val: "1" ) < 0) { |
628 | pr_err("can't enable tracing\n" ); |
629 | goto out_close_fd; |
630 | } |
631 | } |
632 | |
633 | evlist__start_workload(ftrace->evlist); |
634 | |
635 | if (ftrace->target.initial_delay > 0) { |
636 | usleep(ftrace->target.initial_delay * 1000); |
637 | if (write_tracing_file(name: "tracing_on" , val: "1" ) < 0) { |
638 | pr_err("can't enable tracing\n" ); |
639 | goto out_close_fd; |
640 | } |
641 | } |
642 | |
643 | while (!done) { |
644 | if (poll(&pollfd, 1, -1) < 0) |
645 | break; |
646 | |
647 | if (pollfd.revents & POLLIN) { |
648 | int n = read(trace_fd, buf, sizeof(buf)); |
649 | if (n < 0) |
650 | break; |
651 | if (fwrite(buf, n, 1, stdout) != 1) |
652 | break; |
653 | /* flush output since stdout is in full buffering mode due to pager */ |
654 | fflush(stdout); |
655 | } |
656 | } |
657 | |
658 | write_tracing_file(name: "tracing_on" , val: "0" ); |
659 | |
660 | if (workload_exec_errno) { |
661 | const char *emsg = str_error_r(workload_exec_errno, buf, sizeof(buf)); |
662 | /* flush stdout first so below error msg appears at the end. */ |
663 | fflush(stdout); |
664 | pr_err("workload failed: %s\n" , emsg); |
665 | goto out_close_fd; |
666 | } |
667 | |
668 | /* read remaining buffer contents */ |
669 | while (true) { |
670 | int n = read(trace_fd, buf, sizeof(buf)); |
671 | if (n <= 0) |
672 | break; |
673 | if (fwrite(buf, n, 1, stdout) != 1) |
674 | break; |
675 | } |
676 | |
677 | out_close_fd: |
678 | close(trace_fd); |
679 | out_reset: |
680 | reset_tracing_files(ftrace); |
681 | out: |
682 | return (done && !workload_exec_errno) ? 0 : -1; |
683 | } |
684 | |
685 | static void make_histogram(int buckets[], char *buf, size_t len, char *linebuf, |
686 | bool use_nsec) |
687 | { |
688 | char *p, *q; |
689 | char *unit; |
690 | double num; |
691 | int i; |
692 | |
693 | /* ensure NUL termination */ |
694 | buf[len] = '\0'; |
695 | |
696 | /* handle data line by line */ |
697 | for (p = buf; (q = strchr(p, '\n')) != NULL; p = q + 1) { |
698 | *q = '\0'; |
699 | /* move it to the line buffer */ |
700 | strcat(p: linebuf, q: p); |
701 | |
702 | /* |
703 | * parse trace output to get function duration like in |
704 | * |
705 | * # tracer: function_graph |
706 | * # |
707 | * # CPU DURATION FUNCTION CALLS |
708 | * # | | | | | | | |
709 | * 1) + 10.291 us | do_filp_open(); |
710 | * 1) 4.889 us | do_filp_open(); |
711 | * 1) 6.086 us | do_filp_open(); |
712 | * |
713 | */ |
714 | if (linebuf[0] == '#') |
715 | goto next; |
716 | |
717 | /* ignore CPU */ |
718 | p = strchr(linebuf, ')'); |
719 | if (p == NULL) |
720 | p = linebuf; |
721 | |
722 | while (*p && !isdigit(*p) && (*p != '|')) |
723 | p++; |
724 | |
725 | /* no duration */ |
726 | if (*p == '\0' || *p == '|') |
727 | goto next; |
728 | |
729 | num = strtod(p, &unit); |
730 | if (!unit || strncmp(unit, " us" , 3)) |
731 | goto next; |
732 | |
733 | if (use_nsec) |
734 | num *= 1000; |
735 | |
736 | i = log2(num); |
737 | if (i < 0) |
738 | i = 0; |
739 | if (i >= NUM_BUCKET) |
740 | i = NUM_BUCKET - 1; |
741 | |
742 | buckets[i]++; |
743 | |
744 | next: |
745 | /* empty the line buffer for the next output */ |
746 | linebuf[0] = '\0'; |
747 | } |
748 | |
749 | /* preserve any remaining output (before newline) */ |
750 | strcat(p: linebuf, q: p); |
751 | } |
752 | |
753 | static void display_histogram(int buckets[], bool use_nsec) |
754 | { |
755 | int i; |
756 | int total = 0; |
757 | int bar_total = 46; /* to fit in 80 column */ |
758 | char bar[] = "###############################################" ; |
759 | int bar_len; |
760 | |
761 | for (i = 0; i < NUM_BUCKET; i++) |
762 | total += buckets[i]; |
763 | |
764 | if (total == 0) { |
765 | printf("No data found\n" ); |
766 | return; |
767 | } |
768 | |
769 | printf("# %14s | %10s | %-*s |\n" , |
770 | " DURATION " , "COUNT" , bar_total, "GRAPH" ); |
771 | |
772 | bar_len = buckets[0] * bar_total / total; |
773 | printf(" %4d - %-4d %s | %10d | %.*s%*s |\n" , |
774 | 0, 1, "us" , buckets[0], bar_len, bar, bar_total - bar_len, "" ); |
775 | |
776 | for (i = 1; i < NUM_BUCKET - 1; i++) { |
777 | int start = (1 << (i - 1)); |
778 | int stop = 1 << i; |
779 | const char *unit = use_nsec ? "ns" : "us" ; |
780 | |
781 | if (start >= 1024) { |
782 | start >>= 10; |
783 | stop >>= 10; |
784 | unit = use_nsec ? "us" : "ms" ; |
785 | } |
786 | bar_len = buckets[i] * bar_total / total; |
787 | printf(" %4d - %-4d %s | %10d | %.*s%*s |\n" , |
788 | start, stop, unit, buckets[i], bar_len, bar, |
789 | bar_total - bar_len, "" ); |
790 | } |
791 | |
792 | bar_len = buckets[NUM_BUCKET - 1] * bar_total / total; |
793 | printf(" %4d - %-4s %s | %10d | %.*s%*s |\n" , |
794 | 1, "..." , use_nsec ? "ms" : " s" , buckets[NUM_BUCKET - 1], |
795 | bar_len, bar, bar_total - bar_len, "" ); |
796 | |
797 | } |
798 | |
799 | static int prepare_func_latency(struct perf_ftrace *ftrace) |
800 | { |
801 | char *trace_file; |
802 | int fd; |
803 | |
804 | if (ftrace->target.use_bpf) |
805 | return perf_ftrace__latency_prepare_bpf(ftrace); |
806 | |
807 | if (reset_tracing_files(ftrace) < 0) { |
808 | pr_err("failed to reset ftrace\n" ); |
809 | return -1; |
810 | } |
811 | |
812 | /* reset ftrace buffer */ |
813 | if (write_tracing_file(name: "trace" , val: "0" ) < 0) |
814 | return -1; |
815 | |
816 | if (set_tracing_options(ftrace) < 0) |
817 | return -1; |
818 | |
819 | /* force to use the function_graph tracer to track duration */ |
820 | if (write_tracing_file(name: "current_tracer" , val: "function_graph" ) < 0) { |
821 | pr_err("failed to set current_tracer to function_graph\n" ); |
822 | return -1; |
823 | } |
824 | |
825 | trace_file = get_tracing_file("trace_pipe" ); |
826 | if (!trace_file) { |
827 | pr_err("failed to open trace_pipe\n" ); |
828 | return -1; |
829 | } |
830 | |
831 | fd = open(trace_file, O_RDONLY); |
832 | if (fd < 0) |
833 | pr_err("failed to open trace_pipe\n" ); |
834 | |
835 | put_tracing_file(trace_file); |
836 | return fd; |
837 | } |
838 | |
839 | static int start_func_latency(struct perf_ftrace *ftrace) |
840 | { |
841 | if (ftrace->target.use_bpf) |
842 | return perf_ftrace__latency_start_bpf(ftrace); |
843 | |
844 | if (write_tracing_file(name: "tracing_on" , val: "1" ) < 0) { |
845 | pr_err("can't enable tracing\n" ); |
846 | return -1; |
847 | } |
848 | |
849 | return 0; |
850 | } |
851 | |
852 | static int stop_func_latency(struct perf_ftrace *ftrace) |
853 | { |
854 | if (ftrace->target.use_bpf) |
855 | return perf_ftrace__latency_stop_bpf(ftrace); |
856 | |
857 | write_tracing_file(name: "tracing_on" , val: "0" ); |
858 | return 0; |
859 | } |
860 | |
861 | static int read_func_latency(struct perf_ftrace *ftrace, int buckets[]) |
862 | { |
863 | if (ftrace->target.use_bpf) |
864 | return perf_ftrace__latency_read_bpf(ftrace, buckets); |
865 | |
866 | return 0; |
867 | } |
868 | |
869 | static int cleanup_func_latency(struct perf_ftrace *ftrace) |
870 | { |
871 | if (ftrace->target.use_bpf) |
872 | return perf_ftrace__latency_cleanup_bpf(ftrace); |
873 | |
874 | reset_tracing_files(ftrace); |
875 | return 0; |
876 | } |
877 | |
878 | static int __cmd_latency(struct perf_ftrace *ftrace) |
879 | { |
880 | int trace_fd; |
881 | char buf[4096]; |
882 | char line[256]; |
883 | struct pollfd pollfd = { |
884 | .events = POLLIN, |
885 | }; |
886 | int buckets[NUM_BUCKET] = { }; |
887 | |
888 | if (!(perf_cap__capable(CAP_PERFMON) || |
889 | perf_cap__capable(CAP_SYS_ADMIN))) { |
890 | pr_err("ftrace only works for %s!\n" , |
891 | #ifdef HAVE_LIBCAP_SUPPORT |
892 | "users with the CAP_PERFMON or CAP_SYS_ADMIN capability" |
893 | #else |
894 | "root" |
895 | #endif |
896 | ); |
897 | return -1; |
898 | } |
899 | |
900 | trace_fd = prepare_func_latency(ftrace); |
901 | if (trace_fd < 0) |
902 | goto out; |
903 | |
904 | fcntl(trace_fd, F_SETFL, O_NONBLOCK); |
905 | pollfd.fd = trace_fd; |
906 | |
907 | if (start_func_latency(ftrace) < 0) |
908 | goto out; |
909 | |
910 | evlist__start_workload(ftrace->evlist); |
911 | |
912 | line[0] = '\0'; |
913 | while (!done) { |
914 | if (poll(&pollfd, 1, -1) < 0) |
915 | break; |
916 | |
917 | if (pollfd.revents & POLLIN) { |
918 | int n = read(trace_fd, buf, sizeof(buf) - 1); |
919 | if (n < 0) |
920 | break; |
921 | |
922 | make_histogram(buckets, buf, len: n, linebuf: line, use_nsec: ftrace->use_nsec); |
923 | } |
924 | } |
925 | |
926 | stop_func_latency(ftrace); |
927 | |
928 | if (workload_exec_errno) { |
929 | const char *emsg = str_error_r(workload_exec_errno, buf, sizeof(buf)); |
930 | pr_err("workload failed: %s\n" , emsg); |
931 | goto out; |
932 | } |
933 | |
934 | /* read remaining buffer contents */ |
935 | while (!ftrace->target.use_bpf) { |
936 | int n = read(trace_fd, buf, sizeof(buf) - 1); |
937 | if (n <= 0) |
938 | break; |
939 | make_histogram(buckets, buf, len: n, linebuf: line, use_nsec: ftrace->use_nsec); |
940 | } |
941 | |
942 | read_func_latency(ftrace, buckets); |
943 | |
944 | display_histogram(buckets, use_nsec: ftrace->use_nsec); |
945 | |
946 | out: |
947 | close(trace_fd); |
948 | cleanup_func_latency(ftrace); |
949 | |
950 | return (done && !workload_exec_errno) ? 0 : -1; |
951 | } |
952 | |
953 | static int perf_ftrace_config(const char *var, const char *value, void *cb) |
954 | { |
955 | struct perf_ftrace *ftrace = cb; |
956 | |
957 | if (!strstarts(str: var, prefix: "ftrace." )) |
958 | return 0; |
959 | |
960 | if (strcmp(var, "ftrace.tracer" )) |
961 | return -1; |
962 | |
963 | if (!strcmp(value, "function_graph" ) || |
964 | !strcmp(value, "function" )) { |
965 | ftrace->tracer = value; |
966 | return 0; |
967 | } |
968 | |
969 | pr_err("Please select \"function_graph\" (default) or \"function\"\n" ); |
970 | return -1; |
971 | } |
972 | |
973 | static void list_function_cb(char *str, void *arg) |
974 | { |
975 | struct strfilter *filter = (struct strfilter *)arg; |
976 | |
977 | if (strfilter__compare(filter, str)) |
978 | printf("%s" , str); |
979 | } |
980 | |
981 | static int opt_list_avail_functions(const struct option *opt __maybe_unused, |
982 | const char *str, int unset) |
983 | { |
984 | struct strfilter *filter; |
985 | const char *err = NULL; |
986 | int ret; |
987 | |
988 | if (unset || !str) |
989 | return -1; |
990 | |
991 | filter = strfilter__new(str, &err); |
992 | if (!filter) |
993 | return err ? -EINVAL : -ENOMEM; |
994 | |
995 | ret = strfilter__or(filter, str, &err); |
996 | if (ret == -EINVAL) { |
997 | pr_err("Filter parse error at %td.\n" , err - str + 1); |
998 | pr_err("Source: \"%s\"\n" , str); |
999 | pr_err(" %*c\n" , (int)(err - str + 1), '^'); |
1000 | strfilter__delete(filter); |
1001 | return ret; |
1002 | } |
1003 | |
1004 | ret = read_tracing_file_by_line(name: "available_filter_functions" , |
1005 | cb: list_function_cb, cb_arg: filter); |
1006 | strfilter__delete(filter); |
1007 | if (ret < 0) |
1008 | return ret; |
1009 | |
1010 | exit(0); |
1011 | } |
1012 | |
1013 | static int parse_filter_func(const struct option *opt, const char *str, |
1014 | int unset __maybe_unused) |
1015 | { |
1016 | struct list_head *head = opt->value; |
1017 | struct filter_entry *entry; |
1018 | |
1019 | entry = malloc(sizeof(*entry) + strlen(str) + 1); |
1020 | if (entry == NULL) |
1021 | return -ENOMEM; |
1022 | |
1023 | strcpy(p: entry->name, q: str); |
1024 | list_add_tail(new: &entry->list, head); |
1025 | |
1026 | return 0; |
1027 | } |
1028 | |
1029 | static void delete_filter_func(struct list_head *head) |
1030 | { |
1031 | struct filter_entry *pos, *tmp; |
1032 | |
1033 | list_for_each_entry_safe(pos, tmp, head, list) { |
1034 | list_del_init(entry: &pos->list); |
1035 | free(pos); |
1036 | } |
1037 | } |
1038 | |
1039 | static int parse_buffer_size(const struct option *opt, |
1040 | const char *str, int unset) |
1041 | { |
1042 | unsigned long *s = (unsigned long *)opt->value; |
1043 | static struct parse_tag tags_size[] = { |
1044 | { .tag = 'B', .mult = 1 }, |
1045 | { .tag = 'K', .mult = 1 << 10 }, |
1046 | { .tag = 'M', .mult = 1 << 20 }, |
1047 | { .tag = 'G', .mult = 1 << 30 }, |
1048 | { .tag = 0 }, |
1049 | }; |
1050 | unsigned long val; |
1051 | |
1052 | if (unset) { |
1053 | *s = 0; |
1054 | return 0; |
1055 | } |
1056 | |
1057 | val = parse_tag_value(str, tags: tags_size); |
1058 | if (val != (unsigned long) -1) { |
1059 | if (val < 1024) { |
1060 | pr_err("buffer size too small, must larger than 1KB." ); |
1061 | return -1; |
1062 | } |
1063 | *s = val; |
1064 | return 0; |
1065 | } |
1066 | |
1067 | return -1; |
1068 | } |
1069 | |
1070 | static int parse_func_tracer_opts(const struct option *opt, |
1071 | const char *str, int unset) |
1072 | { |
1073 | int ret; |
1074 | struct perf_ftrace *ftrace = (struct perf_ftrace *) opt->value; |
1075 | struct sublevel_option func_tracer_opts[] = { |
1076 | { .name = "call-graph" , .value_ptr = &ftrace->func_stack_trace }, |
1077 | { .name = "irq-info" , .value_ptr = &ftrace->func_irq_info }, |
1078 | { .name = NULL, } |
1079 | }; |
1080 | |
1081 | if (unset) |
1082 | return 0; |
1083 | |
1084 | ret = perf_parse_sublevel_options(str, opts: func_tracer_opts); |
1085 | if (ret) |
1086 | return ret; |
1087 | |
1088 | return 0; |
1089 | } |
1090 | |
1091 | static int parse_graph_tracer_opts(const struct option *opt, |
1092 | const char *str, int unset) |
1093 | { |
1094 | int ret; |
1095 | struct perf_ftrace *ftrace = (struct perf_ftrace *) opt->value; |
1096 | struct sublevel_option graph_tracer_opts[] = { |
1097 | { .name = "nosleep-time" , .value_ptr = &ftrace->graph_nosleep_time }, |
1098 | { .name = "noirqs" , .value_ptr = &ftrace->graph_noirqs }, |
1099 | { .name = "verbose" , .value_ptr = &ftrace->graph_verbose }, |
1100 | { .name = "thresh" , .value_ptr = &ftrace->graph_thresh }, |
1101 | { .name = "depth" , .value_ptr = &ftrace->graph_depth }, |
1102 | { .name = NULL, } |
1103 | }; |
1104 | |
1105 | if (unset) |
1106 | return 0; |
1107 | |
1108 | ret = perf_parse_sublevel_options(str, opts: graph_tracer_opts); |
1109 | if (ret) |
1110 | return ret; |
1111 | |
1112 | return 0; |
1113 | } |
1114 | |
1115 | enum perf_ftrace_subcommand { |
1116 | PERF_FTRACE_NONE, |
1117 | PERF_FTRACE_TRACE, |
1118 | PERF_FTRACE_LATENCY, |
1119 | }; |
1120 | |
1121 | int cmd_ftrace(int argc, const char **argv) |
1122 | { |
1123 | int ret; |
1124 | int (*cmd_func)(struct perf_ftrace *) = NULL; |
1125 | struct perf_ftrace ftrace = { |
1126 | .tracer = DEFAULT_TRACER, |
1127 | .target = { .uid = UINT_MAX, }, |
1128 | }; |
1129 | const struct option common_options[] = { |
1130 | OPT_STRING('p', "pid" , &ftrace.target.pid, "pid" , |
1131 | "Trace on existing process id" ), |
1132 | /* TODO: Add short option -t after -t/--tracer can be removed. */ |
1133 | OPT_STRING(0, "tid" , &ftrace.target.tid, "tid" , |
1134 | "Trace on existing thread id (exclusive to --pid)" ), |
1135 | OPT_INCR('v', "verbose" , &verbose, |
1136 | "Be more verbose" ), |
1137 | OPT_BOOLEAN('a', "all-cpus" , &ftrace.target.system_wide, |
1138 | "System-wide collection from all CPUs" ), |
1139 | OPT_STRING('C', "cpu" , &ftrace.target.cpu_list, "cpu" , |
1140 | "List of cpus to monitor" ), |
1141 | OPT_END() |
1142 | }; |
1143 | const struct option ftrace_options[] = { |
1144 | OPT_STRING('t', "tracer" , &ftrace.tracer, "tracer" , |
1145 | "Tracer to use: function_graph(default) or function" ), |
1146 | OPT_CALLBACK_DEFAULT('F', "funcs" , NULL, "[FILTER]" , |
1147 | "Show available functions to filter" , |
1148 | opt_list_avail_functions, "*" ), |
1149 | OPT_CALLBACK('T', "trace-funcs" , &ftrace.filters, "func" , |
1150 | "Trace given functions using function tracer" , |
1151 | parse_filter_func), |
1152 | OPT_CALLBACK('N', "notrace-funcs" , &ftrace.notrace, "func" , |
1153 | "Do not trace given functions" , parse_filter_func), |
1154 | OPT_CALLBACK(0, "func-opts" , &ftrace, "options" , |
1155 | "Function tracer options, available options: call-graph,irq-info" , |
1156 | parse_func_tracer_opts), |
1157 | OPT_CALLBACK('G', "graph-funcs" , &ftrace.graph_funcs, "func" , |
1158 | "Trace given functions using function_graph tracer" , |
1159 | parse_filter_func), |
1160 | OPT_CALLBACK('g', "nograph-funcs" , &ftrace.nograph_funcs, "func" , |
1161 | "Set nograph filter on given functions" , parse_filter_func), |
1162 | OPT_CALLBACK(0, "graph-opts" , &ftrace, "options" , |
1163 | "Graph tracer options, available options: nosleep-time,noirqs,verbose,thresh=<n>,depth=<n>" , |
1164 | parse_graph_tracer_opts), |
1165 | OPT_CALLBACK('m', "buffer-size" , &ftrace.percpu_buffer_size, "size" , |
1166 | "Size of per cpu buffer, needs to use a B, K, M or G suffix." , parse_buffer_size), |
1167 | OPT_BOOLEAN(0, "inherit" , &ftrace.inherit, |
1168 | "Trace children processes" ), |
1169 | OPT_INTEGER('D', "delay" , &ftrace.target.initial_delay, |
1170 | "Number of milliseconds to wait before starting tracing after program start" ), |
1171 | OPT_PARENT(common_options), |
1172 | }; |
1173 | const struct option latency_options[] = { |
1174 | OPT_CALLBACK('T', "trace-funcs" , &ftrace.filters, "func" , |
1175 | "Show latency of given function" , parse_filter_func), |
1176 | #ifdef HAVE_BPF_SKEL |
1177 | OPT_BOOLEAN('b', "use-bpf" , &ftrace.target.use_bpf, |
1178 | "Use BPF to measure function latency" ), |
1179 | #endif |
1180 | OPT_BOOLEAN('n', "use-nsec" , &ftrace.use_nsec, |
1181 | "Use nano-second histogram" ), |
1182 | OPT_PARENT(common_options), |
1183 | }; |
1184 | const struct option *options = ftrace_options; |
1185 | |
1186 | const char * const ftrace_usage[] = { |
1187 | "perf ftrace [<options>] [<command>]" , |
1188 | "perf ftrace [<options>] -- [<command>] [<options>]" , |
1189 | "perf ftrace {trace|latency} [<options>] [<command>]" , |
1190 | "perf ftrace {trace|latency} [<options>] -- [<command>] [<options>]" , |
1191 | NULL |
1192 | }; |
1193 | enum perf_ftrace_subcommand subcmd = PERF_FTRACE_NONE; |
1194 | |
1195 | INIT_LIST_HEAD(list: &ftrace.filters); |
1196 | INIT_LIST_HEAD(&ftrace.notrace); |
1197 | INIT_LIST_HEAD(list: &ftrace.graph_funcs); |
1198 | INIT_LIST_HEAD(list: &ftrace.nograph_funcs); |
1199 | |
1200 | signal(SIGINT, sig_handler); |
1201 | signal(SIGUSR1, sig_handler); |
1202 | signal(SIGCHLD, sig_handler); |
1203 | signal(SIGPIPE, sig_handler); |
1204 | |
1205 | ret = perf_config(fn: perf_ftrace_config, &ftrace); |
1206 | if (ret < 0) |
1207 | return -1; |
1208 | |
1209 | if (argc > 1) { |
1210 | if (!strcmp(argv[1], "trace" )) { |
1211 | subcmd = PERF_FTRACE_TRACE; |
1212 | } else if (!strcmp(argv[1], "latency" )) { |
1213 | subcmd = PERF_FTRACE_LATENCY; |
1214 | options = latency_options; |
1215 | } |
1216 | |
1217 | if (subcmd != PERF_FTRACE_NONE) { |
1218 | argc--; |
1219 | argv++; |
1220 | } |
1221 | } |
1222 | /* for backward compatibility */ |
1223 | if (subcmd == PERF_FTRACE_NONE) |
1224 | subcmd = PERF_FTRACE_TRACE; |
1225 | |
1226 | argc = parse_options(argc, argv, options, ftrace_usage, |
1227 | PARSE_OPT_STOP_AT_NON_OPTION); |
1228 | if (argc < 0) { |
1229 | ret = -EINVAL; |
1230 | goto out_delete_filters; |
1231 | } |
1232 | |
1233 | /* Make system wide (-a) the default target. */ |
1234 | if (!argc && target__none(target: &ftrace.target)) |
1235 | ftrace.target.system_wide = true; |
1236 | |
1237 | switch (subcmd) { |
1238 | case PERF_FTRACE_TRACE: |
1239 | cmd_func = __cmd_ftrace; |
1240 | break; |
1241 | case PERF_FTRACE_LATENCY: |
1242 | if (list_empty(head: &ftrace.filters)) { |
1243 | pr_err("Should provide a function to measure\n" ); |
1244 | parse_options_usage(ftrace_usage, options, "T" , 1); |
1245 | ret = -EINVAL; |
1246 | goto out_delete_filters; |
1247 | } |
1248 | cmd_func = __cmd_latency; |
1249 | break; |
1250 | case PERF_FTRACE_NONE: |
1251 | default: |
1252 | pr_err("Invalid subcommand\n" ); |
1253 | ret = -EINVAL; |
1254 | goto out_delete_filters; |
1255 | } |
1256 | |
1257 | ret = target__validate(target: &ftrace.target); |
1258 | if (ret) { |
1259 | char errbuf[512]; |
1260 | |
1261 | target__strerror(target: &ftrace.target, errnum: ret, buf: errbuf, buflen: 512); |
1262 | pr_err("%s\n" , errbuf); |
1263 | goto out_delete_filters; |
1264 | } |
1265 | |
1266 | ftrace.evlist = evlist__new(); |
1267 | if (ftrace.evlist == NULL) { |
1268 | ret = -ENOMEM; |
1269 | goto out_delete_filters; |
1270 | } |
1271 | |
1272 | ret = evlist__create_maps(ftrace.evlist, &ftrace.target); |
1273 | if (ret < 0) |
1274 | goto out_delete_evlist; |
1275 | |
1276 | if (argc) { |
1277 | ret = evlist__prepare_workload(ftrace.evlist, &ftrace.target, |
1278 | argv, false, |
1279 | ftrace__workload_exec_failed_signal); |
1280 | if (ret < 0) |
1281 | goto out_delete_evlist; |
1282 | } |
1283 | |
1284 | ret = cmd_func(&ftrace); |
1285 | |
1286 | out_delete_evlist: |
1287 | evlist__delete(ftrace.evlist); |
1288 | |
1289 | out_delete_filters: |
1290 | delete_filter_func(head: &ftrace.filters); |
1291 | delete_filter_func(&ftrace.notrace); |
1292 | delete_filter_func(head: &ftrace.graph_funcs); |
1293 | delete_filter_func(head: &ftrace.nograph_funcs); |
1294 | |
1295 | return ret; |
1296 | } |
1297 | |