Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1676710
| From | Masami Hiramatsu <mhiramat@kernel.org> |
|---|---|
| Newsgroups | linux.kernel |
| Subject | Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support |
| Date | 2017-06-28 16:30 +0200 |
| Message-ID | <tXm8F-7TU-7@gated-at.bofh.it> (permalink) |
| References | <tWKZs-8nP-19@gated-at.bofh.it> <tWKZs-8nP-19@gated-at.bofh.it> |
| Organization | linux.* mail to news gateway |
Hi Tom,
On Mon, 26 Jun 2017 17:49:01 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> This patchset adds support for 'inter-event' quantities to the trace
> event subsystem. The most important example of inter-event quantities
> are latencies, or the time differences between two events.
>
Thank you for your great work!
I'm playing this and found some issues.
(1) new event format
----
# echo "wakeup_latency u64 lat; pid_t pid; int prio" > synthetic_events
# cat /sys/kernel/debug/tracing # cat events/synthetic/wakeup_latency/format
name: wakeup_latency
ID: 972
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1;signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:u64 lat; offset:16; size:8; signed:0;
field:pid_t pid; offset:24; size:4; signed:1;
field:int prio; offset:32; size:4; signed:1;
print fmt: "lat: 0x%08lx, pid: 0x%08lx, prio: 0x%08lx", ((u64)(REC->lat)), ((u64)(REC->pid)), ((u64)(REC->prio))
----
Here, IMO, this format would be better "lat=0x%08lx pid=0x%08lx prio=0x%08lx" so that perf-script can parse it correctly.
(2) lockdep found a dead lock case
When I added a histogram trigger, it happened.
----
# echo 'hist:keys=pid:ts0=$common_timestamp.usecs' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
[33967.672485]
[33967.673117] ======================================================
[33967.673117] WARNING: possible circular locking dependency detected
[33967.673117] 4.12.0-rc5+ #1 Not tainted
[33967.673117] ------------------------------------------------------
[33967.673117] bash/708 is trying to acquire lock:
[33967.673117] (trace_types_lock){+.+.+.}, at: [<ffffffff811307e6>] tracing_set_clock+0x66/0xe0
[33967.673117]
[33967.673117] but task is already holding lock:
[33967.673117] (trigger_cmd_mutex){+.+.+.}, at: [<ffffffff81144264>] event_trigger_write+0xb4/0x1a0
[33967.673117]
[33967.673117] which lock already depends on the new lock.
[33967.673117]
[33967.673117]
[33967.673117] the existing dependency chain (in reverse order) is:
[33967.673117]
[33967.673117] -> #2 (trigger_cmd_mutex){+.+.+.}:
[33967.673117] lock_acquire+0xe3/0x1d0
[33967.673117] __mutex_lock+0x81/0x950
[33967.673117] mutex_lock_nested+0x1b/0x20
[33967.673117] event_trigger_write+0xb4/0x1a0
[33967.673117] __vfs_write+0x28/0x120
[33967.673117] vfs_write+0xc7/0x1b0
[33967.673117] SyS_write+0x49/0xa0
[33967.673117] entry_SYSCALL_64_fastpath+0x1f/0xbe
[33967.673117]
[33967.673117] -> #1 (event_mutex){+.+.+.}:
[33967.673117] lock_acquire+0xe3/0x1d0
[33967.673117] __mutex_lock+0x81/0x950
[33967.673117] mutex_lock_nested+0x1b/0x20
[33967.673117] trace_add_event_call+0x28/0xc0
[33967.673117] create_synth_event+0x40a/0x880
[33967.673117] trace_run_command+0x54/0x60
[33967.673117] trace_parse_run_command+0xc4/0x160
[33967.673117] synth_events_write+0x10/0x20
[33967.673117] __vfs_write+0x28/0x120
[33967.673117] vfs_write+0xc7/0x1b0
[33967.673117] SyS_write+0x49/0xa0
[33967.673117] entry_SYSCALL_64_fastpath+0x1f/0xbe
[33967.673117]
[33967.673117] -> #0 (trace_types_lock){+.+.+.}:
[33967.673117] __lock_acquire+0x1026/0x11d0
[33967.673117] lock_acquire+0xe3/0x1d0
[33967.673117] __mutex_lock+0x81/0x950
[33967.673117] mutex_lock_nested+0x1b/0x20
[33967.673117] tracing_set_clock+0x66/0xe0
[33967.673117] hist_register_trigger+0x209/0x2a0
[33967.673117] event_hist_trigger_func+0xc6b/0x2610
[33967.673117] event_trigger_write+0xfa/0x1a0
[33967.673117] __vfs_write+0x28/0x120
[33967.673117] vfs_write+0xc7/0x1b0
[33967.673117] SyS_write+0x49/0xa0
[33967.673117] entry_SYSCALL_64_fastpath+0x1f/0xbe
[33967.673117]
[33967.673117] other info that might help us debug this:
[33967.673117]
[33967.673117] Chain exists of:
[33967.673117] trace_types_lock --> event_mutex --> trigger_cmd_mutex
[33967.673117]
[33967.673117] Possible unsafe locking scenario:
[33967.673117]
[33967.673117] CPU0 CPU1
[33967.673117] ---- ----
[33967.673117] lock(trigger_cmd_mutex);
[33967.673117] lock(event_mutex);
[33967.673117] lock(trigger_cmd_mutex);
[33967.673117] lock(trace_types_lock);
[33967.673117]
[33967.673117] *** DEADLOCK ***
[33967.673117]
[33967.673117] 3 locks held by bash/708:
[33967.673117] #0: (sb_writers#8){.+.+.+}, at: [<ffffffff811ef42f>] vfs_write+0x18f/0x1b0
[33967.673117] #1: (event_mutex){+.+.+.}, at: [<ffffffff8114421c>] event_trigger_write+0x6c/0x1a0
[33967.673117] #2: (trigger_cmd_mutex){+.+.+.}, at: [<ffffffff81144264>] event_trigger_write+0xb4/0x1a0
[33967.673117]
[33967.673117] stack backtrace:
[33967.673117] CPU: 4 PID: 708 Comm: bash Not tainted 4.12.0-rc5+ #1
[33967.673117] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
[33967.673117] Call Trace:
[33967.673117] dump_stack+0x86/0xcf
[33967.673117] print_circular_bug+0x1be/0x210
[33967.673117] __lock_acquire+0x1026/0x11d0
[33967.673117] lock_acquire+0xe3/0x1d0
[33967.673117] ? lock_acquire+0xe3/0x1d0
[33967.673117] ? tracing_set_clock+0x66/0xe0
[33967.673117] ? tracing_set_clock+0x66/0xe0
[33967.673117] __mutex_lock+0x81/0x950
[33967.673117] ? tracing_set_clock+0x66/0xe0
[33967.673117] ? rcu_read_lock_sched_held+0x4a/0x80
[33967.673117] ? tracing_set_clock+0x66/0xe0
[33967.673117] mutex_lock_nested+0x1b/0x20
[33967.673117] ? mutex_lock_nested+0x1b/0x20
[33967.673117] tracing_set_clock+0x66/0xe0
[33967.673117] hist_register_trigger+0x209/0x2a0
[33967.673117] event_hist_trigger_func+0xc6b/0x2610
[33967.673117] ? event_trigger_write+0xb4/0x1a0
[33967.673117] ? __mutex_lock+0x81/0x950
[33967.673117] ? event_trigger_write+0xb4/0x1a0
[33967.673117] ? event_trigger_write+0xb4/0x1a0
[33967.673117] event_trigger_write+0xfa/0x1a0
[33967.673117] __vfs_write+0x28/0x120
[33967.673117] ? rcu_read_lock_sched_held+0x4a/0x80
[33967.673117] ? rcu_sync_lockdep_assert+0x2f/0x60
[33967.673117] ? __sb_start_write+0xe7/0x1e0
[33967.673117] ? vfs_write+0x18f/0x1b0
[33967.673117] vfs_write+0xc7/0x1b0
[33967.673117] SyS_write+0x49/0xa0
[33967.673117] entry_SYSCALL_64_fastpath+0x1f/0xbe
[33967.673117] RIP: 0033:0x4bb040
[33967.673117] RSP: 002b:00007ffd79e44288 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[33967.673117] RAX: ffffffffffffffda RBX: 0000000002829220 RCX: 00000000004bb040
[33967.673117] RDX: 000000000000002a RSI: 00000000028288f0 RDI: 0000000000000001
[33967.673117] RBP: 0000000002828000 R08: fefefefefefefeff R09: ff8772626471ff72
[33967.673117] R10: 00000000028288f0 R11: 0000000000000246 R12: 0000000002827f90
[33967.673117] R13: 0000000000000003 R14: 0000000000000001 R15: 0000000000000071
----
Anyway I just started to run this series, I'll also try to check other
features.
Thank you!
--
Masami Hiramatsu <mhiramat@kernel.org>
Back to linux.kernel | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread
[PATCH 00/32] tracing: Inter-event (e.g. latency) support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 00:50 +0200
[PATCH 17/32] tracing: Account for variables in named trigger compatibility Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 02/32] tracing: Reimplement log2 Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 10/32] tracing: Add NO_DISCARD event file flag Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 11/32] tracing: Add post-trigger flag to hist trigger command Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 19/32] tracing: Add variable reference handling to hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 29/32] tracing: Add 'last error' error facility for hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 04/32] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
Re: [PATCH 04/32] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP "Joel Fernandes (Google)" <joel.opensrc@gmail.com> - 2017-07-02 11:00 +0200
[PATCH 06/32] tracing: Add ring buffer event param to hist field functions Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 16/32] tracing: Add variable support to hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 20/32] tracing: Add support for dynamic tracepoints Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 24/32] tracing: Add 'onmax' hist trigger action support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 03/32] ring-buffer: Add interface for setting absolute time stamps Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 13/32] tracing: Add per-element variable support to tracing_map Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 09/32] tracing: Make traceprobe parsing code reusable Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 28/32] tracing: Add hist trigger support for variable reference aliases Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 32/32] tracing: Add a clock attribute for hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 25/32] tracing: Allow whitespace to surround hist trigger filter Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 05/32] tracing: Give event triggers access to ring_buffer_event Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 21/32] tracing: Add hist trigger action hook Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 07/32] tracing: Increase tracing map KEYS_MAX size Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 30/32] tracing: Add inter-event hist trigger Documentation Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 31/32] tracing: Make tracing_set_clock() non-static Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 22/32] tracing: Add support for 'synthetic' events Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 12/32] tracing: Add hist trigger timestamp support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 18/32] tracing: Add simple expression support to hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 08/32] tracing: Break out hist trigger assignment parsing Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 15/32] tracing: Add usecs modifier for hist trigger timestamps Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 23/32] tracing: Add 'onmatch' hist trigger action support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 14/32] tracing: Add hist_data member to hist_field Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 26/32] tracing: Make duplicate count from tracing_map available Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 01/32] tracing: Add hist_field_name() accessor Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 27/32] tracing: Add cpu field for hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support Steven Rostedt <rostedt@goodmis.org> - 2017-06-27 17:10 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support Masami Hiramatsu <mhiramat@kernel.org> - 2017-06-28 16:30 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-28 21:20 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support "Joel Fernandes (Google)" <joel.opensrc@gmail.com> - 2017-07-01 09:10 +0200
csiph-web