Hi Masami,
On Fri, 2018-04-06 at 10:53 +0900, Masami Hiramatsu wrote:
> Hi Tom,
>
> On Thu, 05 Apr 2018 18:34:13 -0500
> Tom Zanussi <tom.zanussi@xxxxxxxxxxxxxxx> wrote:
>
> > Hi Masami,
> >
> > On Thu, 2018-04-05 at 12:50 +0900, Masami Hiramatsu 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.
> [...]
> > 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
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).
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"
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.
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.
> 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.
Thanks,
Tom
> Thank you,
>
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
