On Thu, 2017-02-09 at 23:18 +0900, Masami Hiramatsu wrote:
> Hi Tom,
>
> On Wed, 08 Feb 2017 19:14:22 -0600
> Tom Zanussi <tom.zanussi@xxxxxxxxxxxxxxx> wrote:
>
> > > > I'm submitting the patchset (based on tracing/for-next) as an RFC not
> > > > only to get comments, but because there are still some problems I
> > > > haven't fixed yet...
> > > >
> > > > Here are some examples that should make things less abstract.
> > > >
> > > > ====
> > > > Example - wakeup latency
> > > > ====
> > > >
> > > > This basically implements the -RT latency_hist 'wakeup_latency'
> > > > histogram using the synthetic events, variables, and actions
> > > > described. The output below is from a run of cyclictest using the
> > > > following command:
> > > >
> > > > # rt-tests/cyclictest -p 80 -n -s -t 2
> > > >
> > > > What we're measuring the latency of is the time between when a
> > > > thread (of cyclictest) is awakened and when it's scheduled in. To
> > > > do that we add triggers to sched_wakeup and sched_switch with the
> > > > appropriate variables, and on a matching sched_switch event,
> > > > generate a synthetic 'wakeup_latency' event. Since it's just
> > > > another trace event like any other, we can also define a histogram
> > > > on that event, the output of which is what we see displayed when
> > > > reading the wakeup_latency 'hist' file.
> > > >
> > > > First, we create a synthetic event called wakeup_latency, that
> > > > references 3 variables from other events:
> > > >
> > > > # echo 'wakeup_latency lat=sched_switch:wakeup_lat \
> > > > pid=sched_switch:woken_pid \
> > > > prio=sched_switch:woken_prio' >> \
> > > > /sys/kernel/debug/tracing/synthetic_events
> > > >
> > > > Next we add a trigger to sched_wakeup, which saves the value of the
> > > > 'common_timestamp' when that event is hit in a variable, ts0. Note
> > > > that this happens only when 'comm==cyclictest'.
> > > >
> > > > Also, 'common_timestamp' is a new field defined on every event (if
> > > > needed - if there are no users of timestamps in a trace, timestamps
> > > > won't be saved and there's no additional overhead from that).
> > > >
> > > > # echo 'hist:keys=pid:ts0=common_timestamp.usecs if \
> > > > comm=="cyclictest"' >> \
> > > > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
> > > >
> > > > Next, we add a trigger to sched_switch. When the pid being switched
> > > > to matches the pid woken up by a previous sched_wakeup event, this
> > > > event grabs the ts0 saved on that event, takes the difference
> > > > between it and the current sched_switch's common_timestamp, and
> > > > assigns it to a new 'wakeup_lat' variable. It also saves a couple
> > > > other variables and then invokes the onmatch().trace() action which
> > > > generates a new wakeup_latency event using those variables.
> > > >
> > > > # echo 'hist:keys=woken_pid=next_pid:woken_prio=next_prio:\
> > > > wakeup_lat=common_timestamp.usecs-ts0:onmatch().trace(wakeup_latency) \
> > > > if next_comm=="cyclictest"' >> \
> > > > /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
> > >
> > > Hmm, this looks a bit hard to understand, I guess that onmatch() means
> > > "if there is an event which has ts0 variable and the event's key matches
> > > this key, take some action".
> >
> > Yes, that's pretty much it. It's essentially shorthand for this kind of
> > common idiom, where timestamp[] is an associative array, which in our
> > case is the tracing_map of the histogram:
> >
> > event sched_wakeup()
> > {
> > ts0[wakeup_pid] = now()
> > }
> >
> > event sched_switch()
> > {
> > if (ts0[next_pid])
> > latency = now() - ts0[next_pid] /* next_pid == wakeup_pid */
> > }
> >
> > Only if ts0 has already been set does the onmatch() get invoked - if ts0
> > hasn't been set, there's no match and the trace(wakeup_latency) doesn't
> > happen.
>
> OK, it reminds me other questions.
>
> - Even if there is no matched ts0, sched_switch's hist will store
> woken_pid etc on its histogram map?
Yes, the match is just to invoke the onmatch() action, but the variables
are set regardless.
> - If there is matched ts0 and wakeup_latency event has been kicked,
> the matched entry on ts0 is removed? and also in that case what
> happens on sched_switch's hist?
>
The entry isn't actually removed, but as far as ts0 goes, the result is
the same as if it had been - ts0 is a read-once variable, so once it's
used by the latency calculation, it's reset to an 'unset' after reading.
This essentially is how the 'if ts0[next_pid]' gets implemented -
actually, I should have added the implied removal to the pseudocode
above:
if (ts0[next_pid])
latency = now() - ts0[next_pid]
ts0[next_pid] = null
The variables on sched_switch, since they aren't referenced by any
expression, aren't read-once, and just remain as they are.
I wanted to avoid making the user explicitly specify somehow whether a
variable was 'normal' or read-once, so I figured a simplifying
assumption could be that if the variable was referenced in an
expression, that means it should be read-once, while otherwise there's
no reason it should be read-once.
> > > I think there are 2 indefinate point that
> > > - Where the 'ts0' came from? what the variable will have 'global' scope?
> >
> > ts0 is basically a per-table-entry variable - there's one for each entry
> > in the table, and it can only be accessed by events with matching keys.
> > The table owns the variable name, so you can't have two different tables
> > with the ts0 variable.
>
> Would you mean 'ts0' is a special name?
>
Not sure what you mean by a special name here...
> > So if we create a histogram on event1 and associate a variable ts0 with
> > it, any event hit on that histogram assigns to the corresponding entry's
> > ts0 instance.
> >
> > If we create a histogram on event2 which references ts0, it knows that
> > ts0 belongs to event1's histogram, and when there's a hit on event2, the
> > same key is used to look up the entry corresponding to that key on
> > event1, and if there's a matching entry, it grabs the value of ts0 from
> > that and subtracts it from the current event's value to produce the
> > latency or whatever it is.
> >
> > So, that's a long-winded way of saying that the name ts0 is global
> > across all tables (histograms) but an instance of ts0 is local to each
> > entry in the table that owns the name.
>
> Ah, what I concerned was the scope of name... not instance.
>
> Hmm, in that case, what about other variables in sched_switch?
> it seems to have woken_pid,woken_prio and wakeup_lat. Are those also
> becomes global instance?
> Since I saw below definition, I expected those were not global.
Actually, internally, every variable is fully scoped as
system/event/var_name, and that's what those refer to.
To simplify things for the user, I didn't want to require the user to
have to fully qualify variable names in the triggers where there most
commonly used e.g. common_timestamp.usecs-sched_wakeup.ts0, so just made
the simplification that a variable should be globally unique, and
therefore didn't implement any scope parsing in the trigger, assuming
unique names.
But I agree, there is some inconsistency with that and the below -
variables probably shouldn't be global, and if there are two variabls
with the same name we should allow the user to resolve the ambiguity by
explicitly specifying the full system/event/var_name or event/var_name
which usually suffices.
> > > > # echo 'wakeup_latency lat=sched_switch:wakeup_lat \
> > > > pid=sched_switch:woken_pid \
> > > > prio=sched_switch:woken_prio' >> \
> > > > /sys/kernel/debug/tracing/synthetic_events
>
> And if so, it is very unsure for users to check what variables are
> already defined. I think we'd better to have a 'global'tag for ts0.
>
> > > - What matches to what? onmatch() doesn't tell it.
> > >
> >
> > It's implied by the references to other events - in order for ts0 to be
> > resolved, it needs to find the match on event1. Also, the synthetic
> > event has references to variables on other events - in order to generate
> > the synthetic event, those variables also need to be resolved to
> > matching events - note that variables can also come from the current
> > event as well.
>
> I don't like such implications, which can make users lost in events easily,
> especially for triggers since we don't have the system-wide list of triggers.
> IMHO, since this interface is for a kind of programming, it should provide
> the abstract but consistent system model too. Implication will mislead
> users.
I think it might make a lot of sense at this point to actually create a
system-wide list of active triggers e.g. tracing/events/triggers or
something like that. It's something I've kind of wanted anyway, and
would be really useful if not indispensable for this. Actually, I
thought it might even be nice to have some kind of mini-fs or something
making it easy to group sets of related triggers and enable and
disable/remove them as a group, but a simple list would suffice too...
Tom
>
> > Hope that clears things up a bit (although the details under the covers
> > might seem confusing).
>
> 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
