Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support

Tom Zanussi
2017-06-28T19:09:57Z

Hi Masami,

On Wed, 2017-06-28 at 23:21 +0900, Masami Hiramatsu wrote:
> 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.
>

OK, will change it.

> (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] ------------------------------------------------------

Yeah, will fix this and anything else similar, thanks for pointing it
out.

Tom