From: Masami Hiramatsu <mhiramat@kernel.org>
To: Tom Zanussi <tom.zanussi@linux.intel.com>
Cc: rostedt@goodmis.org, tglx@linutronix.de, mhiramat@kernel.org,
namhyung@kernel.org, vedang.patel@intel.com,
linux-kernel@vger.kernel.org, linux-rt-users@vger.kernel.org
Subject: Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support
Date: Wed, 28 Jun 2017 23:21:44 +0900 [thread overview]
Message-ID: <20170628232144.faa4b925cab7a9b3d563fb6d@kernel.org> (raw)
In-Reply-To: <cover.1498510759.git.tom.zanussi@linux.intel.com>
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>
next prev parent reply other threads:[~2017-06-28 14:21 UTC|newest]
Thread overview: 66+ messages / expand[flat|nested] mbox.gz Atom feed top
2017-06-26 22:49 [PATCH 00/32] tracing: Inter-event (e.g. latency) support Tom Zanussi
2017-06-26 22:49 ` [PATCH 01/32] tracing: Add hist_field_name() accessor Tom Zanussi
2017-07-13 6:49 ` Piotr Gregor
2017-07-13 14:41 ` Tom Zanussi
2017-07-14 2:19 ` Namhyung Kim
2017-06-26 22:49 ` [PATCH 02/32] tracing: Reimplement log2 Tom Zanussi
2017-07-14 2:33 ` Namhyung Kim
2017-07-14 16:13 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 03/32] ring-buffer: Add interface for setting absolute time stamps Tom Zanussi
2017-07-14 5:25 ` Namhyung Kim
2017-07-14 16:14 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 04/32] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP Tom Zanussi
2017-07-02 8:51 ` Joel Fernandes (Google)
2017-06-26 22:49 ` [PATCH 05/32] tracing: Give event triggers access to ring_buffer_event Tom Zanussi
2017-06-26 22:49 ` [PATCH 06/32] tracing: Add ring buffer event param to hist field functions Tom Zanussi
2017-06-26 22:49 ` [PATCH 07/32] tracing: Increase tracing map KEYS_MAX size Tom Zanussi
2017-06-26 22:49 ` [PATCH 08/32] tracing: Break out hist trigger assignment parsing Tom Zanussi
2017-06-26 22:49 ` [PATCH 09/32] tracing: Make traceprobe parsing code reusable Tom Zanussi
2017-06-26 22:49 ` [PATCH 10/32] tracing: Add NO_DISCARD event file flag Tom Zanussi
2017-06-26 22:49 ` [PATCH 11/32] tracing: Add post-trigger flag to hist trigger command Tom Zanussi
2017-06-26 22:49 ` [PATCH 12/32] tracing: Add hist trigger timestamp support Tom Zanussi
2017-07-17 6:00 ` Namhyung Kim
2017-07-17 16:57 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 13/32] tracing: Add per-element variable support to tracing_map Tom Zanussi
2017-06-26 22:49 ` [PATCH 14/32] tracing: Add hist_data member to hist_field Tom Zanussi
2017-06-26 22:49 ` [PATCH 15/32] tracing: Add usecs modifier for hist trigger timestamps Tom Zanussi
2017-06-26 22:49 ` [PATCH 16/32] tracing: Add variable support to hist triggers Tom Zanussi
2017-07-19 1:07 ` Namhyung Kim
2017-07-19 15:40 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 17/32] tracing: Account for variables in named trigger compatibility Tom Zanussi
2017-06-26 22:49 ` [PATCH 18/32] tracing: Add simple expression support to hist triggers Tom Zanussi
2017-07-21 2:02 ` Namhyung Kim
2017-07-21 16:29 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 19/32] tracing: Add variable reference handling " Tom Zanussi
2017-07-21 3:31 ` Namhyung Kim
2017-07-21 16:41 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 20/32] tracing: Add support for dynamic tracepoints Tom Zanussi
2017-06-26 22:49 ` [PATCH 21/32] tracing: Add hist trigger action hook Tom Zanussi
2017-06-26 22:49 ` [PATCH 22/32] tracing: Add support for 'synthetic' events Tom Zanussi
2017-07-23 12:00 ` Namhyung Kim
2017-07-24 16:11 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 23/32] tracing: Add 'onmatch' hist trigger action support Tom Zanussi
2017-07-23 15:12 ` Namhyung Kim
2017-07-24 16:17 ` Tom Zanussi
2017-07-26 2:40 ` Namhyung Kim
2017-07-26 16:38 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 24/32] tracing: Add 'onmax' " Tom Zanussi
2017-07-26 3:04 ` Namhyung Kim
2017-07-26 16:45 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 25/32] tracing: Allow whitespace to surround hist trigger filter Tom Zanussi
2017-06-26 22:49 ` [PATCH 26/32] tracing: Make duplicate count from tracing_map available Tom Zanussi
2017-06-26 22:49 ` [PATCH 27/32] tracing: Add cpu field for hist triggers Tom Zanussi
2017-06-26 22:49 ` [PATCH 28/32] tracing: Add hist trigger support for variable reference aliases Tom Zanussi
2017-06-26 22:49 ` [PATCH 29/32] tracing: Add 'last error' error facility for hist triggers Tom Zanussi
2017-07-26 4:39 ` Namhyung Kim
2017-07-26 16:47 ` Tom Zanussi
2017-06-26 22:49 ` [PATCH 30/32] tracing: Add inter-event hist trigger Documentation Tom Zanussi
2017-06-26 22:49 ` [PATCH 31/32] tracing: Make tracing_set_clock() non-static Tom Zanussi
2017-06-26 22:49 ` [PATCH 32/32] tracing: Add a clock attribute for hist triggers Tom Zanussi
2017-06-27 14:58 ` [PATCH 00/32] tracing: Inter-event (e.g. latency) support Steven Rostedt
2017-06-28 14:21 ` Masami Hiramatsu [this message]
2017-06-28 19:09 ` Tom Zanussi
2017-07-01 7:01 ` Joel Fernandes (Google)
2017-07-12 19:17 ` Tom Zanussi
2017-07-04 16:12 ` Sebastian Andrzej Siewior
2017-07-12 19:20 ` Tom Zanussi
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20170628232144.faa4b925cab7a9b3d563fb6d@kernel.org \
--to=mhiramat@kernel.org \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-rt-users@vger.kernel.org \
--cc=namhyung@kernel.org \
--cc=rostedt@goodmis.org \
--cc=tglx@linutronix.de \
--cc=tom.zanussi@linux.intel.com \
--cc=vedang.patel@intel.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).