Re: [PATCH v3 2/3] tracing: Add trace_irqsoff tracepoints
From: Daniel Wagner
Date: Tue Aug 30 2016 - 10:01:55 EST
Hi Steven,
>> 'hist:key=ltype,latency:val=hitcount:sort=latency if cpu==1'
>
> What about using "CPU" (all caps)? Look at
> kernel/trace/trace_events_filter.c for FILTER_CPU.
>
> Lets not add fields when we can fix the generic code to process these.
Well at least the size info needs to be added to the trace field.
Without it hist will bail out with no memory.
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 03c0a48..ab8958f 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -152,7 +152,8 @@ EXPORT_SYMBOL_GPL(trace_define_field);
#define __generic_field(type, item, filter_type) \
ret = __trace_define_field(&ftrace_generic_fields, #type, \
- #item, 0, 0, is_signed_type(type), \
+ #item, 0, sizeof(type), \
+ is_signed_type(type), \
filter_type); \
if (ret) \
return ret;
After that I get this funky report (with only 4 cpus):
echo "'hist:key=cpu,id.syscall' >
/sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist'
# event histogram
#
# trigger info: hist:keys=cpu,id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
#
{ cpu: 262161, id: sys_newfstatat [262] } hitcount: 1
{ cpu: 262161, id: sys_write [ 1] } hitcount: 1
{ cpu: 262161, id: sys_read [ 0] } hitcount: 1
{ cpu: 262161, id: sys_recvmsg [ 47] } hitcount: 1
{ cpu: 17, id: sys_inotify_init1 [294] } hitcount: 2
{ cpu: 17, id: sys_mknod [133] } hitcount: 2
{ cpu: 17, id: sys_setuid [105] } hitcount: 2
{ cpu: 17, id: sys_getcwd [ 79] } hitcount: 2
{ cpu: 17, id: sys_accept [ 43] } hitcount: 2
{ cpu: 17, id: sys_chroot [161] } hitcount: 2
{ cpu: 17, id: sys_fadvise64 [221] } hitcount: 2
{ cpu: 17, id: sys_umount [166] } hitcount: 2
{ cpu: 17, id: sys_rt_sigtimedwait [128] } hitcount: 2
{ cpu: 17, id: sys_mount [165] } hitcount: 2
{ cpu: 262161, id: sys_close [ 3] } hitcount: 2
{ cpu: 262161, id: sys_newfstat [ 5] } hitcount: 2
{ cpu: 262161, id: sys_getrandom [318] } hitcount: 3
{ cpu: 262161, id: sys_open [ 2] } hitcount: 3
{ cpu: 17, id: sys_setgid [106] } hitcount: 4
{ cpu: 17, id: sys_inotify_add_watch [254] } hitcount: 4
{ cpu: 17, id: sys_setpriority [141] } hitcount: 4
{ cpu: 17, id: sys_getpriority [140] } hitcount: 4
{ cpu: 17, id: sys_eventfd2 [290] } hitcount: 4
{ cpu: 17, id: sys_listen [ 50] } hitcount: 4
{ cpu: 17, id: sys_timerfd_create [283] } hitcount: 4
{ cpu: 17, id: sys_dup [ 32] } hitcount: 4
{ cpu: 17, id: sys_fstatfs [138] } hitcount: 5
{ cpu: 17, id: sys_ftruncate [ 77] } hitcount: 5
{ cpu: 17, id: sys_socketpair [ 53] } hitcount: 6
{ cpu: 17, id: sys_name_to_handle_at [303] } hitcount: 6
{ cpu: 17, id: sys_chmod [ 90] } hitcount: 6
{ cpu: 17, id: sys_chown [ 92] } hitcount: 6
{ cpu: 17, id: sys_readlink [ 89] } hitcount: 6
{ cpu: 17, id: sys_getpid [ 39] } hitcount: 8
{ cpu: 17, id: sys_unlinkat [263] } hitcount: 8
{ cpu: 17, id: sys_setrlimit [160] } hitcount: 8
{ cpu: 17, id: sys_sysinfo [ 99] } hitcount: 8
{ cpu: 17, id: sys_getpgrp [111] } hitcount: 8
{ cpu: 17, id: sys_getgroups [115] } hitcount: 10
{ cpu: 17, id: sys_setsid [112] } hitcount: 10
{ cpu: 17, id: sys_getpeername [ 52] } hitcount: 10
{ cpu: 17, id: sys_gettid [186] } hitcount: 10
{ cpu: 17, id: sys_shutdown [ 48] } hitcount: 12
{ cpu: 17, id: sys_getppid [110] } hitcount: 12
{ cpu: 17, id: sys_chdir [ 80] } hitcount: 14
{ cpu: 17, id: sys_alarm [ 37] } hitcount: 14
{ cpu: 17, id: sys_pipe [ 22] } hitcount: 14
{ cpu: 17, id: sys_keyctl [250] } hitcount: 15
{ cpu: 17, id: sys_sendto [ 44] } hitcount: 19
{ cpu: 17, id: unknown_syscall [ 15] } hitcount: 20
{ cpu: 17, id: sys_utimensat [280] } hitcount: 21
{ cpu: 17, id: sys_faccessat [269] } hitcount: 22
{ cpu: 17, id: sys_setgroups [116] } hitcount: 22
{ cpu: 17, id: sys_pipe2 [293] } hitcount: 22
{ cpu: 17, id: sys_setresgid [119] } hitcount: 24
{ cpu: 17, id: sys_accept4 [288] } hitcount: 26
{ cpu: 17, id: sys_setresuid [117] } hitcount: 26
{ cpu: 17, id: unknown_syscall [ 59] } hitcount: 28
{ cpu: 17, id: sys_futex [202] } hitcount: 29
{ cpu: 17, id: unknown_syscall [312] } hitcount: 34
{ cpu: 17, id: sys_waitid [247] } hitcount: 36
{ cpu: 17, id: sys_select [ 23] } hitcount: 37
{ cpu: 17, id: sys_fchmod [ 91] } hitcount: 49
{ cpu: 17, id: sys_statfs [137] } hitcount: 52
{ cpu: 17, id: sys_rename [ 82] } hitcount: 55
{ cpu: 17, id: sys_openat [257] } hitcount: 64
{ cpu: 17, id: sys_newuname [ 63] } hitcount: 68
{ cpu: 17, id: sys_getegid [108] } hitcount: 69
{ cpu: 17, id: sys_getgid [104] } hitcount: 70
{ cpu: 17, id: sys_connect [ 42] } hitcount: 76
{ cpu: 17, id: sys_signalfd4 [289] } hitcount: 83
{ cpu: 17, id: sys_epoll_create1 [291] } hitcount: 85
{ cpu: 17, id: sys_set_tid_address [218] } hitcount: 90
{ cpu: 17, id: sys_kill [ 62] } hitcount: 91
{ cpu: 17, id: sys_bind [ 49] } hitcount: 91
{ cpu: 17, id: unknown_syscall [158] } hitcount: 102
{ cpu: 17, id: sys_prctl [157] } hitcount: 117
{ cpu: 17, id: unknown_syscall [ 56] } hitcount: 117
{ cpu: 17, id: sys_geteuid [107] } hitcount: 119
{ cpu: 17, id: sys_ioctl [ 16] } hitcount: 120
{ cpu: 17, id: sys_dup2 [ 33] } hitcount: 125
{ cpu: 17, id: sys_ppoll [271] } hitcount: 150
{ cpu: 17, id: sys_getuid [102] } hitcount: 160
{ cpu: 17, id: sys_getsockname [ 51] } hitcount: 163
{ cpu: 17, id: sys_timerfd_settime [286] } hitcount: 167
{ cpu: 17, id: sys_umask [ 95] } hitcount: 172
{ cpu: 17, id: sys_wait4 [ 61] } hitcount: 186
{ cpu: 17, id: sys_exit_group [231] } hitcount: 189
{ cpu: 17, id: sys_set_robust_list [273] } hitcount: 191
{ cpu: 17, id: sys_lseek [ 8] } hitcount: 196
{ cpu: 17, id: sys_rmdir [ 84] } hitcount: 210
{ cpu: 17, id: sys_mkdir [ 83] } hitcount: 211
{ cpu: 17, id: sys_setsockopt [ 54] } hitcount: 215
{ cpu: 17, id: sys_poll [ 7] } hitcount: 221
{ cpu: 17, id: sys_unlink [ 87] } hitcount: 221
{ cpu: 17, id: sys_getsockopt [ 55] } hitcount: 222
{ cpu: 17, id: sys_socket [ 41] } hitcount: 229
{ cpu: 17, id: sys_munmap [ 11] } hitcount: 260
{ cpu: 17, id: sys_getrlimit [ 97] } hitcount: 318
{ cpu: 17, id: sys_rt_sigprocmask [ 14] } hitcount: 344
{ cpu: 17, id: sys_access [ 21] } hitcount: 380
{ cpu: 17, id: sys_epoll_ctl [233] } hitcount: 391
{ cpu: 17, id: sys_readlinkat [267] } hitcount: 416
{ cpu: 17, id: sys_newstat [ 4] } hitcount: 582
{ cpu: 17, id: sys_write [ 1] } hitcount: 694
{ cpu: 17, id: sys_rt_sigaction [ 13] } hitcount: 732
{ cpu: 17, id: sys_brk [ 12] } hitcount: 736
{ cpu: 17, id: sys_fcntl [ 72] } hitcount: 818
{ cpu: 17, id: sys_sendmsg [ 46] } hitcount: 850
{ cpu: 17, id: sys_getrandom [318] } hitcount: 908
{ cpu: 17, id: sys_getdents [ 78] } hitcount: 937
{ cpu: 17, id: sys_clock_gettime [228] } hitcount: 1015
{ cpu: 17, id: sys_epoll_wait [232] } hitcount: 1394
{ cpu: 17, id: sys_newfstatat [262] } hitcount: 1544
{ cpu: 17, id: sys_mprotect [ 10] } hitcount: 1592
{ cpu: 17, id: sys_recvmsg [ 47] } hitcount: 1676
{ cpu: 17, id: sys_newlstat [ 6] } hitcount: 1897
{ cpu: 17, id: sys_mmap [ 9] } hitcount: 2474
{ cpu: 17, id: sys_newfstat [ 5] } hitcount: 3301
{ cpu: 17, id: sys_read [ 0] } hitcount: 3570
{ cpu: 17, id: sys_open [ 2] } hitcount: 4191
{ cpu: 17, id: sys_close [ 3] } hitcount: 4194
Totals:
Hits: 40593
Entries: 122
Dropped: 0
Still trying to figure out what's going wrong here.
cheers,
daniel