tjh.dev / kernel
Linux kernel mirror (for testing) git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel os linux
fork atom

perf ftrace latency: Add -n/--use-nsec option

Sometimes we want to see nano-second granularity.

$ sudo perf ftrace latency -T dput -a sleep 1
# DURATION | COUNT | GRAPH |
0 - 1 us | 2098375 | ############################# |
1 - 2 us | 61 | |
2 - 4 us | 33 | |
4 - 8 us | 13 | |
8 - 16 us | 124 | |
16 - 32 us | 123 | |
32 - 64 us | 1 | |
64 - 128 us | 0 | |
128 - 256 us | 1 | |
256 - 512 us | 0 | |
512 - 1024 us | 0 | |
1 - 2 ms | 0 | |
2 - 4 ms | 0 | |
4 - 8 ms | 0 | |
8 - 16 ms | 0 | |
16 - 32 ms | 0 | |
32 - 64 ms | 0 | |
64 - 128 ms | 0 | |
128 - 256 ms | 0 | |
256 - 512 ms | 0 | |
512 - 1024 ms | 0 | |
1 - ... s | 0 | |

$ sudo perf ftrace latency -T dput -a -n sleep 1
# DURATION | COUNT | GRAPH |
0 - 1 us | 0 | |
1 - 2 ns | 0 | |
2 - 4 ns | 0 | |
4 - 8 ns | 0 | |
8 - 16 ns | 0 | |
16 - 32 ns | 0 | |
32 - 64 ns | 0 | |
64 - 128 ns | 1163434 | ############## |
128 - 256 ns | 914102 | ############# |
256 - 512 ns | 884 | |
512 - 1024 ns | 613 | |
1 - 2 us | 31 | |
2 - 4 us | 17 | |
4 - 8 us | 7 | |
8 - 16 us | 123 | |
16 - 32 us | 83 | |
32 - 64 us | 0 | |
64 - 128 us | 0 | |
128 - 256 us | 0 | |
256 - 512 us | 0 | |
512 - 1024 us | 0 | |
1 - ... ms | 0 | |

Committer testing:

Testing it with BPF:

# perf ftrace latency -b -n -T dput -a sleep 1
# DURATION | COUNT | GRAPH |
0 - 1 us | 0 | |
1 - 2 ns | 0 | |
2 - 4 ns | 0 | |
4 - 8 ns | 0 | |
8 - 16 ns | 0 | |
16 - 32 ns | 0 | |
32 - 64 ns | 0 | |
64 - 128 ns | 0 | |
128 - 256 ns | 823489 | ############################################# |
256 - 512 ns | 3232 | |
512 - 1024 ns | 51 | |
1 - 2 us | 172 | |
2 - 4 us | 9 | |
4 - 8 us | 0 | |
8 - 16 us | 2 | |
16 - 32 us | 0 | |
32 - 64 us | 0 | |
64 - 128 us | 0 | |
128 - 256 us | 0 | |
256 - 512 us | 0 | |
512 - 1024 us | 0 | |
1 - ... ms | 0 | |
[root@quaco ~]# strace -e bpf perf ftrace latency -b -n -T dput -a sleep 1
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffe2bd574f0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0\20\0\0\0\20\0\0\0\5\0\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=45, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0000\0\0\0000\0\0\0\t\0\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=81, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\08\0\0\08\0\0\0\t\0\0\0\0\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=89, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0\f\0\0\0\f\0\0\0\7\0\0\0\1\0\0\0\0\0\0\20"..., btf_log_buf=NULL, btf_size=43, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0000\0\0\0000\0\0\0\t\0\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=81, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0000\0\0\0000\0\0\0\5\0\0\0\0\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=77, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0(\0\0\0(\0\0\0\5\0\0\0\0\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=69, btf_log_size=0, btf_log_level=0}, 28) = -1 EINVAL (Invalid argument)
bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0<\3\0\0<\3\0\0\362\3\0\0\0\0\0\0\0\0\0\2"..., btf_log_buf=NULL, btf_size=1862, btf_log_size=0, btf_log_level=0}, 28) = 3
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=4, max_entries=1, map_flags=BPF_F_MMAPABLE, inner_map_fd=0, map_name="", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 4
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffe2bd571c0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="test", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 4
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=8, value_size=8, max_entries=10000, map_flags=0, inner_map_fd=0, map_name="functime", map_ifindex=0, btf_fd=3, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 4
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=4, value_size=1, max_entries=1, map_flags=0, inner_map_fd=0, map_name="cpu_filter", map_ifindex=0, btf_fd=3, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 5
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=4, value_size=1, max_entries=1, map_flags=0, inner_map_fd=0, map_name="task_filter", map_ifindex=0, btf_fd=3, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 7
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERCPU_ARRAY, key_size=4, value_size=8, max_entries=22, map_flags=0, inner_map_fd=0, map_name="latency", map_ifindex=0, btf_fd=3, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 8
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=32, max_entries=1, map_flags=0, inner_map_fd=0, map_name="", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 9
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=5, insns=0x7ffe2bd57220, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 10
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=16, max_entries=1, map_flags=BPF_F_MMAPABLE, inner_map_fd=0, map_name="func_lat.bss", map_ifindex=0, btf_fd=3, btf_key_type_id=0, btf_value_type_id=33, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 9
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=9, key=0x7ffe2bd57330, value=0x7f9a5fc39000, flags=BPF_ANY}, 144) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=42, insns=0x113daf0, license="", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 16, 13), prog_flags=0, prog_name="func_begin", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=3, func_info_rec_size=8, func_info=0x113fb70, func_info_cnt=1, line_info_rec_size=16, line_info=0x113fb90, line_info_cnt=21, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 10
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=124, insns=0x113d360, license="", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 16, 13), prog_flags=0, prog_name="func_end", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=3, func_info_rec_size=8, func_info=0x113fcf0, func_info_cnt=1, line_info_rec_size=16, line_info=0x1139770, line_info_cnt=60, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 11
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_TRACEPOINT, insn_cnt=2, insns=0x7ffe2bd57150, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 13
bpf(BPF_LINK_CREATE, {link_create={prog_fd=13, target_fd=-1, attach_type=BPF_PERF_EVENT, flags=0}}, 144) = -1 EBADF (Bad file descriptor)
bpf(BPF_LINK_CREATE, {link_create={prog_fd=10, target_fd=12, attach_type=BPF_PERF_EVENT, flags=0}}, 144) = 13
bpf(BPF_LINK_CREATE, {link_create={prog_fd=11, target_fd=14, attach_type=BPF_PERF_EVENT, flags=0}}, 144) = 15
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=130075, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
bpf(BPF_MAP_LOOKUP_ELEM, {map_fd=8, key=0x7ffe2bd57624, value=0x113fdd0, flags=BPF_ANY}, 144) = 0
# DURATION | COUNT | GRAPH |
0 - 1 us | 0 | |
1 - 2 ns | 0 | |
2 - 4 ns | 0 | |
4 - 8 ns | 0 | |
8 - 16 ns | 0 | |
16 - 32 ns | 0 | |
32 - 64 ns | 0 | |
64 - 128 ns | 0 | |
128 - 256 ns | 42519 | ########################################### |
256 - 512 ns | 2140 | ## |
512 - 1024 ns | 54 | |
1 - 2 us | 16 | |
2 - 4 us | 10 | |
4 - 8 us | 0 | |
8 - 16 us | 0 | |
16 - 32 us | 0 | |
32 - 64 us | 0 | |
64 - 128 us | 0 | |
128 - 256 us | 0 | |
256 - 512 us | 0 | |
512 - 1024 us | 0 | |
1 - ... ms | 0 | |
+++ exited with 0 +++
#

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Changbin Du <changbin.du@gmail.com>
Cc: Ian Rogers <irogers@google.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: https://lore.kernel.org/r/20220321234609.90455-1-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

authored by

Namhyung Kim and committed by
Arnaldo Carvalho de Melo 84005bb6 7572733b

+22 -11
+15 -9
tools/perf/builtin-ftrace.c
··· 680 680 return (done && !workload_exec_errno) ? 0 : -1; 681 681 } 682 682 683 - static void make_histogram(int buckets[], char *buf, size_t len, char *linebuf) 683 + static void make_histogram(int buckets[], char *buf, size_t len, char *linebuf, 684 + bool use_nsec) 684 685 { 685 686 char *p, *q; 686 687 char *unit; ··· 728 727 if (!unit || strncmp(unit, " us", 3)) 729 728 goto next; 730 729 730 + if (use_nsec) 731 + num *= 1000; 732 + 731 733 i = log2(num); 732 734 if (i < 0) 733 735 i = 0; ··· 748 744 strcat(linebuf, p); 749 745 } 750 746 751 - static void display_histogram(int buckets[]) 747 + static void display_histogram(int buckets[], bool use_nsec) 752 748 { 753 749 int i; 754 750 int total = 0; ··· 774 770 for (i = 1; i < NUM_BUCKET - 1; i++) { 775 771 int start = (1 << (i - 1)); 776 772 int stop = 1 << i; 777 - const char *unit = "us"; 773 + const char *unit = use_nsec ? "ns" : "us"; 778 774 779 775 if (start >= 1024) { 780 776 start >>= 10; 781 777 stop >>= 10; 782 - unit = "ms"; 778 + unit = use_nsec ? "us" : "ms"; 783 779 } 784 780 bar_len = buckets[i] * bar_total / total; 785 781 printf(" %4d - %-4d %s | %10d | %.*s%*s |\n", ··· 789 785 790 786 bar_len = buckets[NUM_BUCKET - 1] * bar_total / total; 791 787 printf(" %4d - %-4s %s | %10d | %.*s%*s |\n", 792 - 1, "...", " s", buckets[NUM_BUCKET - 1], bar_len, bar, 793 - bar_total - bar_len, ""); 788 + 1, "...", use_nsec ? "ms" : " s", buckets[NUM_BUCKET - 1], 789 + bar_len, bar, bar_total - bar_len, ""); 794 790 795 791 } 796 792 ··· 917 913 if (n < 0) 918 914 break; 919 915 920 - make_histogram(buckets, buf, n, line); 916 + make_histogram(buckets, buf, n, line, ftrace->use_nsec); 921 917 } 922 918 } 923 919 ··· 934 930 int n = read(trace_fd, buf, sizeof(buf) - 1); 935 931 if (n <= 0) 936 932 break; 937 - make_histogram(buckets, buf, n, line); 933 + make_histogram(buckets, buf, n, line, ftrace->use_nsec); 938 934 } 939 935 940 936 read_func_latency(ftrace, buckets); 941 937 942 - display_histogram(buckets); 938 + display_histogram(buckets, ftrace->use_nsec); 943 939 944 940 out: 945 941 close(trace_fd); ··· 1175 1171 OPT_BOOLEAN('b', "use-bpf", &ftrace.target.use_bpf, 1176 1172 "Use BPF to measure function latency"), 1177 1173 #endif 1174 + OPT_BOOLEAN('n', "--use-nsec", &ftrace.use_nsec, 1175 + "Use nano-second histogram"), 1178 1176 OPT_PARENT(common_options), 1179 1177 }; 1180 1178 const struct option *options = ftrace_options;
+2
tools/perf/util/bpf_ftrace.c
··· 81 81 } 82 82 } 83 83 84 + skel->bss->use_nsec = ftrace->use_nsec; 85 + 84 86 skel->links.func_begin = bpf_program__attach_kprobe(skel->progs.func_begin, 85 87 false, func->name); 86 88 if (IS_ERR(skel->links.func_begin)) {
+4 -2
tools/perf/util/bpf_skel/func_latency.bpf.c
··· 39 39 int enabled = 0; 40 40 int has_cpu = 0; 41 41 int has_task = 0; 42 + int use_nsec = 0; 42 43 43 44 SEC("kprobe/func") 44 45 int BPF_PROG(func_begin) ··· 81 80 { 82 81 __u64 tid; 83 82 __u64 *start; 83 + __u64 cmp_base = use_nsec ? 1 : 1000; 84 84 85 85 if (!enabled) 86 86 return 0; ··· 99 97 if (delta < 0) 100 98 return 0; 101 99 102 - // calculate index using delta in usec 100 + // calculate index using delta 103 101 for (key = 0; key < (NUM_BUCKET - 1); key++) { 104 - if (delta < ((1000UL) << key)) 102 + if (delta < (cmp_base << key)) 105 103 break; 106 104 } 107 105
+1
tools/perf/util/ftrace.h
··· 17 17 struct list_head nograph_funcs; 18 18 unsigned long percpu_buffer_size; 19 19 bool inherit; 20 + bool use_nsec; 20 21 int graph_depth; 21 22 int func_stack_trace; 22 23 int func_irq_info;