Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

[Masami Hiramatsu <mhiramat@kernel.org>]

On Fri, 06 Apr 2018 11:47:29 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> > > > Can you print out the error with which event we should see? e.g.
> > > > 
> > > >   ERROR: Variable already defined at sched_wakeup: ts0
> > > > 
> > > 
> > > How about printing the event name along with the last command, for any
> > > error? :
> > > 
> > >   ERROR: Variable already defined: ts0
> > >     Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
> > 
> > Hmm, is the Last command shows the last command on sched_wakeup ? or sched_switch??
> > 
> 
> Just the last command that executed with an error - it's a global set by
> the last command that failed, kind of like errno.
> 
> In this case, the last error was for the command listed, on the
> sched_wakeup event.  Even if you see it by reading a different hist
> file, the last error is still the same - we don't keep a last error for
> each event.

OK, in that case, it may not be useful for my case.
I need to know why the error happens and where should I see to solve it.

> 
> > [...]
> > > Before:
> > > 
> > >   # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
> > > 
> > >   # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
> > > 
> > > And other commands making us think we cleared everything out so the
> > > below error is a surprise
> > > 
> > >   # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
> > >   -su: echo: write error: Invalid argument
> > 
> > No, my senario is different.
> > 
> > Your senario tries
> > 1) define ts0 on sched_wakeup
> > 2) remove ts0 from sched_switch (but silently failed)
> > 3) re-define ts0 on sched_wakeup and get an error
> > 
> > In this case, user can dump sched_wakeup/trigger and see there is already ts0 defined.
> > 
> > My senario is a bit different
> > 1) define ts0 on sched_wakeup
> > 2) remove ts0 from sched_switch (but silently failed)
> > 3) re-define ts0 on *sched_switch* and get an error
> > 
> > The 3rd operation failed on "sched_switch" not on "sched_wakeup". In this case we will totally lost where the ts0 defined.
> > That's why I have asked you to show "where the ts0 is defined" at error line.
> > 
> 
> Your scenario should work, which is why I assumed my scenario.  Anyway,
> this I think corresponds to your scenario, which works for me:
> 
>   # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
>   # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
>   # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>   # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

Hmm, is it possible to redefine ts0 on different event??
In that case, will ts0 be updated on both sched_switch and sched_wakeup?

> 
> I also tried this, which works too:
> 
>   # echo '!wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
>   # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
>   # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>   # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>   # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>   # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
> 
> When I looked at the details of what you did in your script, it
> corresponded to my scenario - the error you saw was because you didn't
> remove the sched_wakeup trigger though you apparently thought you did,
> and then tried to do it again (according to your script, the command
> that failed was to sched_wakeup, and then you looked at sched_switch and
> saw the error).

Ah, I got it! I mixed it up, sorry.

BTW, if I defied ts0 at sched_wakeup

====
[root@devbox ~]# echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
====

and do it again,

====
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
-bash: echo: write error: Invalid argument
[root@devbox ~]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist  
# event histogram
#
# trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
#


Totals:
    Hits: 0
    Entries: 0
    Dropped: 0

ERROR: Variable already defined: ts0
  Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
====

OK, I got this error message.
However, if I write same command on sched_switch,

====
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
-bash: echo: write error: Invalid argument
====

This gets error because there is no "pid" argument in the event, but

====
[root@devbox ~]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist# event histogram
#
# trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
#


Totals:
    Hits: 0
    Entries: 0
    Dropped: 0
[root@devbox ~]#
====

I can't see the corresponding error message...

> 
> Anyway, here's the corresponding version that works if you add the
> trigger to sched_switch instead of twice to sched_wakeup:
> 
> Try adding to sched_wakeup, fails:
> 
>   # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
>     -su: echo: 
>     write error: Invalid argument
> 
> Look at sched_switch instead of sched_wakeup, shows error was on sched_wakeup:
> 
>   # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
>     ERROR: Variable already defined: ts0
>     Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
> 
> Look at sched_wakeup, sched_wakeup trigger exists and has the ts0 defined:
> 
>   # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
>     hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
> 
> Let's add a trigger with ts0 to sched_switch:
> 
>   # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
> 
> No error seen, and now we can see that both sched_switch and sched_wakeup have triggers with ts0:
> 
>   # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>     hist:keys=next_pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
>   # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
>     hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
>  
> Now at this point, we have two triggers with the same variable name, ts0
> - if we try to use an unqualified ts0 in another trigger, we get an
> error:
> 
>   # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>     -su: echo: write error: Invalid argument
>   # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
>   # event histogram
>   #
>   # trigger info: 
>     hist:keys=next_pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
>   #
> 
> 
>   Totals:
>        Hits: 0
>        Entries: 0
>        Dropped: 0
> 
>   ERROR: Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ts0
>    Last command: [sched:sched_switch] keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"

Ah, I see. So ts0 is abbreviated name :) we have 2 different variables.


> So in order to set the trigger, we need to explicitly specify which ts0 to use:
> 
> # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-sched.sched_wakeup.$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
> 
> So we use the explicit sched.sched_wakeup.$ts0 to specify that we want
> to use the ts0 on sched_wakeup for the calculation.

got it.

> Note that the most common use case is to put the
> wakeup_lat=common_timestamp.usecs-$ts0 expression on a trigger with an
> onmatch() action, and onmatch() specifies the matching event, so there's
> no need to explicitly use the fully qualified sched.sched_wakeup.$ts0 in
> that case.  The above doesn't have onmatch(), and therefore has no way
> to disambiguate the name without specifying which event explicitly.

Cool :)

> > Anyway, I think it is a good chance to introduce <tracefs>/error_log file, since we have too many non-critical errors on operations. I feel that checking hist file by errors on trigger file is not a bit intuitive.
> > 
> > # cat /sys/kernel/debug/tracing/error_log
> > ERROR(events/sched/sched_switch/trigger): Variable already defined: ts0@sched:sched_wakeup
> >   Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
> > 
> > This can be used from probe events too :) 
> > e.g.
> > 
> > ERROR(kprobe_events): Unsupported type: uint8
> >   Command: p vfs_read arg1=%di:uint8
> > 
> > Any thought?
> > 
> 
> I agree - I think that would make more sense than using the hist files
> for that purpose.  I'll work on adding this and getting rid of the hist
> file error mechanism.

Thank you!

-- 
Masami Hiramatsu <mhiramat@kernel.org>