Hi,
This is V6 of the inter-event tracing patchset, addressing input from
V5.
There were only a couple comments on the last version, which are
addressed here, in addition to a problems noted while testing, and a
fix for a problem found by the 0day bot:
- fixed parse_var_defs() again, moving the VARS_MAX check up to the
proper place. Also added a hist_err message to parse_assignment()
and removed the hist_err message from create_var_field(), since
it's no longer necessary given the above.
- fixed a bogus format string check in synth_field_fmt()
- merged in a fix from Fengguang Wu for a 0day bot-flagged sizeof
pointer problem (to 24/37, Add support for synthetic events)
- noticed that duplicate variables on the same trigger weren't being
detected and added a fix for that
Changes from V4:
- fixed struct noinline typo
- for the selftests, the following changes were made [from Rajvi Jingar]
- In extended error support test, changed last "&&" to redirect
error/output to /dev/null instead.
- In synthetic event create remove test, changed to same event
style in creating and removing and added a case to check adding
an event with wrong format
- Added -q option in grep since don’t need to show grep results.
- Changes to use newly added exit_pass()/exit_fail().
- in the variable reference handling patch, changed list_add_rcu to
list_add_tail_rcu when adding hist triggers. Using list_add_rcu
causes the triggers to be executed in reverse order to how they
were added, which in the case of multiple triggers with variables
on the same event can lead to variables being accessed before they
were set. [thanks to Rajvi for the bug report]
- noticed and fixed a couple problems with synthetic event refcounting
Changes from V3:
These mainly directly address the input from V3, but there are a
couple new things too - a new set of selftests (thanks to Rajvi Jingar
for those), and a new 'timestamp_mode' ftrace file making it easy to
see exactly what mode the ring buffer timestamping is in at any given
time (delta or absolute). The detailed list:
- fixed up 'if' parsing to also handle variables starting with 'if'
- added lots of comments to the field variable code
- added code to check and not fail if a field variable was already created
- fixed various typos,etc in commit messages
- moved target_hist_data fix from onmatch patch to field var patch
- fixed var_name leak in parse_var_defs()
- changed common_timestamp -> $common_timestamp in commit messages
- discovered and fixed a bug where variable references were not guaranteed unique
- added missing destroy_hist_field() in expression code
- separated synth event list management from synth event de/registration
- added missing 2nd-level variable reference checking in expressions
- added self-reference check to find_any_var_ref()
- removed HIST_FIELD_FL_VAR_ONLY and related code
- added WARN_ON_ONCE to hist_trigger_entry_print()
- changed absolute timestamps to allow coexistence with normal (delta) timestamps
- added a new read-only 'timestamp_mode' file to show current timestamp mode
- moved hist trigger Documentation into standalone histogram.txt file
- added new inter-event Documentation to histogram.txt
- removed redundant description of $common_timestamp usage from Documentation
- added missing .log2 line to Documentation
- added missing .usecs line to README pseudo-file
- added new set of selftests for various inter-event features [Rajvi Jingar]
Changes from V2:
- split out standalone bugfixes and cleanups to a separate patchset
- moved hunks around and merged patches as suggested
- added inter-event note in config option
- updates to duplicates patch [Vedang Patel]
- various memory allocation checks and use-after-free bugfix [Rajvi Jingar]
- various code improvements as suggested by Steve
- switched hist_field_flags over to using shifts
- added comments about synth_event mutex usage
- added example and explanation of field variables
- fixed field variable synth_event_mutex bug
- commented the whitespace handling in hist_trigger_func()
(the extra complexity is needed to allow spaces in actions)
- use smp_processor_id() instead of raw_ for cpu field
- added better description of aliases
- use static arrays instead of kmalloc for hist_err code, along with
various other cleanups
- removed 'tracing: Add support for dynamic tracepoints' since I was
mistaken about the need for this
Changes from V1:
There are too many changes to list in detail, most of them directly
addressing input from V1, but here are the major changes from V1
(thanks to everyone who reviewed V1 and thanks to both Vedang Patel
and Baohong Liu for their contributions and included patches):
- cleaned up the event format
- add types to synthetic event fields
- change to mutex ordering to avoid splat
- suppress output of the contributing trace events into the trace
buffer, unless explicitly enabled
- changed from sched_wakeup to sched_waking in the examples
- extended timestamp updates
- use a flag to signify dynamic tracepoints, rather than via api changes
- recursion level fixes
- removal of the possibility of tracing_map duplicates (Vedang)
- removal of duplicate-merging code (Vedang)
- max buffer absolute timestamp fix (Baohong)
- separate variable definition and assignment (Baohong)
- make variables instance-safe
- split a couple larger patches into smaller, various refactoring
- string handling fixes
- use function pointer for synthetic tracepoint func
- use union for actions
- various clean-ups as mentioned in review
- Documentation updates
- special-case recursion allowance for synthetic event generation
NOTE: The first patch in the series, 'tracing: Exclude 'generic
fields' from histograms' should go in regardless of the rest, since it
fixes a bug in existing code.
Thanks,
Tom
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.
One of the main motivations for adding this capability is to provide a
general-purpose base that existing existing tools such as the -RT
latency_hist patchset can be built upon, while at the same time
providing a simple way for users to track latencies (or any
inter-event quantity) generically between any two events.
Previous -RT latency_hist patchsets that take advantage of the trace
event subsystem have been submitted, but they essentially hard-code
special-case tracepoints and application logic in ways that can't be
reused. It seemed to me that rather than providing a one-off patchset
devoted specifically to generating the specific histograms in the
latency_hist patchset, it should be possible to build the same
functionality on top of a generic layer allowing users to do similar
things for other non-latency_hist applications.
In addition to preliminary patches that add some basic missing
functionality such as a common ringbuffer-derived timestamp and
dynamically-creatable tracepoints, the overall patchset is divided up
into a few different areas that combine to produce the overall goal
(The Documentation patch explains all the details):
- variables and simple expressions required to calculate a latency
In order to calculate a latency or any inter-event value,
something from one event needs to be saved and later retrieved,
and some operation such as subtraction or addition is performed on
it. This means some minimal form of variables and expressions,
which the first set of patches implements. Saving and retrieving
events to use in a latency calculation is normally done using a
hash table, and that's exactly what we have with trace event hist
triggers, so that's where variables are instantiated, set, and
retrieved. Basically, variables are set on one entry and
retrieved and used by a 'matching' event.
- 'synthetic' events, combining variables from other events
The trace event interface is based on pseudo-files associated with
individual events, so it wouldn't really make sense to have
quantities derived from multiple events attached to any one of
those events. For that reason, the patchset implements a means of
combining variables from other events into a separate 'synthetic'
event, which can be treated as if it were just like any other
trace event in the system.
- 'actions' generating synthetic events, among other things
Variables and synthetic events provide the data and data structure
for new events, but something still needs to actually generate an
event using that data. 'Actions' are expanded to provide that
capability. Though it hasn't been explicitly called as much
before, the default 'action' currently for a hist trigger is to
update the matching histogram entry's sum values. This patchset
essentially expands that to provide a new 'onmatch.trace(event)'
action that can be used to have one event generate another. The
mechanism is extensible to other actions, and in fact the patchset
also includes another, 'onmax(var).save(field,...)' that can be
used to save context whenever a value exceeds the previous maximum
(something also needed by latency_hist).
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_waking 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
creates 3 fields which will reference variables from other events:
# echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
/sys/kernel/debug/tracing/synthetic_events
Next we add a trigger to sched_waking, 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_waking/trigger
Next, we add a trigger to sched_switch. When the pid being switched
to matches the pid woken up by a previous sched_waking event, this
event grabs the ts0 variable 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 then generates the wakeup_latency synthetic event defined earlier
by 'invoking' it as a function using as parameters the wakeup_lat
variable and two sched_switch event fields directly:
# echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0: \
onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_prio) \
if next_comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
Finally, all we have left to do is create a standard histogram
simply naming the fields of the wakeup_latency synthetic event:
# echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
/sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
At any time, we can see the histogram output by simply reading the
synthetic/wakeup_latency/hist file:
# cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,prio,lat:vals=hitcount:sort=pid,lat:size=2048 [active]
#
{ pid: 2418, prio: 120, lat: 6 } hitcount: 21
{ pid: 2418, prio: 120, lat: 7 } hitcount: 62
{ pid: 2418, prio: 120, lat: 8 } hitcount: 44
{ pid: 2418, prio: 120, lat: 9 } hitcount: 34
{ pid: 2418, prio: 120, lat: 10 } hitcount: 16
{ pid: 2418, prio: 120, lat: 11 } hitcount: 5
{ pid: 2418, prio: 120, lat: 12 } hitcount: 2
{ pid: 2418, prio: 120, lat: 13 } hitcount: 2
{ pid: 2418, prio: 120, lat: 14 } hitcount: 1
{ pid: 2418, prio: 120, lat: 15 } hitcount: 1
{ pid: 2418, prio: 120, lat: 16 } hitcount: 1
{ pid: 2418, prio: 120, lat: 18 } hitcount: 2
{ pid: 2418, prio: 120, lat: 19 } hitcount: 1
{ pid: 2418, prio: 120, lat: 20 } hitcount: 1
{ pid: 2418, prio: 120, lat: 21 } hitcount: 1
{ pid: 2418, prio: 120, lat: 22 } hitcount: 1
{ pid: 2418, prio: 120, lat: 23 } hitcount: 1
{ pid: 2418, prio: 120, lat: 56 } hitcount: 1
{ pid: 2418, prio: 120, lat: 60 } hitcount: 1
{ pid: 2418, prio: 120, lat: 123 } hitcount: 1
{ pid: 2419, prio: 19, lat: 4 } hitcount: 12
{ pid: 2419, prio: 19, lat: 5 } hitcount: 230
{ pid: 2419, prio: 19, lat: 6 } hitcount: 343
{ pid: 2419, prio: 19, lat: 7 } hitcount: 485
{ pid: 2419, prio: 19, lat: 8 } hitcount: 574
{ pid: 2419, prio: 19, lat: 9 } hitcount: 164
{ pid: 2419, prio: 19, lat: 10 } hitcount: 51
{ pid: 2419, prio: 19, lat: 11 } hitcount: 36
{ pid: 2419, prio: 19, lat: 12 } hitcount: 23
{ pid: 2419, prio: 19, lat: 13 } hitcount: 16
{ pid: 2419, prio: 19, lat: 14 } hitcount: 13
{ pid: 2419, prio: 19, lat: 15 } hitcount: 5
{ pid: 2419, prio: 19, lat: 16 } hitcount: 6
{ pid: 2419, prio: 19, lat: 17 } hitcount: 5
{ pid: 2419, prio: 19, lat: 18 } hitcount: 1
{ pid: 2419, prio: 19, lat: 19 } hitcount: 2
{ pid: 2419, prio: 19, lat: 26 } hitcount: 1
{ pid: 2419, prio: 19, lat: 29 } hitcount: 1
{ pid: 2419, prio: 19, lat: 37 } hitcount: 1
{ pid: 2419, prio: 19, lat: 38 } hitcount: 1
{ pid: 2420, prio: 19, lat: 4 } hitcount: 1
{ pid: 2420, prio: 19, lat: 5 } hitcount: 45
{ pid: 2420, prio: 19, lat: 6 } hitcount: 96
{ pid: 2420, prio: 19, lat: 7 } hitcount: 227
{ pid: 2420, prio: 19, lat: 8 } hitcount: 558
{ pid: 2420, prio: 19, lat: 9 } hitcount: 236
{ pid: 2420, prio: 19, lat: 10 } hitcount: 67
{ pid: 2420, prio: 19, lat: 11 } hitcount: 27
{ pid: 2420, prio: 19, lat: 12 } hitcount: 17
{ pid: 2420, prio: 19, lat: 13 } hitcount: 12
{ pid: 2420, prio: 19, lat: 14 } hitcount: 11
{ pid: 2420, prio: 19, lat: 15 } hitcount: 8
{ pid: 2420, prio: 19, lat: 16 } hitcount: 6
{ pid: 2420, prio: 19, lat: 17 } hitcount: 3
{ pid: 2420, prio: 19, lat: 18 } hitcount: 1
{ pid: 2420, prio: 19, lat: 23 } hitcount: 1
{ pid: 2420, prio: 19, lat: 25 } hitcount: 1
{ pid: 2420, prio: 19, lat: 26 } hitcount: 1
{ pid: 2420, prio: 19, lat: 434 } hitcount: 1
Totals:
Hits: 3488
Entries: 59
Dropped: 0
The above output uses the .usecs modifier to common_timestamp, so
the latencies are reported in microseconds. The default, without
the modifier, is nanoseconds, but that's too fine-grained to put
directly into a histogram - for that however we can use the .log2
modifier on the 'lat' key. Otherwise the rest is the same:
# echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
/sys/kernel/debug/tracing/synthetic_events
# echo 'hist:keys=pid:ts0=$common_timestamp if comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_waking/trigger
# echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp-$ts0: \
onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_prio) \
if next_comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
/sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
# cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,prio,lat.log2:vals=hitcount:sort=pid,lat.log2:size=2048 [active]
#
{ pid: 2457, prio: 120, lat: ~ 2^13 } hitcount: 99
{ pid: 2457, prio: 120, lat: ~ 2^14 } hitcount: 91
{ pid: 2457, prio: 120, lat: ~ 2^15 } hitcount: 8
{ pid: 2458, prio: 19, lat: ~ 2^13 } hitcount: 1437
{ pid: 2458, prio: 19, lat: ~ 2^14 } hitcount: 519
{ pid: 2458, prio: 19, lat: ~ 2^15 } hitcount: 11
{ pid: 2458, prio: 19, lat: ~ 2^16 } hitcount: 2
{ pid: 2458, prio: 19, lat: ~ 2^18 } hitcount: 1
{ pid: 2459, prio: 19, lat: ~ 2^13 } hitcount: 874
{ pid: 2459, prio: 19, lat: ~ 2^14 } hitcount: 442
{ pid: 2459, prio: 19, lat: ~ 2^15 } hitcount: 4
Totals:
Hits: 3488
Entries: 11
Dropped: 0
====
Example - wakeup latency with onmax()
====
This example is the same as the previous ones, but here we're
additionally using the onmax() action to save some context (several
fields of the sched_switch event) whenever the latency (wakeup_lat)
exceeds the previous maximum.
As with the similar functionality of the -RT latency_hist
histograms, it's useful to be able to capture information about the
previous process, which potentially could have contributed to the
maximum latency that was saved.
# echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
/sys/kernel/debug/tracing/synthetic_events
# echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_waking/trigger
Here we add an onmax() action that saves some important fields of
the sched_switch event along with the maximum, in addition to
sending some of the same data to the synthetic event:
# echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0: \
onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm): \
onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_prio) \
if next_comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
/sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
To see the maximums and associated data for each pid, cat the
sched_switch event, as that's the event the onmax() action is
associated with:
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
# event histogram
#
# trigger info: hist:keys=next_pid:vals=hitcount:wakeup_lat=$common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm):onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,next_prio) if next_comm=="cyclictest" [active]
#
{ next_pid: 2803 } hitcount: 198
max: 55 next_comm: cyclictest prev_pid: 0
prev_prio: 120 prev_comm: swapper/2
{ next_pid: 2805 } hitcount: 1319
max: 53 next_comm: cyclictest prev_pid: 0
prev_prio: 120 prev_comm: swapper/1
{ next_pid: 2804 } hitcount: 1970
max: 79 next_comm: cyclictest prev_pid: 0
prev_prio: 120 prev_comm: swapper/0
Totals:
Hits: 3487
Entries: 3
Dropped: 0
And, verifying, we can see that the max latencies captured above
match the highest latencies for each thread in the wakeup_latency
histogram:
# cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,prio,lat:vals=hitcount:sort=pid,lat:size=2048 [active]
#
{ pid: 2803, prio: 120, lat: 6 } hitcount: 12
{ pid: 2803, prio: 120, lat: 7 } hitcount: 42
...
{ pid: 2803, prio: 120, lat: 22 } hitcount: 2
{ pid: 2803, prio: 120, lat: 55 } hitcount: 1
{ pid: 2804, prio: 19, lat: 4 } hitcount: 5
{ pid: 2804, prio: 19, lat: 5 } hitcount: 188
...
{ pid: 2804, prio: 19, lat: 30 } hitcount: 1
{ pid: 2804, prio: 19, lat: 79 } hitcount: 1
{ pid: 2805, prio: 19, lat: 5 } hitcount: 19
{ pid: 2805, prio: 19, lat: 6 } hitcount: 73
...
{ pid: 2805, prio: 19, lat: 44 } hitcount: 1
{ pid: 2805, prio: 19, lat: 53 } hitcount: 1
Totals:
Hits: 3487
Entries: 57
Dropped: 0
====
Example - combined wakeup and switchtime (wakeupswitch) latency
====
Finally, this example is quite a bit more involved, but that's
because it implements 3 latencies, one which is a combination of the
other two. This also, is something that the -RT latency_hist
patchset does and which this patchset adds generic support for.
The latency_hist patchset creates a few individual latency
histograms but also combines them into larger overall combined
histograms. For example, the time between when a thread is awakened
and when it actually continues executing in userspace is something
covered by a histogram, but it's also broken down into two
sub-histograms, one covering the time between sched_waking and the
time the thread is scheduled in (wakeup_latency as above), and the
time between when the thread is scheduled in and the time it
actually begins executing again (return from sys_nanosleep), covered
by a separate switchtime_latency histogram.
The below combines the wakeup_latency histogram from before, adds a
new switchtime_latency histogram, and another, wakeupswitch_latency,
that's a combination of the other two.
There isn't anything really new here, other than that the use of the
addition operator to add two latencies to produce the
wakeupswitch_latency.
First, we create the familiar wakeup_latency histogram:
# 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_waking/trigger
# echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:\
onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid) \
if next_comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
Here we save the wakeup_latency lat value as wakeup_lat for use
later in the combined latency:
# echo 'hist:keys=pid,lat:wakeup_lat=lat:sort=pid,lat' \
>> /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
Next, we create the switchtime_latency histogram:
# echo 'switchtime_latency u64 lat; pid_t pid' >> \
/sys/kernel/debug/tracing/synthetic_events
Here we save the sched_switch next_pid field as 'pid'. This is so
we can access the next_pid in the matching sys_exit_nanosleep event.
# echo 'hist:keys=next_pid:pid=next_pid:ts0=$common_timestamp.usecs \
if next_comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# echo 'hist:keys=common_pid:switchtime_lat=$common_timestamp.usecs-$ts0: \
onmatch(sched.sched_switch).switchtime_latency($switchtime_lat,$pid)' \
>> /sys/kernel/debug/tracing/events/syscalls/sys_exit_nanosleep/trigger
# echo 'hist:keys=pid,lat:sort=pid,lat' \
>> /sys/kernel/debug/tracing/events/synthetic/switchtime_latency/trigger
Finally, we create the combined wakeupswitch_latency:
# echo 'wakeupswitch_latency u64 lat; pid_t pid' >> \
/sys/kernel/debug/tracing/synthetic_events
Here we calculate the combined latency using the saved $wakeup_lat
variable from the wakeup_latency histogram and the lat value of the
switchtime_latency, save it as ws_lat and then use it to generate
the combined wakeupswitch latency:
# echo 'hist:keys=pid,lat:sort=pid,lat:ws_lat=$wakeup_lat+lat: \
onmatch(synthetic.wakeup_latency).wakeupswitch_latency($ws_lat,pid)' \
>> /sys/kernel/debug/tracing/events/synthetic/switchtime_latency/trigger
# echo 'hist:keys=pid,lat:sort=pid,lat' >> \
/sys/kernel/debug/tracing/events/synthetic/wakeupswitch_latency/trigger
After running our cyclictest workload, we can now look at each
histogram, starting with wakeup_latency:
# cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,lat:vals=hitcount:wakeup_lat=lat:sort=pid,lat:size=2048 [active]
#
{ pid: 4146, lat: 6 } hitcount: 8
{ pid: 4146, lat: 7 } hitcount: 50
{ pid: 4146, lat: 8 } hitcount: 53
{ pid: 4146, lat: 9 } hitcount: 34
{ pid: 4146, lat: 10 } hitcount: 22
{ pid: 4146, lat: 11 } hitcount: 6
{ pid: 4146, lat: 12 } hitcount: 4
{ pid: 4146, lat: 13 } hitcount: 1
{ pid: 4146, lat: 14 } hitcount: 4
{ pid: 4146, lat: 15 } hitcount: 2
{ pid: 4146, lat: 16 } hitcount: 2
{ pid: 4146, lat: 17 } hitcount: 3
{ pid: 4146, lat: 19 } hitcount: 1
{ pid: 4146, lat: 20 } hitcount: 2
{ pid: 4146, lat: 21 } hitcount: 4
{ pid: 4146, lat: 24 } hitcount: 1
{ pid: 4146, lat: 53 } hitcount: 1
{ pid: 4147, lat: 4 } hitcount: 1
{ pid: 4147, lat: 5 } hitcount: 156
{ pid: 4147, lat: 6 } hitcount: 344
{ pid: 4147, lat: 7 } hitcount: 560
{ pid: 4147, lat: 8 } hitcount: 540
{ pid: 4147, lat: 9 } hitcount: 195
{ pid: 4147, lat: 10 } hitcount: 50
{ pid: 4147, lat: 11 } hitcount: 38
{ pid: 4147, lat: 12 } hitcount: 26
{ pid: 4147, lat: 13 } hitcount: 13
{ pid: 4147, lat: 14 } hitcount: 12
{ pid: 4147, lat: 15 } hitcount: 10
{ pid: 4147, lat: 16 } hitcount: 3
{ pid: 4147, lat: 17 } hitcount: 2
{ pid: 4147, lat: 18 } hitcount: 4
{ pid: 4147, lat: 19 } hitcount: 2
{ pid: 4147, lat: 20 } hitcount: 1
{ pid: 4147, lat: 21 } hitcount: 1
{ pid: 4147, lat: 26 } hitcount: 1
{ pid: 4147, lat: 35 } hitcount: 1
{ pid: 4147, lat: 59 } hitcount: 1
{ pid: 4148, lat: 5 } hitcount: 38
{ pid: 4148, lat: 6 } hitcount: 229
{ pid: 4148, lat: 7 } hitcount: 219
{ pid: 4148, lat: 8 } hitcount: 486
{ pid: 4148, lat: 9 } hitcount: 181
{ pid: 4148, lat: 10 } hitcount: 59
{ pid: 4148, lat: 11 } hitcount: 27
{ pid: 4148, lat: 12 } hitcount: 23
{ pid: 4148, lat: 13 } hitcount: 16
{ pid: 4148, lat: 14 } hitcount: 7
{ pid: 4148, lat: 15 } hitcount: 7
{ pid: 4148, lat: 16 } hitcount: 6
{ pid: 4148, lat: 17 } hitcount: 2
{ pid: 4148, lat: 18 } hitcount: 2
{ pid: 4148, lat: 19 } hitcount: 4
{ pid: 4148, lat: 20 } hitcount: 3
{ pid: 4148, lat: 25 } hitcount: 1
{ pid: 4148, lat: 26 } hitcount: 1
{ pid: 4148, lat: 27 } hitcount: 1
{ pid: 4148, lat: 29 } hitcount: 2
{ pid: 4148, lat: 47 } hitcount: 1
Totals:
Hits: 3474
Entries: 59
Dropped: 0
Here's the switchtime histogram:
# cat /sys/kernel/debug/tracing/events/synthetic/switchtime_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,lat:vals=hitcount:sort=pid,lat:size=2048 [active]
#
{ pid: 4146, lat: 3 } hitcount: 11
{ pid: 4146, lat: 4 } hitcount: 32
{ pid: 4146, lat: 5 } hitcount: 65
{ pid: 4146, lat: 6 } hitcount: 37
{ pid: 4146, lat: 7 } hitcount: 35
{ pid: 4146, lat: 8 } hitcount: 5
{ pid: 4146, lat: 10 } hitcount: 1
{ pid: 4146, lat: 11 } hitcount: 1
{ pid: 4146, lat: 12 } hitcount: 1
{ pid: 4146, lat: 13 } hitcount: 1
{ pid: 4146, lat: 14 } hitcount: 1
{ pid: 4146, lat: 15 } hitcount: 1
{ pid: 4146, lat: 16 } hitcount: 2
{ pid: 4146, lat: 17 } hitcount: 1
{ pid: 4146, lat: 18 } hitcount: 1
{ pid: 4146, lat: 20 } hitcount: 1
{ pid: 4146, lat: 22 } hitcount: 1
{ pid: 4146, lat: 55 } hitcount: 1
{ pid: 4147, lat: 3 } hitcount: 554
{ pid: 4147, lat: 4 } hitcount: 999
{ pid: 4147, lat: 5 } hitcount: 193
{ pid: 4147, lat: 6 } hitcount: 102
{ pid: 4147, lat: 7 } hitcount: 38
{ pid: 4147, lat: 8 } hitcount: 21
{ pid: 4147, lat: 9 } hitcount: 8
{ pid: 4147, lat: 10 } hitcount: 10
{ pid: 4147, lat: 11 } hitcount: 11
{ pid: 4147, lat: 12 } hitcount: 7
{ pid: 4147, lat: 13 } hitcount: 2
{ pid: 4147, lat: 14 } hitcount: 2
{ pid: 4147, lat: 15 } hitcount: 5
{ pid: 4147, lat: 16 } hitcount: 2
{ pid: 4147, lat: 17 } hitcount: 3
{ pid: 4147, lat: 18 } hitcount: 2
{ pid: 4147, lat: 23 } hitcount: 2
{ pid: 4148, lat: 3 } hitcount: 245
{ pid: 4148, lat: 4 } hitcount: 761
{ pid: 4148, lat: 5 } hitcount: 152
{ pid: 4148, lat: 6 } hitcount: 64
{ pid: 4148, lat: 7 } hitcount: 25
{ pid: 4148, lat: 8 } hitcount: 7
{ pid: 4148, lat: 9 } hitcount: 14
{ pid: 4148, lat: 10 } hitcount: 11
{ pid: 4148, lat: 11 } hitcount: 12
{ pid: 4148, lat: 12 } hitcount: 6
{ pid: 4148, lat: 13 } hitcount: 2
{ pid: 4148, lat: 14 } hitcount: 7
{ pid: 4148, lat: 15 } hitcount: 2
{ pid: 4148, lat: 17 } hitcount: 2
{ pid: 4148, lat: 18 } hitcount: 1
{ pid: 4148, lat: 19 } hitcount: 1
{ pid: 4148, lat: 24 } hitcount: 1
{ pid: 4148, lat: 25 } hitcount: 1
{ pid: 4148, lat: 42 } hitcount: 1
Totals:
Hits: 3474
Entries: 54
Dropped: 0
And here's the combined wakeupswitch latency histogram:
# cat /sys/kernel/debug/tracing/events/synthetic/wakeupswitch_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,lat:vals=hitcount:sort=pid,lat:size=2048 [active]
#
{ pid: 4146, lat: 10 } hitcount: 16
{ pid: 4146, lat: 11 } hitcount: 18
{ pid: 4146, lat: 12 } hitcount: 25
{ pid: 4146, lat: 13 } hitcount: 38
{ pid: 4146, lat: 14 } hitcount: 25
{ pid: 4146, lat: 15 } hitcount: 14
{ pid: 4146, lat: 16 } hitcount: 17
{ pid: 4146, lat: 17 } hitcount: 14
{ pid: 4146, lat: 18 } hitcount: 7
{ pid: 4146, lat: 19 } hitcount: 1
{ pid: 4146, lat: 20 } hitcount: 3
{ pid: 4146, lat: 21 } hitcount: 2
{ pid: 4146, lat: 22 } hitcount: 1
{ pid: 4146, lat: 23 } hitcount: 1
{ pid: 4146, lat: 24 } hitcount: 1
{ pid: 4146, lat: 25 } hitcount: 2
{ pid: 4146, lat: 26 } hitcount: 2
{ pid: 4146, lat: 29 } hitcount: 1
{ pid: 4146, lat: 30 } hitcount: 1
{ pid: 4146, lat: 32 } hitcount: 1
{ pid: 4146, lat: 33 } hitcount: 2
{ pid: 4146, lat: 36 } hitcount: 1
{ pid: 4146, lat: 37 } hitcount: 1
{ pid: 4146, lat: 38 } hitcount: 1
{ pid: 4146, lat: 39 } hitcount: 1
{ pid: 4146, lat: 73 } hitcount: 1
{ pid: 4146, lat: 76 } hitcount: 1
{ pid: 4147, lat: 8 } hitcount: 54
{ pid: 4147, lat: 9 } hitcount: 205
{ pid: 4147, lat: 10 } hitcount: 391
{ pid: 4147, lat: 11 } hitcount: 544
{ pid: 4147, lat: 12 } hitcount: 342
{ pid: 4147, lat: 13 } hitcount: 141
{ pid: 4147, lat: 14 } hitcount: 68
{ pid: 4147, lat: 15 } hitcount: 46
{ pid: 4147, lat: 16 } hitcount: 42
{ pid: 4147, lat: 17 } hitcount: 23
{ pid: 4147, lat: 18 } hitcount: 23
{ pid: 4147, lat: 19 } hitcount: 17
{ pid: 4147, lat: 20 } hitcount: 8
{ pid: 4147, lat: 21 } hitcount: 7
{ pid: 4147, lat: 22 } hitcount: 7
{ pid: 4147, lat: 23 } hitcount: 8
{ pid: 4147, lat: 24 } hitcount: 4
{ pid: 4147, lat: 25 } hitcount: 6
{ pid: 4147, lat: 26 } hitcount: 4
{ pid: 4147, lat: 27 } hitcount: 1
{ pid: 4147, lat: 28 } hitcount: 4
{ pid: 4147, lat: 29 } hitcount: 2
{ pid: 4147, lat: 30 } hitcount: 3
{ pid: 4147, lat: 31 } hitcount: 3
{ pid: 4147, lat: 32 } hitcount: 1
{ pid: 4147, lat: 34 } hitcount: 1
{ pid: 4147, lat: 35 } hitcount: 3
{ pid: 4147, lat: 36 } hitcount: 1
{ pid: 4147, lat: 50 } hitcount: 1
{ pid: 4147, lat: 71 } hitcount: 1
{ pid: 4148, lat: 8 } hitcount: 2
{ pid: 4148, lat: 9 } hitcount: 100
{ pid: 4148, lat: 10 } hitcount: 156
{ pid: 4148, lat: 11 } hitcount: 340
{ pid: 4148, lat: 12 } hitcount: 341
{ pid: 4148, lat: 13 } hitcount: 139
{ pid: 4148, lat: 14 } hitcount: 55
{ pid: 4148, lat: 15 } hitcount: 42
{ pid: 4148, lat: 16 } hitcount: 24
{ pid: 4148, lat: 17 } hitcount: 17
{ pid: 4148, lat: 18 } hitcount: 18
{ pid: 4148, lat: 19 } hitcount: 17
{ pid: 4148, lat: 20 } hitcount: 7
{ pid: 4148, lat: 21 } hitcount: 4
{ pid: 4148, lat: 22 } hitcount: 7
{ pid: 4148, lat: 23 } hitcount: 6
{ pid: 4148, lat: 24 } hitcount: 3
{ pid: 4148, lat: 25 } hitcount: 7
{ pid: 4148, lat: 26 } hitcount: 5
{ pid: 4148, lat: 27 } hitcount: 3
{ pid: 4148, lat: 28 } hitcount: 3
{ pid: 4148, lat: 29 } hitcount: 1
{ pid: 4148, lat: 30 } hitcount: 4
{ pid: 4148, lat: 31 } hitcount: 1
{ pid: 4148, lat: 32 } hitcount: 2
{ pid: 4148, lat: 33 } hitcount: 3
{ pid: 4148, lat: 34 } hitcount: 1
{ pid: 4148, lat: 36 } hitcount: 1
{ pid: 4148, lat: 37 } hitcount: 2
{ pid: 4148, lat: 38 } hitcount: 1
{ pid: 4148, lat: 41 } hitcount: 1
{ pid: 4148, lat: 53 } hitcount: 1
{ pid: 4148, lat: 71 } hitcount: 1
Totals:
Hits: 3474
Entries: 90
Dropped: 0
Finally, just to show that synthetic events are indeed just like any
other event as far as the event subsystem is concerned, we can
enable the synthetic events and see the events appear in the trace
buffer:
# echo 1 > /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/enable
# echo 1 > /sys/kernel/debug/tracing/events/synthetic/switchtime_latency/enable
# echo 1 > /sys/kernel/debug/tracing/events/synthetic/wakeupswitch_latency/enable
Below is a snippet of the contents of the trace file produced when
the above histograms were generated:
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 10503/10503 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [001] d..2 23532.240146: wakeup_latency: lat=4, pid=6853
cyclictest-6853 [001] .... 23532.240153: switchtime_latency: lat=7, pid=6853
cyclictest-6853 [001] .... 23532.240157: wakeupswitch_latency: lat=11, pid=6853
gnome-terminal--2500 [001] d..2 23532.240672: wakeup_latency: lat=5, pid=6854
cyclictest-6854 [001] .... 23532.240676: switchtime_latency: lat=4, pid=6854
cyclictest-6854 [001] .... 23532.240677: wakeupswitch_latency: lat=9, pid=6854
gnome-terminal--2500 [001] d..2 23532.241169: wakeup_latency: lat=4, pid=6853
cyclictest-6853 [001] .... 23532.241172: switchtime_latency: lat=3, pid=6853
cyclictest-6853 [001] .... 23532.241174: wakeupswitch_latency: lat=7, pid=6853
<idle>-0 [001] d..2 23532.242189: wakeup_latency: lat=6, pid=6853
cyclictest-6853 [001] .... 23532.242195: switchtime_latency: lat=8, pid=6853
<idle>-0 [000] d..2 23532.242196: wakeup_latency: lat=12, pid=6854
cyclictest-6853 [001] .... 23532.240146: wakeupswitch_latency: lat=14, pid=6853
cyclictest-6854 [000] .... 23532.242196: switchtime_latency: lat=4, pid=6854
<idle>-0 [001] d..2 23532.240146: wakeup_latency: lat=2, pid=6853
cyclictest-6854 [000] .... 23532.242196: wakeupswitch_latency: lat=16, pid=6854
cyclictest-6853 [001] .... 23532.240146: switchtime_latency: lat=3, pid=6853
...
One quick note about usage - the introduction of variables and
actions obviously makes it harder to determine the cause of a hist
trigger command failure - 'Invalid argument' is no longer sufficient
in many cases.
For that reason, a new 'extended error' mechanism has been added to
hist triggers, initially focused on variable and action-related
errors, but something that could possibly expanded to other error
conditions later.
To make use of it, simply read the 'hist' file of the event that was
the target of the command.
In this example, we've entered the same command twice, resulting in
an attempt to define the same variable (ts0) twice. After seeing
the 'Invalid argument' error for the command, we read the same
event's hist file and see a message to that effect at the bottom of
the file:
# echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_waking/trigger
# echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="cyclictest"' >> \
/sys/kernel/debug/tracing/events/sched/sched_waking/trigger
-su: echo: write error: Invalid argument
# cat /sys/kernel/debug/tracing/events/sched/sched_waking/hist
# event histogram
#
#
Totals:
Hits: 0
Entries: 0
Dropped: 0
ERROR: Variable already defined: ts0
Last command: keys=pid:ts0=$common_timestamp.usecs if comm=="cyclictest"
The following changes since commit a96a5037ed0f52e2d86739f4a1ef985bd036e575:
tracing, thermal: Hide cpu cooling trace events when not in use (2017-10-17 19:03:09 -0400)
are available in the git repository at:
https://github.com/tzanussi/linux-trace-inter-event.git tzanussi/inter-event-v6
https://github.com/tzanussi/linux-trace-inter-event/tree/tzanussi/inter-event-v6
Rajvi Jingar (1):
selftests: ftrace: Add inter-event hist triggers testcases
Tom Zanussi (34):
tracing: Move hist trigger Documentation to histogram.txt
tracing: Add Documentation for log2 modifier
ring-buffer: Add interface for setting absolute time stamps
ring-buffer: Redefine the unimplemented RINGBUF_TYPE_TIME_STAMP
tracing: Add timestamp_mode trace file
tracing: Give event triggers access to ring_buffer_event
tracing: Add ring buffer event param to hist field functions
tracing: Break out hist trigger assignment parsing
tracing: Add hist trigger timestamp support
tracing: Add per-element variable support to tracing_map
tracing: Add hist_data member to hist_field
tracing: Add usecs modifier for hist trigger timestamps
tracing: Add variable support to hist triggers
tracing: Account for variables in named trigger compatibility
tracing: Move get_hist_field_flags()
tracing: Add simple expression support to hist triggers
tracing: Generalize per-element hist trigger data
tracing: Pass tracing_map_elt to hist_field accessor functions
tracing: Add hist_field 'type' field
tracing: Add variable reference handling to hist triggers
tracing: Add hist trigger action hook
tracing: Add support for 'synthetic' events
tracing: Add support for 'field variables'
tracing: Add 'onmatch' hist trigger action support
tracing: Add 'onmax' hist trigger action support
tracing: Allow whitespace to surround hist trigger filter
tracing: Add cpu field for hist triggers
tracing: Add hist trigger support for variable reference aliases
tracing: Add 'last error' error facility for hist triggers
tracing: Add inter-event hist trigger Documentation
tracing: Make tracing_set_clock() non-static
tracing: Add a clock attribute for hist triggers
tracing: Increase trace_recursive_lock() limit for synthetic events
tracing: Add inter-event blurb to HIST_TRIGGERS config option
Vedang Patel (2):
tracing: Add support to detect and avoid duplicates
tracing: Remove code which merges duplicates
Documentation/trace/events.txt | 1548 +------
Documentation/trace/ftrace.txt | 24 +
Documentation/trace/histogram.txt | 1998 ++++++++
include/linux/ring_buffer.h | 14 +-
include/linux/trace_events.h | 14 +-
kernel/trace/Kconfig | 3 +
kernel/trace/ring_buffer.c | 125 +-
kernel/trace/trace.c | 97 +-
kernel/trace/trace.h | 18 +-
kernel/trace/trace_events_hist.c | 4748 ++++++++++++++++++--
kernel/trace/trace_events_trigger.c | 53 +-
kernel/trace/tracing_map.c | 232 +-
kernel/trace/tracing_map.h | 18 +-
tools/testing/selftests/ftrace/test.d/functions | 7 +
.../inter-event/trigger-extended-error-support.tc | 39 +
.../inter-event/trigger-field-variable-support.tc | 54 +
.../trigger-inter-event-combined-hist.tc | 58 +
.../inter-event/trigger-onmatch-action-hist.tc | 50 +
.../trigger-onmatch-onmax-action-hist.tc | 50 +
.../inter-event/trigger-onmax-action-hist.tc | 48 +
.../trigger-synthetic-event-createremove.tc | 54 +
21 files changed, 7146 insertions(+), 2106 deletions(-)
create mode 100644 Documentation/trace/histogram.txt
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc
--
1.9.3
From 1584354522843374359@xxx Fri Nov 17 22:36:56 +0000 2017
X-GM-THRID: 1584336194586684476
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
From: Rajvi Jingar <[email protected]>
This adds inter-event hist triggers testcases which covers following:
- create/remove synthetic event
- disable histogram for synthetic event
- extended error support
- field variable support
- histogram variables
- histogram trigger onmatch action
- histogram trigger onmax action
- histogram trigger onmatch-onmax action
- simple expression support
- combined histogram
Here is the test result.
=== Ftrace unit tests ===
[1] event trigger - test extended error support [PASS]
[2] event trigger - test field variable support [PASS]
[3] event trigger - test inter-event combined histogram trigger [PASS]
[4] event trigger - test inter-event histogram trigger onmatch action [PASS]
[5] event trigger - test inter-event histogram trigger onmatch-onmax action [PASS]
[6] event trigger - test inter-event histogram trigger onmax action [PASS]
[7] event trigger - test synthetic event create remove [PASS]
Signed-off-by: Rajvi Jingar <[email protected]>
Signed-off-by: Tom Zanussi <[email protected]>
---
tools/testing/selftests/ftrace/test.d/functions | 7 +++
.../inter-event/trigger-extended-error-support.tc | 39 +++++++++++++++
.../inter-event/trigger-field-variable-support.tc | 54 ++++++++++++++++++++
.../trigger-inter-event-combined-hist.tc | 58 ++++++++++++++++++++++
.../inter-event/trigger-onmatch-action-hist.tc | 50 +++++++++++++++++++
.../trigger-onmatch-onmax-action-hist.tc | 50 +++++++++++++++++++
.../inter-event/trigger-onmax-action-hist.tc | 48 ++++++++++++++++++
.../trigger-synthetic-event-createremove.tc | 54 ++++++++++++++++++++
8 files changed, 360 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index f2019b3..17afa65 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -55,6 +55,13 @@ disable_events() {
echo 0 > events/enable
}
+clear_synthetic_events() { # reset all current synthetic events
+ grep -v ^# synthetic_events |
+ while read line; do
+ echo "!$line" >> synthetic_events
+ done
+}
+
initialize_ftrace() { # Reset ftrace to initial-state
# As the initial state, ftrace will be set to nop tracer,
# no events, no triggers, no filters, no function filters,
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
new file mode 100644
index 0000000..f7691ff
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
@@ -0,0 +1,39 @@
+#!/bin/sh
+# description: event trigger - test extended error support
+
+
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+reset_tracer
+do_reset
+
+echo "Test extended error support"
+echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
+echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger &>/dev/null
+if ! grep -q "ERROR:" events/sched/sched_wakeup/hist; then
+ fail "Failed to generate extended error in histogram"
+fi
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc
new file mode 100644
index 0000000..4665733
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc
@@ -0,0 +1,54 @@
+#!/bin/sh
+# description: event trigger - test field variable support
+
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+clear_synthetic_events
+reset_tracer
+do_reset
+
+echo "Test field variable support"
+
+echo 'wakeup_latency u64 lat; pid_t pid; int prio; char comm[16]' > synthetic_events
+echo 'hist:keys=comm:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_waking/trigger
+echo 'hist:keys=next_comm:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,sched.sched_waking.prio,next_comm) if next_comm=="ping"' > events/sched/sched_switch/trigger
+echo 'hist:keys=pid,prio,comm:vals=lat:sort=pid,prio' > events/synthetic/wakeup_latency/trigger
+
+ping localhost -c 3
+if ! grep -q "ping" events/synthetic/wakeup_latency/hist; then
+ fail "Failed to create inter-event histogram"
+fi
+
+if ! grep -q "synthetic_prio=prio" events/sched/sched_waking/hist; then
+ fail "Failed to create histogram with field variable"
+fi
+
+echo '!hist:keys=next_comm:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,sched.sched_waking.prio,next_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger
+
+if grep -q "synthetic_prio=prio" events/sched/sched_waking/hist; then
+ fail "Failed to remove histogram with field variable"
+fi
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc
new file mode 100644
index 0000000..8d00064
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc
@@ -0,0 +1,58 @@
+#!/bin/sh
+# description: event trigger - test inter-event combined histogram trigger
+
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+reset_tracer
+do_reset
+clear_synthetic_events
+
+echo "Test create synthetic event"
+
+echo 'waking_latency u64 lat pid_t pid' > synthetic_events
+if [ ! -d events/synthetic/waking_latency ]; then
+ fail "Failed to create waking_latency synthetic event"
+fi
+
+echo "Test combined histogram"
+
+echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_waking/trigger
+echo 'hist:keys=pid:waking_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).waking_latency($waking_lat,pid) if comm=="ping"' > events/sched/sched_wakeup/trigger
+echo 'hist:keys=pid,lat:sort=pid,lat' > events/synthetic/waking_latency/trigger
+
+echo 'wakeup_latency u64 lat pid_t pid' >> synthetic_events
+echo 'hist:keys=pid:ts1=$common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger
+echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts1:onmatch(sched.sched_wakeup).wakeup_latency($wakeup_lat,next_pid) if next_comm=="ping"' > events/sched/sched_switch/trigger
+
+echo 'waking+wakeup_latency u64 lat; pid_t pid' >> synthetic_events
+echo 'hist:keys=pid,lat:sort=pid,lat:ww_lat=$waking_lat+$wakeup_lat:onmatch(synthetic.wakeup_latency).waking+wakeup_latency($ww_lat,pid)' >> events/synthetic/wakeup_latency/trigger
+echo 'hist:keys=pid,lat:sort=pid,lat' >> events/synthetic/waking+wakeup_latency/trigger
+
+ping localhost -c 3
+if ! grep -q "pid:" events/synthetic/waking+wakeup_latency/hist; then
+ fail "Failed to create combined histogram"
+fi
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
new file mode 100644
index 0000000..ac13051
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
@@ -0,0 +1,50 @@
+#!/bin/sh
+# description: event trigger - test inter-event histogram trigger onmatch action
+
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+clear_synthetic_events
+reset_tracer
+do_reset
+
+echo "Test create synthetic event"
+
+echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events
+if [ ! -d events/synthetic/wakeup_latency ]; then
+ fail "Failed to create wakeup_latency synthetic event"
+fi
+
+echo "Test create histogram for synthetic event"
+echo "Test histogram variables,simple expression support and onmatch action"
+
+echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
+echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).wakeup_latency($wakeup_lat,next_pid,next_comm) if next_comm=="ping"' > events/sched/sched_switch/trigger
+echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > events/synthetic/wakeup_latency/trigger
+ping localhost -c 5
+if ! grep -q "ping" events/synthetic/wakeup_latency/hist; then
+ fail "Failed to create onmatch action inter-event histogram"
+fi
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc
new file mode 100644
index 0000000..39bf19d
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc
@@ -0,0 +1,50 @@
+#!/bin/sh
+# description: event trigger - test inter-event histogram trigger onmatch-onmax action
+
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+clear_synthetic_events
+reset_tracer
+do_reset
+
+echo "Test create synthetic event"
+
+echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events
+if [ ! -d events/synthetic/wakeup_latency ]; then
+ fail "Failed to create wakeup_latency synthetic event"
+fi
+
+echo "Test create histogram for synthetic event"
+echo "Test histogram variables,simple expression support and onmatch-onmax action"
+
+echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
+echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).wakeup_latency($wakeup_lat,next_pid,next_comm):onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger
+echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > events/synthetic/wakeup_latency/trigger
+ping localhost -c 5
+if [ ! grep -q "ping" events/synthetic/wakeup_latency/hist -o ! grep -q "max:" events/sched/sched_switch/hist]; then
+ fail "Failed to create onmatch-onmax action inter-event histogram"
+fi
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc
new file mode 100644
index 0000000..65f55a5
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc
@@ -0,0 +1,48 @@
+#!/bin/sh
+# description: event trigger - test inter-event histogram trigger onmax action
+
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+clear_synthetic_events
+reset_tracer
+do_reset
+
+echo "Test create synthetic event"
+
+echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events
+if [ ! -d events/synthetic/wakeup_latency ]; then
+ fail "Failed to create wakeup_latency synthetic event"
+fi
+
+echo "Test onmax action"
+
+echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' >> events/sched/sched_waking/trigger
+echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger
+ping localhost -c 3
+if ! grep -q "max:" events/sched/sched_switch/hist; then
+ fail "Failed to create onmax action inter-event histogram"
+fi
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc
new file mode 100644
index 0000000..cef1137
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc
@@ -0,0 +1,54 @@
+#!/bin/sh
+# description: event trigger - test synthetic event create remove
+do_reset() {
+ reset_trigger
+ echo > set_event
+ clear_trace
+}
+
+fail() { #msg
+ do_reset
+ echo $1
+ exit_fail
+}
+
+if [ ! -f set_event ]; then
+ echo "event tracing is not supported"
+ exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+ echo "synthetic event is not supported"
+ exit_unsupported
+fi
+
+clear_synthetic_events
+reset_tracer
+do_reset
+
+echo "Test create synthetic event"
+
+echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events
+if [ ! -d events/synthetic/wakeup_latency ]; then
+ fail "Failed to create wakeup_latency synthetic event"
+fi
+
+reset_trigger
+
+echo "Test create synthetic event with an error"
+echo 'wakeup_latency u64 lat pid_t pid char' > synthetic_events > /dev/null
+if [ -d events/synthetic/wakeup_latency ]; then
+ fail "Created wakeup_latency synthetic event with an invalid format"
+fi
+
+reset_trigger
+
+echo "Test remove synthetic event"
+echo '!wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events
+if [ -d events/synthetic/wakeup_latency ]; then
+ fail "Failed to delete wakeup_latency synthetic event"
+fi
+
+do_reset
+
+exit 0
--
1.9.3
From 1586841000520268551@xxx Fri Dec 15 09:18:26 +0000 2017
X-GM-THRID: 1584468868846641053
X-Gmail-Labels: Inbox,Category Forums
The ring_buffer event can provide a timestamp that may be useful to
various triggers - pass it into the handlers for that purpose.
Signed-off-by: Tom Zanussi <[email protected]>
---
include/linux/trace_events.h | 14 ++++++-----
kernel/trace/trace.h | 9 +++----
kernel/trace/trace_events_hist.c | 11 +++++----
kernel/trace/trace_events_trigger.c | 47 +++++++++++++++++++++++--------------
4 files changed, 49 insertions(+), 32 deletions(-)
diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index ca4e67e..2d1bb0f 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -406,11 +406,13 @@ enum event_trigger_type {
extern int filter_match_preds(struct event_filter *filter, void *rec);
-extern enum event_trigger_type event_triggers_call(struct trace_event_file *file,
- void *rec);
-extern void event_triggers_post_call(struct trace_event_file *file,
- enum event_trigger_type tt,
- void *rec);
+extern enum event_trigger_type
+event_triggers_call(struct trace_event_file *file, void *rec,
+ struct ring_buffer_event *event);
+extern void
+event_triggers_post_call(struct trace_event_file *file,
+ enum event_trigger_type tt,
+ void *rec, struct ring_buffer_event *event);
bool trace_event_ignore_this_pid(struct trace_event_file *trace_file);
@@ -430,7 +432,7 @@ extern void event_triggers_post_call(struct trace_event_file *file,
if (!(eflags & EVENT_FILE_FL_TRIGGER_COND)) {
if (eflags & EVENT_FILE_FL_TRIGGER_MODE)
- event_triggers_call(file, NULL);
+ event_triggers_call(file, NULL, NULL);
if (eflags & EVENT_FILE_FL_SOFT_DISABLED)
return true;
if (eflags & EVENT_FILE_FL_PID_FILTER)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 4d8bde0..bbfb577 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1293,7 +1293,7 @@ static inline void trace_buffer_unlock_commit(struct trace_array *tr,
unsigned long eflags = file->flags;
if (eflags & EVENT_FILE_FL_TRIGGER_COND)
- *tt = event_triggers_call(file, entry);
+ *tt = event_triggers_call(file, entry, event);
if (test_bit(EVENT_FILE_FL_SOFT_DISABLED_BIT, &file->flags) ||
(unlikely(file->flags & EVENT_FILE_FL_FILTERED) &&
@@ -1330,7 +1330,7 @@ static inline void trace_buffer_unlock_commit(struct trace_array *tr,
trace_buffer_unlock_commit(file->tr, buffer, event, irq_flags, pc);
if (tt)
- event_triggers_post_call(file, tt, entry);
+ event_triggers_post_call(file, tt, entry, event);
}
/**
@@ -1363,7 +1363,7 @@ static inline void trace_buffer_unlock_commit(struct trace_array *tr,
irq_flags, pc, regs);
if (tt)
- event_triggers_post_call(file, tt, entry);
+ event_triggers_post_call(file, tt, entry, event);
}
#define FILTER_PRED_INVALID ((unsigned short)-1)
@@ -1588,7 +1588,8 @@ extern void set_named_trigger_data(struct event_trigger_data *data,
*/
struct event_trigger_ops {
void (*func)(struct event_trigger_data *data,
- void *rec);
+ void *rec,
+ struct ring_buffer_event *rbe);
int (*init)(struct event_trigger_ops *ops,
struct event_trigger_data *data);
void (*free)(struct event_trigger_ops *ops,
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 712260e..63a1912 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -909,7 +909,8 @@ static inline void add_to_key(char *compound_key, void *key,
memcpy(compound_key + key_field->offset, key, size);
}
-static void event_hist_trigger(struct event_trigger_data *data, void *rec)
+static void event_hist_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
struct hist_trigger_data *hist_data = data->private_data;
bool use_compound_key = (hist_data->n_keys > 1);
@@ -1658,7 +1659,8 @@ __init int register_trigger_hist_cmd(void)
}
static void
-hist_enable_trigger(struct event_trigger_data *data, void *rec)
+hist_enable_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
struct enable_trigger_data *enable_data = data->private_data;
struct event_trigger_data *test;
@@ -1674,7 +1676,8 @@ __init int register_trigger_hist_cmd(void)
}
static void
-hist_enable_count_trigger(struct event_trigger_data *data, void *rec)
+hist_enable_count_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (!data->count)
return;
@@ -1682,7 +1685,7 @@ __init int register_trigger_hist_cmd(void)
if (data->count != -1)
(data->count)--;
- hist_enable_trigger(data, rec);
+ hist_enable_trigger(data, rec, event);
}
static struct event_trigger_ops hist_enable_trigger_ops = {
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index f2ac9d4..9b0fe31 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -63,7 +63,8 @@ void trigger_data_free(struct event_trigger_data *data)
* any trigger that should be deferred, ETT_NONE if nothing to defer.
*/
enum event_trigger_type
-event_triggers_call(struct trace_event_file *file, void *rec)
+event_triggers_call(struct trace_event_file *file, void *rec,
+ struct ring_buffer_event *event)
{
struct event_trigger_data *data;
enum event_trigger_type tt = ETT_NONE;
@@ -76,7 +77,7 @@ enum event_trigger_type
if (data->paused)
continue;
if (!rec) {
- data->ops->func(data, rec);
+ data->ops->func(data, rec, event);
continue;
}
filter = rcu_dereference_sched(data->filter);
@@ -86,7 +87,7 @@ enum event_trigger_type
tt |= data->cmd_ops->trigger_type;
continue;
}
- data->ops->func(data, rec);
+ data->ops->func(data, rec, event);
}
return tt;
}
@@ -108,7 +109,7 @@ enum event_trigger_type
void
event_triggers_post_call(struct trace_event_file *file,
enum event_trigger_type tt,
- void *rec)
+ void *rec, struct ring_buffer_event *event)
{
struct event_trigger_data *data;
@@ -116,7 +117,7 @@ enum event_trigger_type
if (data->paused)
continue;
if (data->cmd_ops->trigger_type & tt)
- data->ops->func(data, rec);
+ data->ops->func(data, rec, event);
}
}
EXPORT_SYMBOL_GPL(event_triggers_post_call);
@@ -909,7 +910,8 @@ void set_named_trigger_data(struct event_trigger_data *data,
}
static void
-traceon_trigger(struct event_trigger_data *data, void *rec)
+traceon_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (tracing_is_on())
return;
@@ -918,7 +920,8 @@ void set_named_trigger_data(struct event_trigger_data *data,
}
static void
-traceon_count_trigger(struct event_trigger_data *data, void *rec)
+traceon_count_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (tracing_is_on())
return;
@@ -933,7 +936,8 @@ void set_named_trigger_data(struct event_trigger_data *data,
}
static void
-traceoff_trigger(struct event_trigger_data *data, void *rec)
+traceoff_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (!tracing_is_on())
return;
@@ -942,7 +946,8 @@ void set_named_trigger_data(struct event_trigger_data *data,
}
static void
-traceoff_count_trigger(struct event_trigger_data *data, void *rec)
+traceoff_count_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (!tracing_is_on())
return;
@@ -1039,13 +1044,15 @@ void set_named_trigger_data(struct event_trigger_data *data,
#ifdef CONFIG_TRACER_SNAPSHOT
static void
-snapshot_trigger(struct event_trigger_data *data, void *rec)
+snapshot_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
tracing_snapshot();
}
static void
-snapshot_count_trigger(struct event_trigger_data *data, void *rec)
+snapshot_count_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (!data->count)
return;
@@ -1053,7 +1060,7 @@ void set_named_trigger_data(struct event_trigger_data *data,
if (data->count != -1)
(data->count)--;
- snapshot_trigger(data, rec);
+ snapshot_trigger(data, rec, event);
}
static int
@@ -1132,13 +1139,15 @@ static __init int register_trigger_snapshot_cmd(void)
#define STACK_SKIP 3
static void
-stacktrace_trigger(struct event_trigger_data *data, void *rec)
+stacktrace_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
trace_dump_stack(STACK_SKIP);
}
static void
-stacktrace_count_trigger(struct event_trigger_data *data, void *rec)
+stacktrace_count_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
if (!data->count)
return;
@@ -1146,7 +1155,7 @@ static __init int register_trigger_snapshot_cmd(void)
if (data->count != -1)
(data->count)--;
- stacktrace_trigger(data, rec);
+ stacktrace_trigger(data, rec, event);
}
static int
@@ -1208,7 +1217,8 @@ static __init void unregister_trigger_traceon_traceoff_cmds(void)
}
static void
-event_enable_trigger(struct event_trigger_data *data, void *rec)
+event_enable_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
struct enable_trigger_data *enable_data = data->private_data;
@@ -1219,7 +1229,8 @@ static __init void unregister_trigger_traceon_traceoff_cmds(void)
}
static void
-event_enable_count_trigger(struct event_trigger_data *data, void *rec)
+event_enable_count_trigger(struct event_trigger_data *data, void *rec,
+ struct ring_buffer_event *event)
{
struct enable_trigger_data *enable_data = data->private_data;
@@ -1233,7 +1244,7 @@ static __init void unregister_trigger_traceon_traceoff_cmds(void)
if (data->count != -1)
(data->count)--;
- event_enable_trigger(data, rec);
+ event_enable_trigger(data, rec, event);
}
int event_enable_trigger_print(struct seq_file *m,
--
1.9.3
From 1584610986218328188@xxx Mon Nov 20 18:33:19 +0000 2017
X-GM-THRID: 1584610986218328188
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Appending .usecs onto a $common_timestamp field will cause the
timestamp value to be in microseconds instead of the default
nanoseconds. A typical latency histogram using usecs would look like
this:
# echo 'hist:keys=pid,prio:ts0=$common_timestamp.usecs ...
# echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0 ...
This also adds an external trace_clock_in_ns() to trace.c for the
timestamp conversion.
Signed-off-by: Tom Zanussi <[email protected]>
---
Documentation/trace/histogram.txt | 1 +
kernel/trace/trace.c | 13 +++++++++++--
kernel/trace/trace.h | 2 ++
kernel/trace/trace_events_hist.c | 28 ++++++++++++++++++++++------
4 files changed, 36 insertions(+), 8 deletions(-)
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index a4143f04a..d1d92ed 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -74,6 +74,7 @@
.syscall display a syscall id as a system call name
.execname display a common_pid as a program name
.log2 display log2 value rather than raw number
+ .usecs display a $common_timestamp in microseconds
Note that in general the semantics of a given field aren't
interpreted when applying a modifier to it, but there are some
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index da604fa..969e247 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1170,6 +1170,14 @@ unsigned long nsecs_to_usecs(unsigned long nsecs)
ARCH_TRACE_CLOCKS
};
+bool trace_clock_in_ns(struct trace_array *tr)
+{
+ if (trace_clocks[tr->clock_id].in_ns)
+ return true;
+
+ return false;
+}
+
/*
* trace_parser_get_init - gets the buffer for trace parser
*/
@@ -4710,8 +4718,9 @@ static int tracing_trace_options_open(struct inode *inode, struct file *file)
"\t .sym display an address as a symbol\n"
"\t .sym-offset display an address as a symbol and offset\n"
"\t .execname display a common_pid as a program name\n"
- "\t .syscall display a syscall id as a syscall name\n\n"
- "\t .log2 display log2 value rather than raw number\n\n"
+ "\t .syscall display a syscall id as a syscall name\n"
+ "\t .log2 display log2 value rather than raw number\n"
+ "\t .usecs display a $common_timestamp in microseconds\n\n"
"\t The 'pause' parameter can be used to pause an existing hist\n"
"\t trigger or to start a hist trigger but not log any events\n"
"\t until told to do so. 'continue' can be used to start or\n"
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index bbfb577..88a6fe3 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -288,6 +288,8 @@ enum {
extern int tracing_set_time_stamp_abs(struct trace_array *tr, bool abs);
+extern bool trace_clock_in_ns(struct trace_array *tr);
+
/*
* The global tracer (top) should be the first trace array added,
* but we check the flag anyway.
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index d0b818c..ec2df88 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -90,12 +90,6 @@ static u64 hist_field_log2(struct hist_field *hist_field, void *event,
return (u64) ilog2(roundup_pow_of_two(val));
}
-static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
-{
- return ring_buffer_event_time_stamp(rbe);
-}
-
#define DEFINE_HIST_FIELD_FN(type) \
static u64 hist_field_##type(struct hist_field *hist_field, \
void *event, \
@@ -143,6 +137,7 @@ enum hist_field_flags {
HIST_FIELD_FL_STACKTRACE = 1 << 8,
HIST_FIELD_FL_LOG2 = 1 << 9,
HIST_FIELD_FL_TIMESTAMP = 1 << 10,
+ HIST_FIELD_FL_TIMESTAMP_USECS = 1 << 11,
};
struct hist_trigger_attrs {
@@ -153,6 +148,7 @@ struct hist_trigger_attrs {
bool pause;
bool cont;
bool clear;
+ bool ts_in_usecs;
unsigned int map_bits;
};
@@ -170,6 +166,20 @@ struct hist_trigger_data {
bool enable_timestamps;
};
+static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
+ struct ring_buffer_event *rbe)
+{
+ struct hist_trigger_data *hist_data = hist_field->hist_data;
+ struct trace_array *tr = hist_data->event_file->tr;
+
+ u64 ts = ring_buffer_event_time_stamp(rbe);
+
+ if (hist_data->attrs->ts_in_usecs && trace_clock_in_ns(tr))
+ ts = ns2usecs(ts);
+
+ return ts;
+}
+
static const char *hist_field_name(struct hist_field *field,
unsigned int level)
{
@@ -634,6 +644,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
flags |= HIST_FIELD_FL_SYSCALL;
else if (strcmp(field_str, "log2") == 0)
flags |= HIST_FIELD_FL_LOG2;
+ else if (strcmp(field_str, "usecs") == 0)
+ flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
else {
ret = -EINVAL;
goto out;
@@ -643,6 +655,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
if (strcmp(field_name, "$common_timestamp") == 0) {
flags |= HIST_FIELD_FL_TIMESTAMP;
hist_data->enable_timestamps = true;
+ if (flags & HIST_FIELD_FL_TIMESTAMP_USECS)
+ hist_data->attrs->ts_in_usecs = true;
key_size = sizeof(u64);
} else {
field = trace_find_event_field(file->event_call, field_name);
@@ -1241,6 +1255,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)
flags_str = "syscall";
else if (hist_field->flags & HIST_FIELD_FL_LOG2)
flags_str = "log2";
+ else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP_USECS)
+ flags_str = "usecs";
return flags_str;
}
--
1.9.3
From 1584399454175766983@xxx Sat Nov 18 10:31:06 +0000 2017
X-GM-THRID: 1584399454175766983
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Add background and details on inter-event hist triggers, including
hist variables, synthetic events, and actions.
Signed-off-by: Tom Zanussi <[email protected]>
Signed-off-by: Baohong Liu <[email protected]>
---
Documentation/trace/histogram.txt | 382 ++++++++++++++++++++++++++++++++++++++
1 file changed, 382 insertions(+)
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index 7ae5a39..0eea8b9 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -1605,3 +1605,385 @@
Hits: 489
Entries: 7
Dropped: 0
+
+
+2.2 Inter-event hist triggers
+-----------------------------
+
+Inter-event hist triggers are hist triggers that combine values from
+one or more other events and create a histogram using that data. Data
+from an inter-event histogram can in turn become the source for
+further combined histograms, thus providing a chain of related
+histograms, which is important for some applications.
+
+The most important example of an inter-event quantity that can be used
+in this manner is latency, which is simply a difference in timestamps
+between two events. Although latency is the most important
+inter-event quantity, note that because the support is completely
+general across the trace event subsystem, any event field can be used
+in an inter-event quantity.
+
+An example of a histogram that combines data from other histograms
+into a useful chain would be a 'wakeupswitch latency' histogram that
+combines a 'wakeup latency' histogram and a 'switch latency'
+histogram.
+
+Normally, a hist trigger specification consists of a (possibly
+compound) key along with one or more numeric values, which are
+continually updated sums associated with that key. A histogram
+specification in this case consists of individual key and value
+specifications that refer to trace event fields associated with a
+single event type.
+
+The inter-event hist trigger extension allows fields from multiple
+events to be referenced and combined into a multi-event histogram
+specification. In support of this overall goal, a few enabling
+features have been added to the hist trigger support:
+
+ - In order to compute an inter-event quantity, a value from one
+ event needs to saved and then referenced from another event. This
+ requires the introduction of support for histogram 'variables'.
+
+ - The computation of inter-event quantities and their combination
+ require some minimal amount of support for applying simple
+ expressions to variables (+ and -).
+
+ - A histogram consisting of inter-event quantities isn't logically a
+ histogram on either event (so having the 'hist' file for either
+ event host the histogram output doesn't really make sense). To
+ address the idea that the histogram is associated with a
+ combination of events, support is added allowing the creation of
+ 'synthetic' events that are events derived from other events.
+ These synthetic events are full-fledged events just like any other
+ and can be used as such, as for instance to create the
+ 'combination' histograms mentioned previously.
+
+ - A set of 'actions' can be associated with histogram entries -
+ these can be used to generate the previously mentioned synthetic
+ events, but can also be used for other purposes, such as for
+ example saving context when a 'max' latency has been hit.
+
+ - Trace events don't have a 'timestamp' associated with them, but
+ there is an implicit timestamp saved along with an event in the
+ underlying ftrace ring buffer. This timestamp is now exposed as a
+ a synthetic field named '$common_timestamp' which can be used in
+ histograms as if it were any other event field. Note that it has
+ a '$' prefixed to it - this is meant to indicate that it isn't an
+ actual field in the trace format but rather is a synthesized value
+ that nonetheless can be used as if it were an actual field. By
+ default it is in units of nanoseconds; appending '.usecs' to a
+ common_timestamp field changes the units to microseconds.
+
+These features are decribed in more detail in the following sections.
+
+2.2.1 Histogram Variables
+-------------------------
+
+Variables are simply named locations used for saving and retrieving
+values between matching events. A 'matching' event is defined as an
+event that has a matching key - if a variable is saved for a histogram
+entry corresponding to that key, any subsequent event with a matching
+key can access that variable.
+
+A variable's value is normally available to any subsequent event until
+it is set to something else by a subsequent event. The one exception
+to that rule is that any variable used in an expression is essentially
+'read-once' - once it's used by an expression in a subsequent event,
+it's reset to its 'unset' state, which means it can't be used again
+unless it's set again. This ensures not only that an event doesn't
+use an uninitialized variable in a calculation, but that that variable
+is used only once and not for any unrelated subsequent match.
+
+The basic syntax for saving a variable is to simply prefix a unique
+variable name not corresponding to any keyword along with an '=' sign
+to any event field.
+
+Either keys or values can be saved and retrieved in this way. This
+creates a variable named 'ts0' for a histogram entry with the key
+'next_pid':
+
+ # echo 'hist:keys=next_pid:vals=$ts0:ts0=$common_timestamp ... >> \
+ event/trigger
+
+The ts0 variable can be accessed by any subsequent event having the
+same pid as 'next_pid'.
+
+Variable references are formed by prepending the variable name with
+the '$' sign. Thus for example, the ts0 variable above would be
+referenced as '$ts0' in expressions.
+
+Because 'vals=' is used, the $common_timestamp variable value above
+will also be summed as a normal histogram value would (though for a
+timestamp it makes little sense).
+
+The below shows that a key value can also be saved in the same way:
+
+ # echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger
+
+If a variable isn't a key variable or prefixed with 'vals=', the
+associated event field will be saved in a variable but won't be summed
+as a value:
+
+ # echo 'hist:keys=next_pid:ts1=$common_timestamp ... >> event/trigger
+
+Multiple variables can be assigned at the same time. The below would
+result in both ts0 and b being created as variables, with both
+common_timestamp and field1 additionally being summed as values:
+
+ # echo 'hist:keys=pid:vals=$ts0,$b:ts0=$common_timestamp,b=field1 ... >> \
+ event/trigger
+
+Note that variable assignments can appear either preceding or
+following their use. The command below behaves identically to the
+command above:
+
+ # echo 'hist:keys=pid:ts0=$common_timestamp,b=field1:vals=$ts0,$b ... >> \
+ event/trigger
+
+Any number of variables not bound to a 'vals=' prefix can also be
+assigned by simply separating them with colons. Below is the same
+thing but without the values being summed in the histogram:
+
+ # echo 'hist:keys=pid:ts0=$common_timestamp:b=field1 ... >> event/trigger
+
+Variables set as above can be referenced and used in expressions on
+another event.
+
+For example, here's how a latency can be calculated:
+
+ # echo 'hist:keys=pid,prio:ts0=$common_timestamp ... >> event1/trigger
+ # echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp-$ts0 ... >> event2/trigger
+
+In the first line above, the event's timetamp is saved into the
+variable ts0. In the next line, ts0 is subtracted from the second
+event's timestamp to produce the latency, which is then assigned into
+yet another variable, 'wakeup_lat'. The hist trigger below in turn
+makes use of the wakeup_lat variable to compute a combined latency
+using the same key and variable from yet another event:
+
+ # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ... >> event3/trigger
+
+2.2.2 Synthetic Events
+----------------------
+
+Synthetic events are user-defined events generated from hist trigger
+variables or fields associated with one or more other events. Their
+purpose is to provide a mechanism for displaying data spanning
+multiple events consistent with the existing and already familiar
+usage for normal events.
+
+To define a synthetic event, the user writes a simple specification
+consisting of the name of the new event along with one or more
+variables and their types, which can be any valid field type,
+separated by semicolons, to the tracing/synthetic_events file.
+
+For instance, the following creates a new event named 'wakeup_latency'
+with 3 fields: lat, pid, and prio. Each of those fields is simply a
+variable reference to a variable on another event:
+
+ # echo 'wakeup_latency \
+ u64 lat; \
+ pid_t pid; \
+ int prio' >> \
+ /sys/kernel/debug/tracing/synthetic_events
+
+Reading the tracing/synthetic_events file lists all the currently
+defined synthetic events, in this case the event defined above:
+
+ # cat /sys/kernel/debug/tracing/synthetic_events
+ wakeup_latency u64 lat; pid_t pid; int prio
+
+An existing synthetic event definition can be removed by prepending
+the command that defined it with a '!':
+
+ # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \
+ /sys/kernel/debug/tracing/synthetic_events
+
+At this point, there isn't yet an actual 'wakeup_latency' event
+instantiated in the event subsytem - for this to happen, a 'hist
+trigger action' needs to be instantiated and bound to actual fields
+and variables defined on other events (see Section 6.3.3 below).
+
+Once that is done, an event instance is created, and a histogram can
+be defined using it:
+
+ # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
+ /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
+
+The new event is created under the tracing/events/synthetic/ directory
+and looks and behaves just like any other event:
+
+ # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency
+ enable filter format hist id trigger
+
+Like any other event, once a histogram is enabled for the event, the
+output can be displayed by reading the event's 'hist' file.
+
+2.2.3 Hist trigger 'actions'
+----------------------------
+
+A hist trigger 'action' is a function that's executed whenever a
+histogram entry is added or updated.
+
+The default 'action' if no special function is explicity specified is
+as it always has been, to simply update the set of values associated
+with an entry. Some applications, however, may want to perform
+additional actions at that point, such as generate another event, or
+compare and save a maximum.
+
+The following additional actions are available. To specify an action
+for a given event, simply specify the action between colons in the
+hist trigger specification.
+
+ - onmatch(matching.event).<synthetic_event_name>(param list)
+
+ The 'onmatch(matching.event).<synthetic_event_name>(params)' hist
+ trigger action is invoked whenever an event matches and the
+ histogram entry would be added or updated. It causes the named
+ synthetic event to be generated with the values given in the
+ 'param list'. The result is the generation of a synthetic event
+ that consists of the values contained in those variables at the
+ time the invoking event was hit.
+
+ The 'param list' consists of one or more parameters which may be
+ either variables or fields defined on either the 'matching.event'
+ or the target event. The variables or fields specified in the
+ param list may be either fully-qualified or unqualified. If a
+ variable is specified as unqualified, it must be unique between
+ the two events. A field name used as a param can be unqualified
+ if it refers to the target event, but must be fully qualified if
+ it refers to the matching event. A fully-qualified name is of the
+ form 'system.event_name.$var_name' or 'system.event_name.field'.
+
+ The 'matching.event' specification is simply the fully qualified
+ event name of the event that matches the target event for the
+ onmatch() functionality, in the form 'system.event_name'.
+
+ Finally, the number and type of variables/fields in the 'param
+ list' must match the number and types of the fields in the
+ synthetic event being generated.
+
+ As an example the below defines a simple synthetic event and uses
+ a variable defined on the sched_wakeup_new event as a parameter
+ when invoking the synthetic event. Here we define the synthetic
+ event:
+
+ # echo 'wakeup_new_test pid_t pid' >> \
+ /sys/kernel/debug/tracing/synthetic_events
+
+ # cat /sys/kernel/debug/tracing/synthetic_events
+ wakeup_new_test pid_t pid
+
+ The following hist trigger both defines the missing testpid
+ variable and specifies an onmatch() action that generates a
+ wakeup_new_test synthetic event whenever a sched_wakeup_new event
+ occurs, which because of the 'if comm == "cyclictest"' filter only
+ happens when the executable is cyclictest:
+
+ # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
+ wakeup_new_test($testpid) if comm=="cyclictest"' >> \
+ /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger
+
+ Creating and displaying a histogram based on those events is now
+ just a matter of using the fields and new synthetic event in the
+ tracing/events/synthetic directory, as usual:
+
+ # echo 'hist:keys=pid:sort=pid' >> \
+ /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger
+
+ Running 'cyclictest' should cause wakeup_new events to generate
+ wakeup_new_test synthetic events which should result in histogram
+ output in the wakeup_new_test event's hist file:
+
+ # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist
+
+ A more typical usage would be to use two events to calculate a
+ latency. The following example uses a set of hist triggers to
+ produce a 'wakeup_latency' histogram:
+
+ First, we define a 'wakeup_latency' synthetic event:
+
+ # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
+ /sys/kernel/debug/tracing/synthetic_events
+
+ Next, we specify that whenever we see a sched_waking event for a
+ cyclictest thread, save the timestamp in a 'ts0' variable:
+
+ # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=$common_timestamp.usecs \
+ if comm=="cyclictest"' >> \
+ /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
+
+ Then, when the corresponding thread is actually scheduled onto the
+ CPU by a sched_switch event, calculate the latency and use that
+ along with another variable and an event field to generate a
+ wakeup_latency synthetic event:
+
+ # echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:\
+ onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\
+ $saved_pid,next_prio) if next_comm=="cyclictest"' >> \
+ /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
+
+ We also need to create a histogram on the wakeup_latency synthetic
+ event in order to aggregate the generated synthetic event data:
+
+ # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
+ /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
+
+ Finally, once we've run cyclictest to actually generate some
+ events, we can see the output by looking at the wakeup_latency
+ synthetic event's hist file:
+
+ # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
+
+ - onmax(var).save(field,.. .)
+
+ The 'onmax(var).save(field,...)' hist trigger action is invoked
+ whenever the value of 'var' associated with a histogram entry
+ exceeds the current maximum contained in that variable.
+
+ The end result is that the trace event fields specified as the
+ onmax.save() params will be saved if 'var' exceeds the current
+ maximum for that hist trigger entry. This allows context from the
+ event that exhibited the new maximum to be saved for later
+ reference. When the histogram is displayed, additional fields
+ displaying the saved values will be printed.
+
+ As an example the below defines a couple of hist triggers, one for
+ sched_waking and another for sched_switch, keyed on pid. Whenever
+ a sched_waking occurs, the timestamp is saved in the entry
+ corresponding to the current pid, and when the scheduler switches
+ back to that pid, the timestamp difference is calculated. If the
+ resulting latency, stored in wakeup_lat, exceeds the current
+ maximum latency, the values specified in the save() fields are
+ recoreded:
+
+ # echo 'hist:keys=pid:ts0=$common_timestamp.usecs \
+ if comm=="cyclictest"' >> \
+ /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
+
+ # echo 'hist:keys=next_pid:\
+ wakeup_lat=$common_timestamp.usecs-$ts0:\
+ onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \
+ if next_comm=="cyclictest"' >> \
+ /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
+
+ When the histogram is displayed, the max value and the saved
+ values corresponding to the max are displayed following the rest
+ of the fields:
+
+ # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
+ { next_pid: 2255 } hitcount: 239
+ common_timestamp-ts0: 0
+ max: 27
+ next_comm: cyclictest
+ prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
+
+ { next_pid: 2256 } hitcount: 2355
+ common_timestamp-ts0: 0
+ max: 49 next_comm: cyclictest
+ prev_pid: 0 prev_prio: 120 prev_comm: swapper/0
+
+ Totals:
+ Hits: 12970
+ Entries: 2
+ Dropped: 0
--
1.9.3
From 1586587211001154472@xxx Tue Dec 12 14:04:33 +0000 2017
X-GM-THRID: 1586582941305745342
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Up until now, hist triggers only needed per-element support for saving
'comm' data, which was saved directly as a private data pointer.
In anticipation of the need to save other data besides 'comm', add a
new hist_elt_data struct for the purpose, and switch the current
'comm'-related code over to that.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 76 +++++++++++++++++++++++-----------------
1 file changed, 43 insertions(+), 33 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index f6c59a5..d9f24b7 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -289,6 +289,10 @@ static struct hist_field *find_var(struct hist_trigger_data *hist_data,
return NULL;
}
+struct hist_elt_data {
+ char *comm;
+};
+
static const char *hist_field_name(struct hist_field *field,
unsigned int level)
{
@@ -503,45 +507,61 @@ static inline void save_comm(char *comm, struct task_struct *task)
memcpy(comm, task->comm, TASK_COMM_LEN);
}
-static void hist_trigger_elt_comm_free(struct tracing_map_elt *elt)
+static void hist_elt_data_free(struct hist_elt_data *elt_data)
+{
+ kfree(elt_data->comm);
+ kfree(elt_data);
+}
+
+static void hist_trigger_elt_data_free(struct tracing_map_elt *elt)
{
- kfree((char *)elt->private_data);
+ struct hist_elt_data *elt_data = elt->private_data;
+
+ hist_elt_data_free(elt_data);
}
-static int hist_trigger_elt_comm_alloc(struct tracing_map_elt *elt)
+static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt)
{
struct hist_trigger_data *hist_data = elt->map->private_data;
+ unsigned int size = TASK_COMM_LEN + 1;
+ struct hist_elt_data *elt_data;
struct hist_field *key_field;
unsigned int i;
+ elt_data = kzalloc(sizeof(*elt_data), GFP_KERNEL);
+ if (!elt_data)
+ return -ENOMEM;
+
for_each_hist_key_field(i, hist_data) {
key_field = hist_data->fields[i];
if (key_field->flags & HIST_FIELD_FL_EXECNAME) {
- unsigned int size = TASK_COMM_LEN + 1;
-
- elt->private_data = kzalloc(size, GFP_KERNEL);
- if (!elt->private_data)
+ elt_data->comm = kzalloc(size, GFP_KERNEL);
+ if (!elt_data->comm) {
+ kfree(elt_data);
return -ENOMEM;
+ }
break;
}
}
+ elt->private_data = elt_data;
+
return 0;
}
-static void hist_trigger_elt_comm_init(struct tracing_map_elt *elt)
+static void hist_trigger_elt_data_init(struct tracing_map_elt *elt)
{
- char *comm = elt->private_data;
+ struct hist_elt_data *elt_data = elt->private_data;
- if (comm)
- save_comm(comm, current);
+ if (elt_data->comm)
+ save_comm(elt_data->comm, current);
}
-static const struct tracing_map_ops hist_trigger_elt_comm_ops = {
- .elt_alloc = hist_trigger_elt_comm_alloc,
- .elt_free = hist_trigger_elt_comm_free,
- .elt_init = hist_trigger_elt_comm_init,
+static const struct tracing_map_ops hist_trigger_elt_data_ops = {
+ .elt_alloc = hist_trigger_elt_data_alloc,
+ .elt_free = hist_trigger_elt_data_free,
+ .elt_init = hist_trigger_elt_data_init,
};
static const char *get_hist_field_flags(struct hist_field *hist_field)
@@ -1512,21 +1532,6 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)
return 0;
}
-static bool need_tracing_map_ops(struct hist_trigger_data *hist_data)
-{
- struct hist_field *key_field;
- unsigned int i;
-
- for_each_hist_key_field(i, hist_data) {
- key_field = hist_data->fields[i];
-
- if (key_field->flags & HIST_FIELD_FL_EXECNAME)
- return true;
- }
-
- return false;
-}
-
static struct hist_trigger_data *
create_hist_data(unsigned int map_bits,
struct hist_trigger_attrs *attrs,
@@ -1552,8 +1557,7 @@ static bool need_tracing_map_ops(struct hist_trigger_data *hist_data)
if (ret)
goto free;
- if (need_tracing_map_ops(hist_data))
- map_ops = &hist_trigger_elt_comm_ops;
+ map_ops = &hist_trigger_elt_data_ops;
hist_data->map = tracing_map_create(map_bits, hist_data->key_size,
map_ops, hist_data);
@@ -1741,7 +1745,13 @@ static void hist_trigger_stacktrace_print(struct seq_file *m,
seq_printf(m, "%s: [%llx] %-55s", field_name,
uval, str);
} else if (key_field->flags & HIST_FIELD_FL_EXECNAME) {
- char *comm = elt->private_data;
+ struct hist_elt_data *elt_data = elt->private_data;
+ char *comm;
+
+ if (WARN_ON_ONCE(!elt_data))
+ return;
+
+ comm = elt_data->comm;
uval = *(u64 *)(key + key_field->offset);
seq_printf(m, "%s: %-16s[%10llu]", field_name,
--
1.9.3
From 1584590418201357236@xxx Mon Nov 20 13:06:23 +0000 2017
X-GM-THRID: 1583945945590122535
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
RINGBUF_TYPE_TIME_STAMP is defined but not used, and from what I can
gather was reserved for something like an absolute timestamp feature
for the ring buffer, if not a complete replacement of the current
time_delta scheme.
This code redefines RINGBUF_TYPE_TIME_STAMP to implement absolute time
stamps. Another way to look at it is that it essentially forces
extended time_deltas for all events.
The motivation for doing this is to enable time_deltas that aren't
dependent on previous events in the ring buffer, making it feasible to
use the ring_buffer_event timetamps in a more random-access way, for
purposes other than serial event printing.
To set/reset this mode, use tracing_set_timestamp_abs() from the
previous interface patch.
Signed-off-by: Tom Zanussi <[email protected]>
---
include/linux/ring_buffer.h | 12 ++---
kernel/trace/ring_buffer.c | 104 ++++++++++++++++++++++++++++++++------------
2 files changed, 83 insertions(+), 33 deletions(-)
diff --git a/include/linux/ring_buffer.h b/include/linux/ring_buffer.h
index 28e3472..74bc276 100644
--- a/include/linux/ring_buffer.h
+++ b/include/linux/ring_buffer.h
@@ -36,10 +36,12 @@ struct ring_buffer_event {
* array[0] = time delta (28 .. 59)
* size = 8 bytes
*
- * @RINGBUF_TYPE_TIME_STAMP: Sync time stamp with external clock
- * array[0] = tv_nsec
- * array[1..2] = tv_sec
- * size = 16 bytes
+ * @RINGBUF_TYPE_TIME_STAMP: Absolute timestamp
+ * Same format as TIME_EXTEND except that the
+ * value is an absolute timestamp, not a delta
+ * event.time_delta contains bottom 27 bits
+ * array[0] = top (28 .. 59) bits
+ * size = 8 bytes
*
* <= @RINGBUF_TYPE_DATA_TYPE_LEN_MAX:
* Data record
@@ -56,12 +58,12 @@ enum ring_buffer_type {
RINGBUF_TYPE_DATA_TYPE_LEN_MAX = 28,
RINGBUF_TYPE_PADDING,
RINGBUF_TYPE_TIME_EXTEND,
- /* FIXME: RINGBUF_TYPE_TIME_STAMP not implemented */
RINGBUF_TYPE_TIME_STAMP,
};
unsigned ring_buffer_event_length(struct ring_buffer_event *event);
void *ring_buffer_event_data(struct ring_buffer_event *event);
+u64 ring_buffer_event_time_stamp(struct ring_buffer_event *event);
/*
* ring_buffer_discard_commit will remove an event that has not
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 1e5b75a..763b3fb 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -42,6 +42,8 @@ int ring_buffer_print_entry_header(struct trace_seq *s)
RINGBUF_TYPE_PADDING);
trace_seq_printf(s, "\ttime_extend : type == %d\n",
RINGBUF_TYPE_TIME_EXTEND);
+ trace_seq_printf(s, "\ttime_stamp : type == %d\n",
+ RINGBUF_TYPE_TIME_STAMP);
trace_seq_printf(s, "\tdata max type_len == %d\n",
RINGBUF_TYPE_DATA_TYPE_LEN_MAX);
@@ -141,12 +143,15 @@ int ring_buffer_print_entry_header(struct trace_seq *s)
enum {
RB_LEN_TIME_EXTEND = 8,
- RB_LEN_TIME_STAMP = 16,
+ RB_LEN_TIME_STAMP = 8,
};
#define skip_time_extend(event) \
((struct ring_buffer_event *)((char *)event + RB_LEN_TIME_EXTEND))
+#define extended_time(event) \
+ (event->type_len >= RINGBUF_TYPE_TIME_EXTEND)
+
static inline int rb_null_event(struct ring_buffer_event *event)
{
return event->type_len == RINGBUF_TYPE_PADDING && !event->time_delta;
@@ -210,7 +215,7 @@ static void rb_event_set_padding(struct ring_buffer_event *event)
{
unsigned len = 0;
- if (event->type_len == RINGBUF_TYPE_TIME_EXTEND) {
+ if (extended_time(event)) {
/* time extends include the data event after it */
len = RB_LEN_TIME_EXTEND;
event = skip_time_extend(event);
@@ -232,7 +237,7 @@ unsigned ring_buffer_event_length(struct ring_buffer_event *event)
{
unsigned length;
- if (event->type_len == RINGBUF_TYPE_TIME_EXTEND)
+ if (extended_time(event))
event = skip_time_extend(event);
length = rb_event_length(event);
@@ -249,7 +254,7 @@ unsigned ring_buffer_event_length(struct ring_buffer_event *event)
static __always_inline void *
rb_event_data(struct ring_buffer_event *event)
{
- if (event->type_len == RINGBUF_TYPE_TIME_EXTEND)
+ if (extended_time(event))
event = skip_time_extend(event);
BUG_ON(event->type_len > RINGBUF_TYPE_DATA_TYPE_LEN_MAX);
/* If length is in len field, then array[0] has the data */
@@ -276,6 +281,27 @@ void *ring_buffer_event_data(struct ring_buffer_event *event)
#define TS_MASK ((1ULL << TS_SHIFT) - 1)
#define TS_DELTA_TEST (~TS_MASK)
+/**
+ * ring_buffer_event_time_stamp - return the event's extended timestamp
+ * @event: the event to get the timestamp of
+ *
+ * Returns the extended timestamp associated with a data event.
+ * An extended time_stamp is a 64-bit timestamp represented
+ * internally in a special way that makes the best use of space
+ * contained within a ring buffer event. This function decodes
+ * it and maps it to a straight u64 value.
+ */
+u64 ring_buffer_event_time_stamp(struct ring_buffer_event *event)
+{
+ u64 ts;
+
+ ts = event->array[0];
+ ts <<= TS_SHIFT;
+ ts += event->time_delta;
+
+ return ts;
+}
+
/* Flag when events were overwritten */
#define RB_MISSED_EVENTS (1 << 31)
/* Missed count stored at end */
@@ -2221,12 +2247,15 @@ static void rb_inc_iter(struct ring_buffer_iter *iter)
/* Slow path, do not inline */
static noinline struct ring_buffer_event *
-rb_add_time_stamp(struct ring_buffer_event *event, u64 delta)
+rb_add_time_stamp(struct ring_buffer_event *event, u64 delta, bool abs)
{
- event->type_len = RINGBUF_TYPE_TIME_EXTEND;
+ if (abs)
+ event->type_len = RINGBUF_TYPE_TIME_STAMP;
+ else
+ event->type_len = RINGBUF_TYPE_TIME_EXTEND;
- /* Not the first event on the page? */
- if (rb_event_index(event)) {
+ /* Not the first event on the page, or not delta? */
+ if (abs || rb_event_index(event)) {
event->time_delta = delta & TS_MASK;
event->array[0] = delta >> TS_SHIFT;
} else {
@@ -2269,7 +2298,9 @@ static inline bool rb_event_is_commit(struct ring_buffer_per_cpu *cpu_buffer,
* add it to the start of the resevered space.
*/
if (unlikely(info->add_timestamp)) {
- event = rb_add_time_stamp(event, delta);
+ bool abs = ring_buffer_time_stamp_abs(cpu_buffer->buffer);
+
+ event = rb_add_time_stamp(event, info->delta, abs);
length -= RB_LEN_TIME_EXTEND;
delta = 0;
}
@@ -2457,7 +2488,7 @@ static __always_inline void rb_end_commit(struct ring_buffer_per_cpu *cpu_buffer
static inline void rb_event_discard(struct ring_buffer_event *event)
{
- if (event->type_len == RINGBUF_TYPE_TIME_EXTEND)
+ if (extended_time(event))
event = skip_time_extend(event);
/* array[0] holds the actual length for the discarded event */
@@ -2501,10 +2532,11 @@ static inline void rb_event_discard(struct ring_buffer_event *event)
cpu_buffer->write_stamp =
cpu_buffer->commit_page->page->time_stamp;
else if (event->type_len == RINGBUF_TYPE_TIME_EXTEND) {
- delta = event->array[0];
- delta <<= TS_SHIFT;
- delta += event->time_delta;
+ delta = ring_buffer_event_time_stamp(event);
cpu_buffer->write_stamp += delta;
+ } else if (event->type_len == RINGBUF_TYPE_TIME_STAMP) {
+ delta = ring_buffer_event_time_stamp(event);
+ cpu_buffer->write_stamp = delta;
} else
cpu_buffer->write_stamp += event->time_delta;
}
@@ -2657,7 +2689,7 @@ int ring_buffer_unlock_commit(struct ring_buffer *buffer,
* If this is the first commit on the page, then it has the same
* timestamp as the page itself.
*/
- if (!tail)
+ if (!tail && !ring_buffer_time_stamp_abs(cpu_buffer->buffer))
info->delta = 0;
/* See if we shot pass the end of this buffer page */
@@ -2735,8 +2767,11 @@ int ring_buffer_unlock_commit(struct ring_buffer *buffer,
/* make sure this diff is calculated here */
barrier();
- /* Did the write stamp get updated already? */
- if (likely(info.ts >= cpu_buffer->write_stamp)) {
+ if (ring_buffer_time_stamp_abs(buffer)) {
+ info.delta = info.ts;
+ rb_handle_timestamp(cpu_buffer, &info);
+ } else /* Did the write stamp get updated already? */
+ if (likely(info.ts >= cpu_buffer->write_stamp)) {
info.delta = diff;
if (unlikely(test_time_stamp(info.delta)))
rb_handle_timestamp(cpu_buffer, &info);
@@ -3418,14 +3453,13 @@ int ring_buffer_iter_empty(struct ring_buffer_iter *iter)
return;
case RINGBUF_TYPE_TIME_EXTEND:
- delta = event->array[0];
- delta <<= TS_SHIFT;
- delta += event->time_delta;
+ delta = ring_buffer_event_time_stamp(event);
cpu_buffer->read_stamp += delta;
return;
case RINGBUF_TYPE_TIME_STAMP:
- /* FIXME: not implemented */
+ delta = ring_buffer_event_time_stamp(event);
+ cpu_buffer->read_stamp = delta;
return;
case RINGBUF_TYPE_DATA:
@@ -3449,14 +3483,13 @@ int ring_buffer_iter_empty(struct ring_buffer_iter *iter)
return;
case RINGBUF_TYPE_TIME_EXTEND:
- delta = event->array[0];
- delta <<= TS_SHIFT;
- delta += event->time_delta;
+ delta = ring_buffer_event_time_stamp(event);
iter->read_stamp += delta;
return;
case RINGBUF_TYPE_TIME_STAMP:
- /* FIXME: not implemented */
+ delta = ring_buffer_event_time_stamp(event);
+ iter->read_stamp = delta;
return;
case RINGBUF_TYPE_DATA:
@@ -3680,6 +3713,8 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
struct buffer_page *reader;
int nr_loops = 0;
+ if (ts)
+ *ts = 0;
again:
/*
* We repeat when a time extend is encountered.
@@ -3716,12 +3751,17 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
goto again;
case RINGBUF_TYPE_TIME_STAMP:
- /* FIXME: not implemented */
+ if (ts) {
+ *ts = ring_buffer_event_time_stamp(event);
+ ring_buffer_normalize_time_stamp(cpu_buffer->buffer,
+ cpu_buffer->cpu, ts);
+ }
+ /* Internal data, OK to advance */
rb_advance_reader(cpu_buffer);
goto again;
case RINGBUF_TYPE_DATA:
- if (ts) {
+ if (ts && !(*ts)) {
*ts = cpu_buffer->read_stamp + event->time_delta;
ring_buffer_normalize_time_stamp(cpu_buffer->buffer,
cpu_buffer->cpu, ts);
@@ -3746,6 +3786,9 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
struct ring_buffer_event *event;
int nr_loops = 0;
+ if (ts)
+ *ts = 0;
+
cpu_buffer = iter->cpu_buffer;
buffer = cpu_buffer->buffer;
@@ -3798,12 +3841,17 @@ static int rb_lost_events(struct ring_buffer_per_cpu *cpu_buffer)
goto again;
case RINGBUF_TYPE_TIME_STAMP:
- /* FIXME: not implemented */
+ if (ts) {
+ *ts = ring_buffer_event_time_stamp(event);
+ ring_buffer_normalize_time_stamp(cpu_buffer->buffer,
+ cpu_buffer->cpu, ts);
+ }
+ /* Internal data, OK to advance */
rb_advance_iter(iter);
goto again;
case RINGBUF_TYPE_DATA:
- if (ts) {
+ if (ts && !(*ts)) {
*ts = iter->read_stamp + event->time_delta;
ring_buffer_normalize_time_stamp(buffer,
cpu_buffer->cpu, ts);
--
1.9.3
From 1584352660371033003@xxx Fri Nov 17 22:07:20 +0000 2017
X-GM-THRID: 1584244642886126649
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
From: Vedang Patel <[email protected]>
We now have the logic to detect and remove duplicates in the
tracing_map hash table. The code which merges duplicates in the
histogram is redundant now. So, modify this code just to detect
duplicates. The duplication detection code is still kept to ensure
that any rare race condition which might cause duplicates does not go
unnoticed.
Signed-off-by: Vedang Patel <[email protected]>
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 11 ------
kernel/trace/tracing_map.c | 83 +++-------------------------------------
kernel/trace/tracing_map.h | 7 ----
3 files changed, 6 insertions(+), 95 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 1e1558c..712260e 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -340,16 +340,6 @@ static int hist_trigger_elt_comm_alloc(struct tracing_map_elt *elt)
return 0;
}
-static void hist_trigger_elt_comm_copy(struct tracing_map_elt *to,
- struct tracing_map_elt *from)
-{
- char *comm_from = from->private_data;
- char *comm_to = to->private_data;
-
- if (comm_from)
- memcpy(comm_to, comm_from, TASK_COMM_LEN + 1);
-}
-
static void hist_trigger_elt_comm_init(struct tracing_map_elt *elt)
{
char *comm = elt->private_data;
@@ -360,7 +350,6 @@ static void hist_trigger_elt_comm_init(struct tracing_map_elt *elt)
static const struct tracing_map_ops hist_trigger_elt_comm_ops = {
.elt_alloc = hist_trigger_elt_comm_alloc,
- .elt_copy = hist_trigger_elt_comm_copy,
.elt_free = hist_trigger_elt_comm_free,
.elt_init = hist_trigger_elt_comm_init,
};
diff --git a/kernel/trace/tracing_map.c b/kernel/trace/tracing_map.c
index b30f343..f47a4d5 100644
--- a/kernel/trace/tracing_map.c
+++ b/kernel/trace/tracing_map.c
@@ -847,67 +847,15 @@ void tracing_map_destroy_sort_entries(struct tracing_map_sort_entry **entries,
return sort_entry;
}
-static struct tracing_map_elt *copy_elt(struct tracing_map_elt *elt)
-{
- struct tracing_map_elt *dup_elt;
- unsigned int i;
-
- dup_elt = tracing_map_elt_alloc(elt->map);
- if (IS_ERR(dup_elt))
- return NULL;
-
- if (elt->map->ops && elt->map->ops->elt_copy)
- elt->map->ops->elt_copy(dup_elt, elt);
-
- dup_elt->private_data = elt->private_data;
- memcpy(dup_elt->key, elt->key, elt->map->key_size);
-
- for (i = 0; i < elt->map->n_fields; i++) {
- atomic64_set(&dup_elt->fields[i].sum,
- atomic64_read(&elt->fields[i].sum));
- dup_elt->fields[i].cmp_fn = elt->fields[i].cmp_fn;
- }
-
- return dup_elt;
-}
-
-static int merge_dup(struct tracing_map_sort_entry **sort_entries,
- unsigned int target, unsigned int dup)
-{
- struct tracing_map_elt *target_elt, *elt;
- bool first_dup = (target - dup) == 1;
- int i;
-
- if (first_dup) {
- elt = sort_entries[target]->elt;
- target_elt = copy_elt(elt);
- if (!target_elt)
- return -ENOMEM;
- sort_entries[target]->elt = target_elt;
- sort_entries[target]->elt_copied = true;
- } else
- target_elt = sort_entries[target]->elt;
-
- elt = sort_entries[dup]->elt;
-
- for (i = 0; i < elt->map->n_fields; i++)
- atomic64_add(atomic64_read(&elt->fields[i].sum),
- &target_elt->fields[i].sum);
-
- sort_entries[dup]->dup = true;
-
- return 0;
-}
-
-static int merge_dups(struct tracing_map_sort_entry **sort_entries,
+static void detect_dups(struct tracing_map_sort_entry **sort_entries,
int n_entries, unsigned int key_size)
{
unsigned int dups = 0, total_dups = 0;
- int err, i, j;
+ int i;
void *key;
if (n_entries < 2)
- return total_dups;
+ return;
sort(sort_entries, n_entries, sizeof(struct tracing_map_sort_entry *),
(int (*)(const void *, const void *))cmp_entries_dup, NULL);
@@ -916,30 +864,14 @@ static int merge_dups(struct tracing_map_sort_entry **sort_entries,
for (i = 1; i < n_entries; i++) {
if (!memcmp(sort_entries[i]->key, key, key_size)) {
dups++; total_dups++;
- err = merge_dup(sort_entries, i - dups, i);
- if (err)
- return err;
continue;
}
key = sort_entries[i]->key;
dups = 0;
}
- if (!total_dups)
- return total_dups;
-
- for (i = 0, j = 0; i < n_entries; i++) {
- if (!sort_entries[i]->dup) {
- sort_entries[j] = sort_entries[i];
- if (j++ != i)
- sort_entries[i] = NULL;
- } else {
- destroy_sort_entry(sort_entries[i]);
- sort_entries[i] = NULL;
- }
- }
-
- return total_dups;
+ WARN_ONCE(total_dups > 0,
+ "Duplicates detected: %d\n", total_dups);
}
static bool is_key(struct tracing_map *map, unsigned int field_idx)
@@ -1065,10 +997,7 @@ int tracing_map_sort_entries(struct tracing_map *map,
return 1;
}
- ret = merge_dups(entries, n_entries, map->key_size);
- if (ret < 0)
- goto free;
- n_entries -= ret;
+ detect_dups(entries, n_entries, map->key_size);
if (is_key(map, sort_keys[0].field_idx))
cmp_entries_fn = cmp_entries_key;
diff --git a/kernel/trace/tracing_map.h b/kernel/trace/tracing_map.h
index f097511..98ef6d6 100644
--- a/kernel/trace/tracing_map.h
+++ b/kernel/trace/tracing_map.h
@@ -214,11 +214,6 @@ struct tracing_map {
* Element allocation occurs before tracing begins, when the
* tracing_map_init() call is made by client code.
*
- * @elt_copy: At certain points in the lifetime of an element, it may
- * need to be copied. The copy should include a copy of the
- * client-allocated data, which can be copied into the 'to'
- * element from the 'from' element.
- *
* @elt_free: When a tracing_map_elt is freed, this function is called
* and allows client-allocated per-element data to be freed.
*
@@ -232,8 +227,6 @@ struct tracing_map {
*/
struct tracing_map_ops {
int (*elt_alloc)(struct tracing_map_elt *elt);
- void (*elt_copy)(struct tracing_map_elt *to,
- struct tracing_map_elt *from);
void (*elt_free)(struct tracing_map_elt *elt);
void (*elt_clear)(struct tracing_map_elt *elt);
void (*elt_init)(struct tracing_map_elt *elt);
--
1.9.3
From 1584453762596791222@xxx Sun Nov 19 00:54:18 +0000 2017
X-GM-THRID: 1584453762596791222
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Some accessor functions, such as for variable references, require
access to a corrsponding tracing_map_elt.
Add a tracing_map_elt param to the function signature and update the
accessor functions accordingly.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 91 +++++++++++++++++++++++++---------------
1 file changed, 57 insertions(+), 34 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index d9f24b7..db903ce 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -26,8 +26,10 @@
struct hist_field;
-typedef u64 (*hist_field_fn_t) (struct hist_field *field, void *event,
- struct ring_buffer_event *rbe);
+typedef u64 (*hist_field_fn_t) (struct hist_field *field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event);
#define HIST_FIELD_OPERANDS_MAX 2
#define HIST_FIELDS_MAX (TRACING_MAP_FIELDS_MAX + TRACING_MAP_VARS_MAX)
@@ -59,28 +61,36 @@ struct hist_field {
char *name;
};
-static u64 hist_field_none(struct hist_field *field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_none(struct hist_field *field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
return 0;
}
-static u64 hist_field_counter(struct hist_field *field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_counter(struct hist_field *field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
return 1;
}
-static u64 hist_field_string(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_string(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
char *addr = (char *)(event + hist_field->field->offset);
return (u64)(unsigned long)addr;
}
-static u64 hist_field_dynstring(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_dynstring(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
u32 str_item = *(u32 *)(event + hist_field->field->offset);
int str_loc = str_item & 0xffff;
@@ -89,54 +99,64 @@ static u64 hist_field_dynstring(struct hist_field *hist_field, void *event,
return (u64)(unsigned long)addr;
}
-static u64 hist_field_pstring(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_pstring(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
char **addr = (char **)(event + hist_field->field->offset);
return (u64)(unsigned long)*addr;
}
-static u64 hist_field_log2(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_log2(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
struct hist_field *operand = hist_field->operands[0];
- u64 val = operand->fn(operand, event, rbe);
+ u64 val = operand->fn(operand, elt, rbe, event);
return (u64) ilog2(roundup_pow_of_two(val));
}
-static u64 hist_field_plus(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_plus(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
struct hist_field *operand1 = hist_field->operands[0];
struct hist_field *operand2 = hist_field->operands[1];
- u64 val1 = operand1->fn(operand1, event, rbe);
- u64 val2 = operand2->fn(operand2, event, rbe);
+ u64 val1 = operand1->fn(operand1, elt, rbe, event);
+ u64 val2 = operand2->fn(operand2, elt, rbe, event);
return val1 + val2;
}
-static u64 hist_field_minus(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_minus(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
struct hist_field *operand1 = hist_field->operands[0];
struct hist_field *operand2 = hist_field->operands[1];
- u64 val1 = operand1->fn(operand1, event, rbe);
- u64 val2 = operand2->fn(operand2, event, rbe);
+ u64 val1 = operand1->fn(operand1, elt, rbe, event);
+ u64 val2 = operand2->fn(operand2, elt, rbe, event);
return val1 - val2;
}
-static u64 hist_field_unary_minus(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_unary_minus(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
struct hist_field *operand = hist_field->operands[0];
- s64 sval = (s64)operand->fn(operand, event, rbe);
+ s64 sval = (s64)operand->fn(operand, elt, rbe, event);
u64 val = (u64)-sval;
return val;
@@ -144,8 +164,9 @@ static u64 hist_field_unary_minus(struct hist_field *hist_field, void *event,
#define DEFINE_HIST_FIELD_FN(type) \
static u64 hist_field_##type(struct hist_field *hist_field, \
- void *event, \
- struct ring_buffer_event *rbe) \
+ struct tracing_map_elt *elt, \
+ struct ring_buffer_event *rbe, \
+ void *event) \
{ \
type *addr = (type *)(event + hist_field->field->offset); \
\
@@ -233,8 +254,10 @@ struct hist_trigger_data {
bool remove;
};
-static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
- struct ring_buffer_event *rbe)
+static u64 hist_field_timestamp(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
{
struct hist_trigger_data *hist_data = hist_field->hist_data;
struct trace_array *tr = hist_data->event_file->tr;
@@ -1598,7 +1621,7 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
for_each_hist_val_field(i, hist_data) {
hist_field = hist_data->fields[i];
- hist_val = hist_field->fn(hist_field, rbe, rec);
+ hist_val = hist_field->fn(hist_field, elt, rbe, rec);
if (hist_field->flags & HIST_FIELD_FL_VAR) {
var_idx = hist_field->var.idx;
tracing_map_set_var(elt, var_idx, hist_val);
@@ -1610,7 +1633,7 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
for_each_hist_key_field(i, hist_data) {
hist_field = hist_data->fields[i];
if (hist_field->flags & HIST_FIELD_FL_VAR) {
- hist_val = hist_field->fn(hist_field, rbe, rec);
+ hist_val = hist_field->fn(hist_field, elt, rbe, rec);
var_idx = hist_field->var.idx;
tracing_map_set_var(elt, var_idx, hist_val);
}
@@ -1648,9 +1671,9 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec,
bool use_compound_key = (hist_data->n_keys > 1);
unsigned long entries[HIST_STACKTRACE_DEPTH];
char compound_key[HIST_KEY_SIZE_MAX];
+ struct tracing_map_elt *elt = NULL;
struct stack_trace stacktrace;
struct hist_field *key_field;
- struct tracing_map_elt *elt;
u64 field_contents;
void *key = NULL;
unsigned int i;
@@ -1671,7 +1694,7 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec,
key = entries;
} else {
- field_contents = key_field->fn(key_field, rec, rbe);
+ field_contents = key_field->fn(key_field, elt, rbe, rec);
if (key_field->flags & HIST_FIELD_FL_STRING) {
key = (void *)(unsigned long)field_contents;
use_compound_key = true;
--
1.9.3
From 1584345296981425287@xxx Fri Nov 17 20:10:18 +0000 2017
X-GM-THRID: 1584269800005684023
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Allow hist_data access via hist_field. Some users of hist_fields
require or will require more access to the associated hist_data.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 14 +++++++++-----
1 file changed, 9 insertions(+), 5 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 7e7428c..d0b818c 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -39,6 +39,7 @@ struct hist_field {
unsigned int offset;
unsigned int is_signed;
struct hist_field *operands[HIST_FIELD_OPERANDS_MAX];
+ struct hist_trigger_data *hist_data;
};
static u64 hist_field_none(struct hist_field *field, void *event,
@@ -420,7 +421,8 @@ static void destroy_hist_field(struct hist_field *hist_field,
kfree(hist_field);
}
-static struct hist_field *create_hist_field(struct ftrace_event_field *field,
+static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
+ struct ftrace_event_field *field,
unsigned long flags)
{
struct hist_field *hist_field;
@@ -432,6 +434,8 @@ static struct hist_field *create_hist_field(struct ftrace_event_field *field,
if (!hist_field)
return NULL;
+ hist_field->hist_data = hist_data;
+
if (flags & HIST_FIELD_FL_HITCOUNT) {
hist_field->fn = hist_field_counter;
goto out;
@@ -445,7 +449,7 @@ static struct hist_field *create_hist_field(struct ftrace_event_field *field,
if (flags & HIST_FIELD_FL_LOG2) {
unsigned long fl = flags & ~HIST_FIELD_FL_LOG2;
hist_field->fn = hist_field_log2;
- hist_field->operands[0] = create_hist_field(field, fl);
+ hist_field->operands[0] = create_hist_field(hist_data, field, fl);
hist_field->size = hist_field->operands[0]->size;
goto out;
}
@@ -498,7 +502,7 @@ static void destroy_hist_fields(struct hist_trigger_data *hist_data)
static int create_hitcount_val(struct hist_trigger_data *hist_data)
{
hist_data->fields[HITCOUNT_IDX] =
- create_hist_field(NULL, HIST_FIELD_FL_HITCOUNT);
+ create_hist_field(hist_data, NULL, HIST_FIELD_FL_HITCOUNT);
if (!hist_data->fields[HITCOUNT_IDX])
return -ENOMEM;
@@ -544,7 +548,7 @@ static int create_val_field(struct hist_trigger_data *hist_data,
}
}
- hist_data->fields[val_idx] = create_hist_field(field, flags);
+ hist_data->fields[val_idx] = create_hist_field(hist_data, field, flags);
if (!hist_data->fields[val_idx]) {
ret = -ENOMEM;
goto out;
@@ -654,7 +658,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
}
}
- hist_data->fields[key_idx] = create_hist_field(field, flags);
+ hist_data->fields[key_idx] = create_hist_field(hist_data, field, flags);
if (!hist_data->fields[key_idx]) {
ret = -ENOMEM;
goto out;
--
1.9.3
From 1584337688055112314@xxx Fri Nov 17 18:09:21 +0000 2017
X-GM-THRID: 1584337688055112314
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Allow tracing code outside of trace.c to access tracing_set_clock().
Some applications may require a particular clock in order to function
properly, such as latency calculations.
Also, add an accessor returning the current clock string.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace.c | 2 +-
kernel/trace/trace.h | 1 +
2 files changed, 2 insertions(+), 1 deletion(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index f667a78..16000c9 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6230,7 +6230,7 @@ static int tracing_clock_show(struct seq_file *m, void *v)
return 0;
}
-static int tracing_set_clock(struct trace_array *tr, const char *clockstr)
+int tracing_set_clock(struct trace_array *tr, const char *clockstr)
{
int i;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 52667dd..68153a8 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -288,6 +288,7 @@ enum {
extern void trace_array_put(struct trace_array *tr);
extern int tracing_set_time_stamp_abs(struct trace_array *tr, bool abs);
+extern int tracing_set_clock(struct trace_array *tr, const char *clockstr);
extern bool trace_clock_in_ns(struct trace_array *tr);
--
1.9.3
From 1584345849919397530@xxx Fri Nov 17 20:19:05 +0000 2017
X-GM-THRID: 1584345849919397530
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Add support for saving the value of a current event's event field by
assigning it to a variable that can be read by a subsequent event.
The basic syntax for saving a variable is to simply prefix a unique
variable name not corresponding to any keyword along with an '=' sign
to any event field.
Both keys and values can be saved and retrieved in this way:
# echo 'hist:keys=next_pid:vals=$ts0:ts0=$common_timestamp ...
# echo 'hist:timer_pid=common_pid:key=$timer_pid ...'
If a variable isn't a key variable or prefixed with 'vals=', the
associated event field will be saved in a variable but won't be summed
as a value:
# echo 'hist:keys=next_pid:ts1=$common_timestamp:...
Multiple variables can be assigned at the same time:
# echo 'hist:keys=pid:vals=$ts0,$b,field2:ts0=$common_timestamp,b=field1 ...
Multiple (or single) variables can also be assigned at the same time
using separate assignments:
# echo 'hist:keys=pid:vals=$ts0:ts0=$common_timestamp:b=field1:c=field2 ...
Variables set as above can be used by being referenced from another
event, as described in a subsequent patch.
Signed-off-by: Tom Zanussi <[email protected]>
Signed-off-by: Baohong Liu <[email protected]>
---
kernel/trace/trace_events_hist.c | 372 ++++++++++++++++++++++++++++++++++-----
1 file changed, 332 insertions(+), 40 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index ec2df88..eccfe07 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -30,6 +30,13 @@ typedef u64 (*hist_field_fn_t) (struct hist_field *field, void *event,
struct ring_buffer_event *rbe);
#define HIST_FIELD_OPERANDS_MAX 2
+#define HIST_FIELDS_MAX (TRACING_MAP_FIELDS_MAX + TRACING_MAP_VARS_MAX)
+
+struct hist_var {
+ char *name;
+ struct hist_trigger_data *hist_data;
+ unsigned int idx;
+};
struct hist_field {
struct ftrace_event_field *field;
@@ -40,6 +47,7 @@ struct hist_field {
unsigned int is_signed;
struct hist_field *operands[HIST_FIELD_OPERANDS_MAX];
struct hist_trigger_data *hist_data;
+ struct hist_var var;
};
static u64 hist_field_none(struct hist_field *field, void *event,
@@ -138,6 +146,13 @@ enum hist_field_flags {
HIST_FIELD_FL_LOG2 = 1 << 9,
HIST_FIELD_FL_TIMESTAMP = 1 << 10,
HIST_FIELD_FL_TIMESTAMP_USECS = 1 << 11,
+ HIST_FIELD_FL_VAR = 1 << 12,
+};
+
+struct var_defs {
+ unsigned int n_vars;
+ char *name[TRACING_MAP_VARS_MAX];
+ char *expr[TRACING_MAP_VARS_MAX];
};
struct hist_trigger_attrs {
@@ -150,13 +165,19 @@ struct hist_trigger_attrs {
bool clear;
bool ts_in_usecs;
unsigned int map_bits;
+
+ char *assignment_str[TRACING_MAP_VARS_MAX];
+ unsigned int n_assignments;
+
+ struct var_defs var_defs;
};
struct hist_trigger_data {
- struct hist_field *fields[TRACING_MAP_FIELDS_MAX];
+ struct hist_field *fields[HIST_FIELDS_MAX];
unsigned int n_vals;
unsigned int n_keys;
unsigned int n_fields;
+ unsigned int n_vars;
unsigned int key_size;
struct tracing_map_sort_key sort_keys[TRACING_MAP_SORT_KEYS_MAX];
unsigned int n_sort_keys;
@@ -164,6 +185,7 @@ struct hist_trigger_data {
struct hist_trigger_attrs *attrs;
struct tracing_map *map;
bool enable_timestamps;
+ bool remove;
};
static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
@@ -180,6 +202,48 @@ static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
return ts;
}
+static struct hist_field *find_var_field(struct hist_trigger_data *hist_data,
+ const char *var_name)
+{
+ struct hist_field *hist_field, *found = NULL;
+ int i;
+
+ for_each_hist_field(i, hist_data) {
+ hist_field = hist_data->fields[i];
+ if (hist_field && hist_field->flags & HIST_FIELD_FL_VAR &&
+ strcmp(hist_field->var.name, var_name) == 0) {
+ found = hist_field;
+ break;
+ }
+ }
+
+ return found;
+}
+
+static struct hist_field *find_var(struct hist_trigger_data *hist_data,
+ struct trace_event_file *file,
+ const char *var_name)
+{
+ struct hist_trigger_data *test_data;
+ struct event_trigger_data *test;
+ struct hist_field *hist_field;
+
+ hist_field = find_var_field(hist_data, var_name);
+ if (hist_field)
+ return hist_field;
+
+ list_for_each_entry_rcu(test, &file->triggers, list) {
+ if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
+ test_data = test->private_data;
+ hist_field = find_var_field(test_data, var_name);
+ if (hist_field)
+ return hist_field;
+ }
+ }
+
+ return NULL;
+}
+
static const char *hist_field_name(struct hist_field *field,
unsigned int level)
{
@@ -262,9 +326,14 @@ static int parse_map_size(char *str)
static void destroy_hist_trigger_attrs(struct hist_trigger_attrs *attrs)
{
+ unsigned int i;
+
if (!attrs)
return;
+ for (i = 0; i < attrs->n_assignments; i++)
+ kfree(attrs->assignment_str[i]);
+
kfree(attrs->name);
kfree(attrs->sort_key_str);
kfree(attrs->keys_str);
@@ -311,8 +380,22 @@ static int parse_assignment(char *str, struct hist_trigger_attrs *attrs)
goto out;
}
attrs->map_bits = map_bits;
- } else
- ret = -EINVAL;
+ } else {
+ char *assignment;
+
+ if (attrs->n_assignments == TRACING_MAP_VARS_MAX) {
+ ret = -EINVAL;
+ goto out;
+ }
+
+ assignment = kstrdup(str, GFP_KERNEL);
+ if (!assignment) {
+ ret = -ENOMEM;
+ goto out;
+ }
+
+ attrs->assignment_str[attrs->n_assignments++] = assignment;
+ }
out:
return ret;
}
@@ -428,12 +511,15 @@ static void destroy_hist_field(struct hist_field *hist_field,
for (i = 0; i < HIST_FIELD_OPERANDS_MAX; i++)
destroy_hist_field(hist_field->operands[i], level + 1);
+ kfree(hist_field->var.name);
+
kfree(hist_field);
}
static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
struct ftrace_event_field *field,
- unsigned long flags)
+ unsigned long flags,
+ char *var_name)
{
struct hist_field *hist_field;
@@ -459,7 +545,7 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
if (flags & HIST_FIELD_FL_LOG2) {
unsigned long fl = flags & ~HIST_FIELD_FL_LOG2;
hist_field->fn = hist_field_log2;
- hist_field->operands[0] = create_hist_field(hist_data, field, fl);
+ hist_field->operands[0] = create_hist_field(hist_data, field, fl, NULL);
hist_field->size = hist_field->operands[0]->size;
goto out;
}
@@ -494,14 +580,23 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
hist_field->field = field;
hist_field->flags = flags;
+ if (var_name) {
+ hist_field->var.name = kstrdup(var_name, GFP_KERNEL);
+ if (!hist_field->var.name)
+ goto free;
+ }
+
return hist_field;
+ free:
+ destroy_hist_field(hist_field, 0);
+ return NULL;
}
static void destroy_hist_fields(struct hist_trigger_data *hist_data)
{
unsigned int i;
- for (i = 0; i < TRACING_MAP_FIELDS_MAX; i++) {
+ for (i = 0; i < HIST_FIELDS_MAX; i++) {
if (hist_data->fields[i]) {
destroy_hist_field(hist_data->fields[i], 0);
hist_data->fields[i] = NULL;
@@ -512,11 +607,12 @@ static void destroy_hist_fields(struct hist_trigger_data *hist_data)
static int create_hitcount_val(struct hist_trigger_data *hist_data)
{
hist_data->fields[HITCOUNT_IDX] =
- create_hist_field(hist_data, NULL, HIST_FIELD_FL_HITCOUNT);
+ create_hist_field(hist_data, NULL, HIST_FIELD_FL_HITCOUNT, NULL);
if (!hist_data->fields[HITCOUNT_IDX])
return -ENOMEM;
hist_data->n_vals++;
+ hist_data->n_fields++;
if (WARN_ON(hist_data->n_vals > TRACING_MAP_VALS_MAX))
return -EINVAL;
@@ -524,19 +620,16 @@ static int create_hitcount_val(struct hist_trigger_data *hist_data)
return 0;
}
-static int create_val_field(struct hist_trigger_data *hist_data,
- unsigned int val_idx,
- struct trace_event_file *file,
- char *field_str)
+static int __create_val_field(struct hist_trigger_data *hist_data,
+ unsigned int val_idx,
+ struct trace_event_file *file,
+ char *var_name, char *field_str,
+ unsigned long flags)
{
struct ftrace_event_field *field = NULL;
- unsigned long flags = 0;
char *field_name;
int ret = 0;
- if (WARN_ON(val_idx >= TRACING_MAP_VALS_MAX))
- return -EINVAL;
-
field_name = strsep(&field_str, ".");
if (field_str) {
if (strcmp(field_str, "hex") == 0)
@@ -558,25 +651,58 @@ static int create_val_field(struct hist_trigger_data *hist_data,
}
}
- hist_data->fields[val_idx] = create_hist_field(hist_data, field, flags);
+ hist_data->fields[val_idx] = create_hist_field(hist_data, field, flags, var_name);
if (!hist_data->fields[val_idx]) {
ret = -ENOMEM;
goto out;
}
++hist_data->n_vals;
+ ++hist_data->n_fields;
- if (WARN_ON(hist_data->n_vals > TRACING_MAP_VALS_MAX))
+ if (WARN_ON(hist_data->n_vals > TRACING_MAP_VALS_MAX + TRACING_MAP_VARS_MAX))
ret = -EINVAL;
out:
return ret;
}
+static int create_val_field(struct hist_trigger_data *hist_data,
+ unsigned int val_idx,
+ struct trace_event_file *file,
+ char *field_str)
+{
+ if (WARN_ON(val_idx >= TRACING_MAP_VALS_MAX))
+ return -EINVAL;
+
+ return __create_val_field(hist_data, val_idx, file, NULL, field_str, 0);
+}
+
+static int create_var_field(struct hist_trigger_data *hist_data,
+ unsigned int val_idx,
+ struct trace_event_file *file,
+ char *var_name, char *expr_str)
+{
+ unsigned long flags = 0;
+
+ if (WARN_ON(val_idx >= TRACING_MAP_VALS_MAX + TRACING_MAP_VARS_MAX))
+ return -EINVAL;
+ if (find_var(hist_data, file, var_name) && !hist_data->remove) {
+ return -EINVAL;
+ }
+
+ flags |= HIST_FIELD_FL_VAR;
+ hist_data->n_vars++;
+ if (WARN_ON(hist_data->n_vars > TRACING_MAP_VARS_MAX))
+ return -EINVAL;
+
+ return __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags);
+}
+
static int create_val_fields(struct hist_trigger_data *hist_data,
struct trace_event_file *file)
{
char *fields_str, *field_str;
- unsigned int i, j;
+ unsigned int i, j = 1;
int ret;
ret = create_hitcount_val(hist_data);
@@ -596,12 +722,15 @@ static int create_val_fields(struct hist_trigger_data *hist_data,
field_str = strsep(&fields_str, ",");
if (!field_str)
break;
+
if (strcmp(field_str, "hitcount") == 0)
continue;
+
ret = create_val_field(hist_data, j++, file, field_str);
if (ret)
goto out;
}
+
if (fields_str && (strcmp(fields_str, "hitcount") != 0))
ret = -EINVAL;
out:
@@ -615,11 +744,12 @@ static int create_key_field(struct hist_trigger_data *hist_data,
char *field_str)
{
struct ftrace_event_field *field = NULL;
+ struct hist_field *hist_field = NULL;
unsigned long flags = 0;
unsigned int key_size;
int ret = 0;
- if (WARN_ON(key_idx >= TRACING_MAP_FIELDS_MAX))
+ if (WARN_ON(key_idx >= HIST_FIELDS_MAX))
return -EINVAL;
flags |= HIST_FIELD_FL_KEY;
@@ -627,6 +757,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
if (strcmp(field_str, "stacktrace") == 0) {
flags |= HIST_FIELD_FL_STACKTRACE;
key_size = sizeof(unsigned long) * HIST_STACKTRACE_DEPTH;
+ hist_field = create_hist_field(hist_data, NULL, flags, NULL);
} else {
char *field_name = strsep(&field_str, ".");
@@ -672,7 +803,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
}
}
- hist_data->fields[key_idx] = create_hist_field(hist_data, field, flags);
+ hist_data->fields[key_idx] = create_hist_field(hist_data, field, flags, NULL);
if (!hist_data->fields[key_idx]) {
ret = -ENOMEM;
goto out;
@@ -688,6 +819,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
}
hist_data->n_keys++;
+ hist_data->n_fields++;
if (WARN_ON(hist_data->n_keys > TRACING_MAP_KEYS_MAX))
return -EINVAL;
@@ -731,21 +863,111 @@ static int create_key_fields(struct hist_trigger_data *hist_data,
return ret;
}
+static int create_var_fields(struct hist_trigger_data *hist_data,
+ struct trace_event_file *file)
+{
+ unsigned int i, j = hist_data->n_vals;
+ int ret = 0;
+
+ unsigned int n_vars = hist_data->attrs->var_defs.n_vars;
+
+ for (i = 0; i < n_vars; i++) {
+ char *var_name = hist_data->attrs->var_defs.name[i];
+ char *expr = hist_data->attrs->var_defs.expr[i];
+
+ ret = create_var_field(hist_data, j++, file, var_name, expr);
+ if (ret)
+ goto out;
+ }
+ out:
+ return ret;
+}
+
+static void free_var_defs(struct hist_trigger_data *hist_data)
+{
+ unsigned int i;
+
+ for (i = 0; i < hist_data->attrs->var_defs.n_vars; i++) {
+ kfree(hist_data->attrs->var_defs.name[i]);
+ kfree(hist_data->attrs->var_defs.expr[i]);
+ }
+
+ hist_data->attrs->var_defs.n_vars = 0;
+}
+
+static int parse_var_defs(struct hist_trigger_data *hist_data)
+{
+ char *s, *str, *var_name, *field_str;
+ unsigned int i, j, n_vars = 0;
+ int ret = 0;
+
+ for (i = 0; i < hist_data->attrs->n_assignments; i++) {
+ str = hist_data->attrs->assignment_str[i];
+ for (j = 0; j < TRACING_MAP_VARS_MAX; j++) {
+ field_str = strsep(&str, ",");
+ if (!field_str)
+ break;
+
+ var_name = strsep(&field_str, "=");
+ if (!var_name || !field_str) {
+ ret = -EINVAL;
+ goto free;
+ }
+
+ if (n_vars == TRACING_MAP_VARS_MAX) {
+ ret = -EINVAL;
+ goto free;
+ }
+
+ s = kstrdup(var_name, GFP_KERNEL);
+ if (!s) {
+ ret = -ENOMEM;
+ goto free;
+ }
+ hist_data->attrs->var_defs.name[n_vars] = s;
+
+ s = kstrdup(field_str, GFP_KERNEL);
+ if (!s) {
+ kfree(hist_data->attrs->var_defs.name[n_vars]);
+ ret = -ENOMEM;
+ goto free;
+ }
+ hist_data->attrs->var_defs.expr[n_vars++] = s;
+
+ hist_data->attrs->var_defs.n_vars = n_vars;
+ }
+ }
+
+ return ret;
+ free:
+ free_var_defs(hist_data);
+
+ return ret;
+}
+
static int create_hist_fields(struct hist_trigger_data *hist_data,
struct trace_event_file *file)
{
int ret;
+ ret = parse_var_defs(hist_data);
+ if (ret)
+ goto out;
+
ret = create_val_fields(hist_data, file);
if (ret)
goto out;
- ret = create_key_fields(hist_data, file);
+ ret = create_var_fields(hist_data, file);
if (ret)
goto out;
- hist_data->n_fields = hist_data->n_vals + hist_data->n_keys;
+ ret = create_key_fields(hist_data, file);
+ if (ret)
+ goto out;
out:
+ free_var_defs(hist_data);
+
return ret;
}
@@ -768,7 +990,7 @@ static int create_sort_keys(struct hist_trigger_data *hist_data)
char *fields_str = hist_data->attrs->sort_key_str;
struct tracing_map_sort_key *sort_key;
int descending, ret = 0;
- unsigned int i, j;
+ unsigned int i, j, k;
hist_data->n_sort_keys = 1; /* we always have at least one, hitcount */
@@ -816,12 +1038,19 @@ static int create_sort_keys(struct hist_trigger_data *hist_data)
continue;
}
- for (j = 1; j < hist_data->n_fields; j++) {
+ for (j = 1, k = 1; j < hist_data->n_fields; j++) {
+ unsigned int idx;
+
hist_field = hist_data->fields[j];
+ if (hist_field->flags & HIST_FIELD_FL_VAR)
+ continue;
+
+ idx = k++;
+
test_name = hist_field_name(hist_field, 0);
if (strcmp(field_name, test_name) == 0) {
- sort_key->field_idx = j;
+ sort_key->field_idx = idx;
descending = is_descending(field_str);
if (descending < 0) {
ret = descending;
@@ -836,6 +1065,7 @@ static int create_sort_keys(struct hist_trigger_data *hist_data)
break;
}
}
+
hist_data->n_sort_keys = i;
out:
return ret;
@@ -876,12 +1106,19 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)
idx = tracing_map_add_key_field(map,
hist_field->offset,
cmp_fn);
-
- } else
+ } else if (!(hist_field->flags & HIST_FIELD_FL_VAR))
idx = tracing_map_add_sum_field(map);
if (idx < 0)
return idx;
+
+ if (hist_field->flags & HIST_FIELD_FL_VAR) {
+ idx = tracing_map_add_var(map);
+ if (idx < 0)
+ return idx;
+ hist_field->var.idx = idx;
+ hist_field->var.hist_data = hist_data;
+ }
}
return 0;
@@ -905,7 +1142,8 @@ static bool need_tracing_map_ops(struct hist_trigger_data *hist_data)
static struct hist_trigger_data *
create_hist_data(unsigned int map_bits,
struct hist_trigger_attrs *attrs,
- struct trace_event_file *file)
+ struct trace_event_file *file,
+ bool remove)
{
const struct tracing_map_ops *map_ops = NULL;
struct hist_trigger_data *hist_data;
@@ -916,6 +1154,7 @@ static bool need_tracing_map_ops(struct hist_trigger_data *hist_data)
return ERR_PTR(-ENOMEM);
hist_data->attrs = attrs;
+ hist_data->remove = remove;
ret = create_hist_fields(hist_data, file);
if (ret)
@@ -962,14 +1201,28 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
struct ring_buffer_event *rbe)
{
struct hist_field *hist_field;
- unsigned int i;
+ unsigned int i, var_idx;
u64 hist_val;
for_each_hist_val_field(i, hist_data) {
hist_field = hist_data->fields[i];
- hist_val = hist_field->fn(hist_field, rec, rbe);
+ hist_val = hist_field->fn(hist_field, rbe, rec);
+ if (hist_field->flags & HIST_FIELD_FL_VAR) {
+ var_idx = hist_field->var.idx;
+ tracing_map_set_var(elt, var_idx, hist_val);
+ continue;
+ }
tracing_map_update_sum(elt, i, hist_val);
}
+
+ for_each_hist_key_field(i, hist_data) {
+ hist_field = hist_data->fields[i];
+ if (hist_field->flags & HIST_FIELD_FL_VAR) {
+ hist_val = hist_field->fn(hist_field, rbe, rec);
+ var_idx = hist_field->var.idx;
+ tracing_map_set_var(elt, var_idx, hist_val);
+ }
+ }
}
static inline void add_to_key(char *compound_key, void *key,
@@ -1144,6 +1397,9 @@ static void hist_trigger_stacktrace_print(struct seq_file *m,
for (i = 1; i < hist_data->n_vals; i++) {
field_name = hist_field_name(hist_data->fields[i], 0);
+ if (hist_data->fields[i]->flags & HIST_FIELD_FL_VAR)
+ continue;
+
if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) {
seq_printf(m, " %s: %10llx", field_name,
tracing_map_read_sum(elt, i));
@@ -1265,6 +1521,9 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
{
const char *field_name = hist_field_name(hist_field, 0);
+ if (hist_field->var.name)
+ seq_printf(m, "%s=", hist_field->var.name);
+
if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
seq_puts(m, "$common_timestamp");
else if (field_name)
@@ -1283,7 +1542,8 @@ static int event_hist_trigger_print(struct seq_file *m,
struct event_trigger_data *data)
{
struct hist_trigger_data *hist_data = data->private_data;
- struct hist_field *key_field;
+ struct hist_field *field;
+ bool have_var = false;
unsigned int i;
seq_puts(m, "hist:");
@@ -1294,25 +1554,47 @@ static int event_hist_trigger_print(struct seq_file *m,
seq_puts(m, "keys=");
for_each_hist_key_field(i, hist_data) {
- key_field = hist_data->fields[i];
+ field = hist_data->fields[i];
if (i > hist_data->n_vals)
seq_puts(m, ",");
- if (key_field->flags & HIST_FIELD_FL_STACKTRACE)
+ if (field->flags & HIST_FIELD_FL_STACKTRACE)
seq_puts(m, "stacktrace");
else
- hist_field_print(m, key_field);
+ hist_field_print(m, field);
}
seq_puts(m, ":vals=");
for_each_hist_val_field(i, hist_data) {
+ field = hist_data->fields[i];
+ if (field->flags & HIST_FIELD_FL_VAR) {
+ have_var = true;
+ continue;
+ }
+
if (i == HITCOUNT_IDX)
seq_puts(m, "hitcount");
else {
seq_puts(m, ",");
- hist_field_print(m, hist_data->fields[i]);
+ hist_field_print(m, field);
+ }
+ }
+
+ if (have_var) {
+ unsigned int n = 0;
+
+ seq_puts(m, ":");
+
+ for_each_hist_val_field(i, hist_data) {
+ field = hist_data->fields[i];
+
+ if (field->flags & HIST_FIELD_FL_VAR) {
+ if (n++)
+ seq_puts(m, ",");
+ hist_field_print(m, field);
+ }
}
}
@@ -1320,7 +1602,10 @@ static int event_hist_trigger_print(struct seq_file *m,
for (i = 0; i < hist_data->n_sort_keys; i++) {
struct tracing_map_sort_key *sort_key;
- unsigned int idx;
+ unsigned int idx, first_key_idx;
+
+ /* skip VAR vals */
+ first_key_idx = hist_data->n_vals - hist_data->n_vars;
sort_key = &hist_data->sort_keys[i];
idx = sort_key->field_idx;
@@ -1333,8 +1618,11 @@ static int event_hist_trigger_print(struct seq_file *m,
if (idx == HITCOUNT_IDX)
seq_puts(m, "hitcount");
- else
+ else {
+ if (idx >= first_key_idx)
+ idx += hist_data->n_vars;
hist_field_print(m, hist_data->fields[idx]);
+ }
if (sort_key->descending)
seq_puts(m, ".descending");
@@ -1631,7 +1919,7 @@ static void hist_unregister_trigger(char *glob, struct event_trigger_ops *ops,
test->ops->free(test->ops, test);
if (hist_data->enable_timestamps) {
- if (unregistered)
+ if (!hist_data->remove || unregistered)
tracing_set_time_stamp_abs(file->tr, false);
}
}
@@ -1664,12 +1952,16 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
struct hist_trigger_attrs *attrs;
struct event_trigger_ops *trigger_ops;
struct hist_trigger_data *hist_data;
+ bool remove = false;
char *trigger;
int ret = 0;
if (!param)
return -EINVAL;
+ if (glob[0] == '!')
+ remove = true;
+
/* separate the trigger from the filter (k:v [if filter]) */
trigger = strsep(¶m, " \t");
if (!trigger)
@@ -1682,7 +1974,7 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
if (attrs->map_bits)
hist_trigger_bits = attrs->map_bits;
- hist_data = create_hist_data(hist_trigger_bits, attrs, file);
+ hist_data = create_hist_data(hist_trigger_bits, attrs, file, remove);
if (IS_ERR(hist_data)) {
destroy_hist_trigger_attrs(attrs);
return PTR_ERR(hist_data);
@@ -1711,7 +2003,7 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
goto out_free;
}
- if (glob[0] == '!') {
+ if (remove) {
cmd_ops->unreg(glob+1, trigger_ops, trigger_data, file);
ret = 0;
goto out_free;
--
1.9.3
From 1584356084670160978@xxx Fri Nov 17 23:01:45 +0000 2017
X-GM-THRID: 1584342234857172406
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Synthetic event generation needs to happen while the current event is
still in progress, so add 1 to the trace_recursive_lock() recursion
limit to account for that.
Because we also want to allow for the possibility of a synthetic event
being generated from another synthetic event, add an additional
increment for that as well.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/ring_buffer.c | 10 +++++-----
1 file changed, 5 insertions(+), 5 deletions(-)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 763b3fb..8c862ea 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2589,16 +2589,16 @@ static void rb_commit(struct ring_buffer_per_cpu *cpu_buffer,
* IRQ context
* NMI context
*
- * If for some reason the ring buffer starts to recurse, we
- * only allow that to happen at most 4 times (one for each
- * context). If it happens 5 times, then we consider this a
- * recusive loop and do not let it go further.
+ * If for some reason the ring buffer starts to recurse, we only allow
+ * that to happen at most 6 times (one for each context, plus possibly
+ * two levels of synthetic event generation). If it happens 7 times,
+ * then we consider this a recusive loop and do not let it go further.
*/
static __always_inline int
trace_recursive_lock(struct ring_buffer_per_cpu *cpu_buffer)
{
- if (cpu_buffer->current_context >= 4)
+ if (cpu_buffer->current_context >= 6)
return 1;
cpu_buffer->current_context++;
--
1.9.3
From 1584323186391227360@xxx Fri Nov 17 14:18:51 +0000 2017
X-GM-THRID: 1584160883252782517
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
The default clock if timestamps are used in a histogram is "global".
If timestamps aren't used, the clock is irrelevant.
Use the "clock=" param only if you want to override the default
"global" clock for a histogram with timestamps.
Signed-off-by: Tom Zanussi <[email protected]>
Signed-off-by: Rajvi Jingar <[email protected]>
---
Documentation/trace/histogram.txt | 11 ++++++++++-
kernel/trace/trace_events_hist.c | 38 ++++++++++++++++++++++++++++++++++++--
2 files changed, 46 insertions(+), 3 deletions(-)
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index 0eea8b9..aa450bb 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -1674,7 +1674,16 @@ features have been added to the hist trigger support:
default it is in units of nanoseconds; appending '.usecs' to a
common_timestamp field changes the units to microseconds.
-These features are decribed in more detail in the following sections.
+A note on inter-event timestamps: If $common_timestamp is used in a
+histogram, the trace buffer is automatically switched over to using
+absolute timestamps and the "global" trace clock, in order to avoid
+bogus timestamp differences with other clocks that aren't coherent
+across CPUs. This can be overridden by specifying one of the other
+trace clocks instead, using the "clock=XXX" hist trigger attribute,
+where XXX is any of the clocks listed in the tracing/trace_clock
+pseudo-file.
+
+These features are described in more detail in the following sections.
2.2.1 Histogram Variables
-------------------------
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 174aef21..1ac0cda 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -242,6 +242,7 @@ struct hist_trigger_attrs {
char *vals_str;
char *sort_key_str;
char *name;
+ char *clock;
bool pause;
bool cont;
bool clear;
@@ -1795,6 +1796,7 @@ static void destroy_hist_trigger_attrs(struct hist_trigger_attrs *attrs)
kfree(attrs->sort_key_str);
kfree(attrs->keys_str);
kfree(attrs->vals_str);
+ kfree(attrs->clock);
kfree(attrs);
}
@@ -1850,6 +1852,19 @@ static int parse_assignment(char *str, struct hist_trigger_attrs *attrs)
ret = -ENOMEM;
goto out;
}
+ } else if (strncmp(str, "clock=", strlen("clock=")) == 0) {
+ strsep(&str, "=");
+ if (!str) {
+ ret = -EINVAL;
+ goto out;
+ }
+
+ str = strstrip(str);
+ attrs->clock = kstrdup(str, GFP_KERNEL);
+ if (!attrs->clock) {
+ ret = -ENOMEM;
+ goto out;
+ }
} else if (strncmp(str, "size=", strlen("size=")) == 0) {
int map_bits = parse_map_size(str);
@@ -1914,6 +1929,14 @@ static struct hist_trigger_attrs *parse_hist_trigger_attrs(char *trigger_str)
goto free;
}
+ if (!attrs->clock) {
+ attrs->clock = kstrdup("global", GFP_KERNEL);
+ if (!attrs->clock) {
+ ret = -ENOMEM;
+ goto free;
+ }
+ }
+
return attrs;
free:
destroy_hist_trigger_attrs(attrs);
@@ -4924,6 +4947,8 @@ static int event_hist_trigger_print(struct seq_file *m,
seq_puts(m, ".descending");
}
seq_printf(m, ":size=%u", (1 << hist_data->map->map_bits));
+ if (hist_data->enable_timestamps)
+ seq_printf(m, ":clock=%s", hist_data->attrs->clock);
print_actions_spec(m, hist_data);
@@ -5186,10 +5211,19 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
goto out;
}
- ret++;
+ if (hist_data->enable_timestamps) {
+ char *clock = hist_data->attrs->clock;
+
+ ret = tracing_set_clock(file->tr, hist_data->attrs->clock);
+ if (ret) {
+ hist_err("Couldn't set trace_clock: ", clock);
+ goto out;
+ }
- if (hist_data->enable_timestamps)
tracing_set_time_stamp_abs(file->tr, true);
+ }
+
+ ret++;
out:
return ret;
}
--
1.9.3
From 1584372796200441880@xxx Sat Nov 18 03:27:23 +0000 2017
X-GM-THRID: 1584372796200441880
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Add support for alias=$somevar where alias can be used as
onmatch.xxx($alias).
Aliases are a way of creating a new name for an existing variable, for
flexibly in making naming more clear in certain cases. For example in
the below the user perhaps feels that using $new_lat in the synthetic
event invocation is opaque or doesn't fit well stylistically with
previous triggers, so creates an alias of $new_lat named $latency and
uses that in the call instead:
# echo 'hist:keys=next_pid:new_lat=$common_timestamp.usecs' >
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# echo 'hist:keys=pid:latency=$new_lat:
onmatch(sched.sched_switch).wake2($latency,pid)' >
/sys/kernel/debug/tracing/events/synthetic/wake1/trigger
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 58 +++++++++++++++++++++++++++++++++++++---
1 file changed, 55 insertions(+), 3 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index afbfa9c..0336f03 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -228,6 +228,7 @@ enum hist_field_flags {
HIST_FIELD_FL_EXPR = 1 << 13,
HIST_FIELD_FL_VAR_REF = 1 << 14,
HIST_FIELD_FL_CPU = 1 << 15,
+ HIST_FIELD_FL_ALIAS = 1 << 16,
};
struct var_defs {
@@ -1629,7 +1630,8 @@ static const char *hist_field_name(struct hist_field *field,
if (field->field)
field_name = field->field->name;
- else if (field->flags & HIST_FIELD_FL_LOG2)
+ else if (field->flags & HIST_FIELD_FL_LOG2 ||
+ field->flags & HIST_FIELD_FL_ALIAS)
field_name = hist_field_name(field->operands[0], ++level);
else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
field_name = "$common_timestamp";
@@ -2096,7 +2098,7 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
hist_field->hist_data = hist_data;
- if (flags & HIST_FIELD_FL_EXPR)
+ if (flags & HIST_FIELD_FL_EXPR || flags & HIST_FIELD_FL_ALIAS)
goto out; /* caller will populate */
if (flags & HIST_FIELD_FL_VAR_REF) {
@@ -2380,6 +2382,28 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
return field;
}
+static struct hist_field *create_alias(struct hist_trigger_data *hist_data,
+ struct hist_field *var_ref,
+ char *var_name)
+{
+ struct hist_field *alias = NULL;
+ unsigned long flags = HIST_FIELD_FL_ALIAS | HIST_FIELD_FL_VAR;
+
+ alias = create_hist_field(hist_data, NULL, flags, var_name);
+ if (!alias)
+ return NULL;
+
+ alias->fn = var_ref->fn;
+ alias->operands[0] = var_ref;
+
+ if (init_var_ref(alias, var_ref, var_ref->system, var_ref->event_name)) {
+ destroy_hist_field(alias, 0);
+ return NULL;
+ }
+
+ return alias;
+}
+
struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
struct trace_event_file *file, char *str,
unsigned long *flags, char *var_name)
@@ -2413,6 +2437,13 @@ struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
if (hist_field) {
hist_data->var_refs[hist_data->n_var_refs] = hist_field;
hist_field->var_ref_idx = hist_data->n_var_refs++;
+ if (var_name) {
+ hist_field = create_alias(hist_data, hist_field, var_name);
+ if (!hist_field) {
+ ret = -ENOMEM;
+ goto out;
+ }
+ }
return hist_field;
}
} else
@@ -2517,6 +2548,26 @@ static int check_expr_operands(struct hist_field *operand1,
unsigned long operand1_flags = operand1->flags;
unsigned long operand2_flags = operand2->flags;
+ if ((operand1_flags & HIST_FIELD_FL_VAR_REF) ||
+ (operand1_flags & HIST_FIELD_FL_ALIAS)) {
+ struct hist_field *var;
+
+ var = find_var_field(operand1->var.hist_data, operand1->name);
+ if (!var)
+ return -EINVAL;
+ operand1_flags = var->flags;
+ }
+
+ if ((operand2_flags & HIST_FIELD_FL_VAR_REF) ||
+ (operand2_flags & HIST_FIELD_FL_ALIAS)) {
+ struct hist_field *var;
+
+ var = find_var_field(operand2->var.hist_data, operand2->name);
+ if (!var)
+ return -EINVAL;
+ operand2_flags = var->flags;
+ }
+
if ((operand1_flags & HIST_FIELD_FL_TIMESTAMP_USECS) !=
(operand2_flags & HIST_FIELD_FL_TIMESTAMP_USECS))
return -EINVAL;
@@ -4639,7 +4690,8 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
else if (hist_field->flags & HIST_FIELD_FL_CPU)
seq_puts(m, "cpu");
else if (field_name) {
- if (hist_field->flags & HIST_FIELD_FL_VAR_REF)
+ if (hist_field->flags & HIST_FIELD_FL_VAR_REF ||
+ hist_field->flags & HIST_FIELD_FL_ALIAS)
seq_putc(m, '$');
seq_printf(m, "%s", field_name);
}
--
1.9.3
From 1584466888653811504@xxx Sun Nov 19 04:22:56 +0000 2017
X-GM-THRID: 1584466888653811504
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Add the necessary infrastructure to allow the variables defined on one
event to be referenced in another. This allows variables set by a
previous event to be referenced and used in expressions combining the
variable values saved by that previous event and the event fields of
the current event. For example, here's how a latency can be
calculated and saved into yet another variable named 'wakeup_lat':
# echo 'hist:keys=pid,prio:ts0=$common_timestamp ...
# echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp-$ts0 ...
In the first event, the event's timetamp is saved into the variable
ts0. In the next line, ts0 is subtracted from the second event's
timestamp to produce the latency.
Further users of variable references will be described in subsequent
patches, such as for instance how the 'wakeup_lat' variable above can
be displayed in a latency histogram.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace.c | 2 +
kernel/trace/trace.h | 3 +
kernel/trace/trace_events_hist.c | 632 ++++++++++++++++++++++++++++++++++--
kernel/trace/trace_events_trigger.c | 6 +
4 files changed, 623 insertions(+), 20 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 969e247..f667a78 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -7804,6 +7804,7 @@ static int instance_mkdir(const char *name)
INIT_LIST_HEAD(&tr->systems);
INIT_LIST_HEAD(&tr->events);
+ INIT_LIST_HEAD(&tr->hist_vars);
if (allocate_trace_buffers(tr, trace_buf_size) < 0)
goto out_free_tr;
@@ -8554,6 +8555,7 @@ __init static int tracer_alloc_buffers(void)
INIT_LIST_HEAD(&global_trace.systems);
INIT_LIST_HEAD(&global_trace.events);
+ INIT_LIST_HEAD(&global_trace.hist_vars);
list_add(&global_trace.list, &ftrace_trace_arrays);
apply_trace_boot_options();
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 88a6fe3..52667dd 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -273,6 +273,7 @@ struct trace_array {
int function_enabled;
#endif
int time_stamp_abs_ref;
+ struct list_head hist_vars;
};
enum {
@@ -1547,6 +1548,8 @@ extern int save_named_trigger(const char *name,
extern void unpause_named_trigger(struct event_trigger_data *data);
extern void set_named_trigger_data(struct event_trigger_data *data,
struct event_trigger_data *named_data);
+extern struct event_trigger_data *
+get_named_trigger_data(struct event_trigger_data *data);
extern int register_event_command(struct event_command *cmd);
extern int unregister_event_command(struct event_command *cmd);
extern int register_trigger_hist_enable_disable_cmds(void);
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index d22cdfd..09a9430d 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -59,7 +59,12 @@ struct hist_field {
struct hist_trigger_data *hist_data;
struct hist_var var;
enum field_op_id operator;
+ char *system;
+ char *event_name;
char *name;
+ unsigned int var_idx;
+ unsigned int var_ref_idx;
+ bool read_once;
};
static u64 hist_field_none(struct hist_field *field,
@@ -214,6 +219,7 @@ enum hist_field_flags {
HIST_FIELD_FL_TIMESTAMP_USECS = 1 << 11,
HIST_FIELD_FL_VAR = 1 << 12,
HIST_FIELD_FL_EXPR = 1 << 13,
+ HIST_FIELD_FL_VAR_REF = 1 << 14,
};
struct var_defs {
@@ -253,6 +259,8 @@ struct hist_trigger_data {
struct tracing_map *map;
bool enable_timestamps;
bool remove;
+ struct hist_field *var_refs[TRACING_MAP_VARS_MAX];
+ unsigned int n_var_refs;
};
static u64 hist_field_timestamp(struct hist_field *hist_field,
@@ -271,6 +279,216 @@ static u64 hist_field_timestamp(struct hist_field *hist_field,
return ts;
}
+struct hist_var_data {
+ struct list_head list;
+ struct hist_trigger_data *hist_data;
+};
+
+static struct hist_field *
+check_field_for_var_ref(struct hist_field *hist_field,
+ struct hist_trigger_data *var_data,
+ unsigned int var_idx)
+{
+ struct hist_field *found = NULL;
+
+ if (hist_field && hist_field->flags & HIST_FIELD_FL_VAR_REF) {
+ if (hist_field->var.idx == var_idx &&
+ hist_field->var.hist_data == var_data) {
+ found = hist_field;
+ }
+ }
+
+ return found;
+}
+
+static struct hist_field *
+check_field_for_var_refs(struct hist_trigger_data *hist_data,
+ struct hist_field *hist_field,
+ struct hist_trigger_data *var_data,
+ unsigned int var_idx,
+ unsigned int level)
+{
+ struct hist_field *found = NULL;
+ unsigned int i;
+
+ if (level > 2)
+ return found;
+
+ if (!hist_field)
+ return found;
+
+ found = check_field_for_var_ref(hist_field, var_data, var_idx);
+ if (found)
+ return found;
+
+ for (i = 0; i < HIST_FIELD_OPERANDS_MAX; i++) {
+ struct hist_field *operand;
+
+ operand = hist_field->operands[i];
+ found = check_field_for_var_refs(hist_data, operand, var_data,
+ var_idx, level + 1);
+ if (found)
+ return found;
+ }
+
+ return found;
+}
+
+static struct hist_field *find_var_ref(struct hist_trigger_data *hist_data,
+ struct hist_trigger_data *var_data,
+ unsigned int var_idx)
+{
+ struct hist_field *hist_field, *found = NULL;
+ unsigned int i;
+
+ for_each_hist_field(i, hist_data) {
+ hist_field = hist_data->fields[i];
+ found = check_field_for_var_refs(hist_data, hist_field,
+ var_data, var_idx, 0);
+ if (found)
+ return found;
+ }
+
+ return found;
+}
+
+static struct hist_field *find_any_var_ref(struct hist_trigger_data *hist_data,
+ unsigned int var_idx)
+{
+ struct trace_array *tr = hist_data->event_file->tr;
+ struct hist_field *found = NULL;
+ struct hist_var_data *var_data;
+
+ found = find_var_ref(hist_data, hist_data, var_idx);
+ if (found)
+ return found;
+
+ list_for_each_entry(var_data, &tr->hist_vars, list) {
+ found = find_var_ref(var_data->hist_data, hist_data, var_idx);
+ if (found)
+ break;
+ }
+
+ return found;
+}
+
+static bool check_var_refs(struct hist_trigger_data *hist_data)
+{
+ struct hist_field *field;
+ bool found = false;
+ int i;
+
+ for_each_hist_field(i, hist_data) {
+ field = hist_data->fields[i];
+ if (field && field->flags & HIST_FIELD_FL_VAR) {
+ if (find_any_var_ref(hist_data, field->var.idx)) {
+ found = true;
+ break;
+ }
+ }
+ }
+
+ return found;
+}
+
+static struct hist_var_data *find_hist_vars(struct hist_trigger_data *hist_data)
+{
+ struct trace_array *tr = hist_data->event_file->tr;
+ struct hist_var_data *var_data, *found = NULL;
+
+ list_for_each_entry(var_data, &tr->hist_vars, list) {
+ if (var_data->hist_data == hist_data) {
+ found = var_data;
+ break;
+ }
+ }
+
+ return found;
+}
+
+static bool field_has_hist_vars(struct hist_field *hist_field,
+ unsigned int level)
+{
+ int i;
+
+ if (level > 2)
+ return false;
+
+ if (!hist_field)
+ return false;
+
+ if (hist_field->flags & HIST_FIELD_FL_VAR ||
+ hist_field->flags & HIST_FIELD_FL_VAR_REF)
+ return true;
+
+ for (i = 0; i < HIST_FIELD_OPERANDS_MAX; i++) {
+ struct hist_field *operand;
+
+ operand = hist_field->operands[i];
+ if (field_has_hist_vars(operand, level + 1))
+ return true;
+ }
+
+ return false;
+}
+
+static bool has_hist_vars(struct hist_trigger_data *hist_data)
+{
+ struct hist_field *hist_field;
+ int i;
+
+ for_each_hist_field(i, hist_data) {
+ hist_field = hist_data->fields[i];
+ if (field_has_hist_vars(hist_field, 0))
+ return true;
+ }
+
+ return false;
+}
+
+static int save_hist_vars(struct hist_trigger_data *hist_data)
+{
+ struct trace_array *tr = hist_data->event_file->tr;
+ struct hist_var_data *var_data;
+
+ var_data = find_hist_vars(hist_data);
+ if (var_data)
+ return 0;
+
+ if (trace_array_get(tr) < 0)
+ return -ENODEV;
+
+ var_data = kzalloc(sizeof(*var_data), GFP_KERNEL);
+ if (!var_data) {
+ trace_array_put(tr);
+ return -ENOMEM;
+ }
+
+ var_data->hist_data = hist_data;
+ list_add(&var_data->list, &tr->hist_vars);
+
+ return 0;
+}
+
+static void remove_hist_vars(struct hist_trigger_data *hist_data)
+{
+ struct trace_array *tr = hist_data->event_file->tr;
+ struct hist_var_data *var_data;
+
+ var_data = find_hist_vars(hist_data);
+ if (!var_data)
+ return;
+
+ if (WARN_ON(check_var_refs(hist_data)))
+ return;
+
+ list_del(&var_data->list);
+
+ kfree(var_data);
+
+ trace_array_put(tr);
+}
+
static struct hist_field *find_var_field(struct hist_trigger_data *hist_data,
const char *var_name)
{
@@ -313,10 +531,148 @@ static struct hist_field *find_var(struct hist_trigger_data *hist_data,
return NULL;
}
+static struct trace_event_file *find_var_file(struct trace_array *tr,
+ char *system,
+ char *event_name,
+ char *var_name)
+{
+ struct hist_trigger_data *var_hist_data;
+ struct hist_var_data *var_data;
+ struct trace_event_call *call;
+ struct trace_event_file *file, *found = NULL;
+ const char *name;
+
+ list_for_each_entry(var_data, &tr->hist_vars, list) {
+ var_hist_data = var_data->hist_data;
+ file = var_hist_data->event_file;
+ call = file->event_call;
+ name = trace_event_name(call);
+
+ if (!system || !event_name) {
+ if (find_var(var_hist_data, file, var_name)) {
+ if (found) {
+ return NULL;
+ }
+
+ found = file;
+ }
+ continue;
+ }
+
+ if (strcmp(event_name, name) != 0)
+ continue;
+ if (strcmp(system, call->class->system) != 0)
+ continue;
+
+ found = file;
+ break;
+ }
+
+ return found;
+}
+
+static struct hist_field *find_file_var(struct trace_event_file *file,
+ const char *var_name)
+{
+ struct hist_trigger_data *test_data;
+ struct event_trigger_data *test;
+ struct hist_field *hist_field;
+
+ list_for_each_entry_rcu(test, &file->triggers, list) {
+ if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
+ test_data = test->private_data;
+ hist_field = find_var_field(test_data, var_name);
+ if (hist_field)
+ return hist_field;
+ }
+ }
+
+ return NULL;
+}
+
+static struct hist_field *find_event_var(struct hist_trigger_data *hist_data,
+ char *system,
+ char *event_name,
+ char *var_name)
+{
+ struct trace_array *tr = hist_data->event_file->tr;
+ struct hist_field *hist_field = NULL;
+ struct trace_event_file *file;
+
+ file = find_var_file(tr, system, event_name, var_name);
+ if (!file)
+ return NULL;
+
+ hist_field = find_file_var(file, var_name);
+
+ return hist_field;
+}
+
struct hist_elt_data {
char *comm;
+ u64 *var_ref_vals;
};
+static u64 hist_field_var_ref(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ struct hist_elt_data *elt_data;
+ u64 var_val = 0;
+
+ elt_data = elt->private_data;
+ var_val = elt_data->var_ref_vals[hist_field->var_ref_idx];
+
+ return var_val;
+}
+
+static bool resolve_var_refs(struct hist_trigger_data *hist_data, void *key,
+ u64 *var_ref_vals, bool self)
+{
+ struct hist_trigger_data *var_data;
+ struct tracing_map_elt *var_elt;
+ struct hist_field *hist_field;
+ unsigned int i, var_idx;
+ bool resolved = true;
+ u64 var_val = 0;
+
+ for (i = 0; i < hist_data->n_var_refs; i++) {
+ hist_field = hist_data->var_refs[i];
+ var_idx = hist_field->var.idx;
+ var_data = hist_field->var.hist_data;
+
+ if (var_data == NULL) {
+ resolved = false;
+ break;
+ }
+
+ if ((self && var_data != hist_data) ||
+ (!self && var_data == hist_data))
+ continue;
+
+ var_elt = tracing_map_lookup(var_data->map, key);
+ if (!var_elt) {
+ resolved = false;
+ break;
+ }
+
+ if (!tracing_map_var_set(var_elt, var_idx)) {
+ resolved = false;
+ break;
+ }
+
+ if (self || !hist_field->read_once)
+ var_val = tracing_map_read_var(var_elt, var_idx);
+ else
+ var_val = tracing_map_read_var_once(var_elt, var_idx);
+
+ var_ref_vals[i] = var_val;
+ }
+
+ return resolved;
+}
+
static const char *hist_field_name(struct hist_field *field,
unsigned int level)
{
@@ -331,8 +687,20 @@ static const char *hist_field_name(struct hist_field *field,
field_name = hist_field_name(field->operands[0], ++level);
else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
field_name = "$common_timestamp";
- else if (field->flags & HIST_FIELD_FL_EXPR)
- field_name = field->name;
+ else if (field->flags & HIST_FIELD_FL_EXPR ||
+ field->flags & HIST_FIELD_FL_VAR_REF) {
+ if (field->system) {
+ static char full_name[MAX_FILTER_STR_VAL];
+
+ strcat(full_name, field->system);
+ strcat(full_name, ".");
+ strcat(full_name, field->event_name);
+ strcat(full_name, ".");
+ strcat(full_name, field->name);
+ field_name = full_name;
+ } else
+ field_name = field->name;
+ }
if (field_name == NULL)
field_name = "";
@@ -636,6 +1004,8 @@ static char *expr_str(struct hist_field *field, unsigned int level)
return expr;
}
+ if (field->operands[0]->flags & HIST_FIELD_FL_VAR_REF)
+ strcat(expr, "$");
strcat(expr, hist_field_name(field->operands[0], 0));
if (field->operands[0]->flags) {
const char *flags_str = get_hist_field_flags(field->operands[0]);
@@ -658,6 +1028,8 @@ static char *expr_str(struct hist_field *field, unsigned int level)
return NULL;
}
+ if (field->operands[1]->flags & HIST_FIELD_FL_VAR_REF)
+ strcat(expr, "$");
strcat(expr, hist_field_name(field->operands[1], 0));
if (field->operands[1]->flags) {
const char *flags_str = get_hist_field_flags(field->operands[1]);
@@ -737,6 +1109,11 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
if (flags & HIST_FIELD_FL_EXPR)
goto out; /* caller will populate */
+ if (flags & HIST_FIELD_FL_VAR_REF) {
+ hist_field->fn = hist_field_var_ref;
+ goto out;
+ }
+
if (flags & HIST_FIELD_FL_HITCOUNT) {
hist_field->fn = hist_field_counter;
hist_field->size = sizeof(u64);
@@ -830,6 +1207,77 @@ static void destroy_hist_fields(struct hist_trigger_data *hist_data)
}
}
+static int init_var_ref(struct hist_field *ref_field,
+ struct hist_field *var_field,
+ char *system, char *event_name)
+{
+ int err = 0;
+
+ ref_field->var.idx = var_field->var.idx;
+ ref_field->var.hist_data = var_field->hist_data;
+ ref_field->size = var_field->size;
+ ref_field->is_signed = var_field->is_signed;
+
+ if (system) {
+ ref_field->system = kstrdup(system, GFP_KERNEL);
+ if (!ref_field->system)
+ return -ENOMEM;
+ }
+
+ if (event_name) {
+ ref_field->event_name = kstrdup(event_name, GFP_KERNEL);
+ if (!ref_field->event_name) {
+ err = -ENOMEM;
+ goto free;
+ }
+ }
+
+ ref_field->name = kstrdup(var_field->var.name, GFP_KERNEL);
+ if (!ref_field->name) {
+ err = -ENOMEM;
+ goto free;
+ }
+
+ ref_field->type = kstrdup(var_field->type, GFP_KERNEL);
+ if (!ref_field->type) {
+ err = -ENOMEM;
+ goto free;
+ }
+ out:
+ return err;
+ free:
+ kfree(ref_field->system);
+ kfree(ref_field->event_name);
+ kfree(ref_field->name);
+
+ goto out;
+}
+
+static struct hist_field *create_var_ref(struct hist_field *var_field,
+ char *system, char *event_name)
+{
+ unsigned long flags = HIST_FIELD_FL_VAR_REF;
+ struct hist_field *ref_field;
+
+ ref_field = create_hist_field(var_field->hist_data, NULL, flags, NULL);
+ if (ref_field) {
+ if (init_var_ref(ref_field, var_field, system, event_name)) {
+ destroy_hist_field(ref_field, 0);
+ return NULL;
+ }
+ }
+
+ return ref_field;
+}
+
+static bool is_var_ref(char *var_name)
+{
+ if (!var_name || strlen(var_name) < 2 || var_name[0] != '$')
+ return false;
+
+ return true;
+}
+
static char *field_name_from_var(struct hist_trigger_data *hist_data,
char *var_name)
{
@@ -841,7 +1289,7 @@ static char *field_name_from_var(struct hist_trigger_data *hist_data,
if (strcmp(var_name, name) == 0) {
field = hist_data->attrs->var_defs.expr[i];
- if (contains_operator(field))
+ if (contains_operator(field) || is_var_ref(field))
continue;
return field;
}
@@ -853,11 +1301,32 @@ static char *field_name_from_var(struct hist_trigger_data *hist_data,
static char *local_field_var_ref(struct hist_trigger_data *hist_data,
char *var_name)
{
+ if (!is_var_ref(var_name))
+ return NULL;
+
var_name++;
return field_name_from_var(hist_data, var_name);
}
+static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
+ char *system, char *event_name,
+ char *var_name)
+{
+ struct hist_field *var_field = NULL, *ref_field = NULL;
+
+ if (!is_var_ref(var_name))
+ return NULL;
+
+ var_name++;
+
+ var_field = find_event_var(hist_data, system, event_name, var_name);
+ if (var_field)
+ ref_field = create_var_ref(var_field, system, event_name);
+
+ return ref_field;
+}
+
static struct ftrace_event_field *
parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
char *field_str, unsigned long *flags)
@@ -914,13 +1383,38 @@ struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
struct trace_event_file *file, char *str,
unsigned long *flags, char *var_name)
{
- char *s;
+ char *s, *ref_system = NULL, *ref_event = NULL, *ref_var = str;
struct ftrace_event_field *field = NULL;
struct hist_field *hist_field = NULL;
int ret = 0;
- s = local_field_var_ref(hist_data, str);
- if (s)
+ s = strchr(str, '.');
+ if (s) {
+ s = strchr(++s, '.');
+ if (s) {
+ ref_system = strsep(&str, ".");
+ if (!str) {
+ ret = -EINVAL;
+ goto out;
+ }
+ ref_event = strsep(&str, ".");
+ if (!str) {
+ ret = -EINVAL;
+ goto out;
+ }
+ ref_var = str;
+ }
+ }
+
+ s = local_field_var_ref(hist_data, ref_var);
+ if (!s) {
+ hist_field = parse_var_ref(hist_data, ref_system, ref_event, ref_var);
+ if (hist_field) {
+ hist_data->var_refs[hist_data->n_var_refs] = hist_field;
+ hist_field->var_ref_idx = hist_data->n_var_refs++;
+ return hist_field;
+ }
+ } else
str = s;
field = parse_field(hist_data, file, str, flags);
@@ -1094,6 +1588,9 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
goto free;
}
+ operand1->read_once = true;
+ operand2->read_once = true;
+
expr->operands[0] = operand1;
expr->operands[1] = operand2;
expr->operator = field_op;
@@ -1266,6 +1763,12 @@ static int create_key_field(struct hist_trigger_data *hist_data,
goto out;
}
+ if (hist_field->flags & HIST_FIELD_FL_VAR_REF) {
+ destroy_hist_field(hist_field, 0);
+ ret = -EINVAL;
+ goto out;
+ }
+
key_size = hist_field->size;
}
@@ -1604,6 +2107,7 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)
hist_data->attrs = attrs;
hist_data->remove = remove;
+ hist_data->event_file = file;
ret = create_hist_fields(hist_data, file);
if (ret)
@@ -1626,12 +2130,6 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)
ret = create_tracing_map_fields(hist_data);
if (ret)
goto free;
-
- ret = tracing_map_init(hist_data->map);
- if (ret)
- goto free;
-
- hist_data->event_file = file;
out:
return hist_data;
free:
@@ -1646,12 +2144,17 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)
static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
struct tracing_map_elt *elt, void *rec,
- struct ring_buffer_event *rbe)
+ struct ring_buffer_event *rbe,
+ u64 *var_ref_vals)
{
+ struct hist_elt_data *elt_data;
struct hist_field *hist_field;
unsigned int i, var_idx;
u64 hist_val;
+ elt_data = elt->private_data;
+ elt_data->var_ref_vals = var_ref_vals;
+
for_each_hist_val_field(i, hist_data) {
hist_field = hist_data->fields[i];
hist_val = hist_field->fn(hist_field, elt, rbe, rec);
@@ -1703,6 +2206,7 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec,
struct hist_trigger_data *hist_data = data->private_data;
bool use_compound_key = (hist_data->n_keys > 1);
unsigned long entries[HIST_STACKTRACE_DEPTH];
+ u64 var_ref_vals[TRACING_MAP_VARS_MAX];
char compound_key[HIST_KEY_SIZE_MAX];
struct tracing_map_elt *elt = NULL;
struct stack_trace stacktrace;
@@ -1742,9 +2246,15 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec,
if (use_compound_key)
key = compound_key;
+ if (hist_data->n_var_refs &&
+ !resolve_var_refs(hist_data, key, var_ref_vals, false))
+ return;
+
elt = tracing_map_insert(hist_data->map, key);
- if (elt)
- hist_trigger_elt_update(hist_data, elt, rec, rbe);
+ if (!elt)
+ return;
+
+ hist_trigger_elt_update(hist_data, elt, rec, rbe, var_ref_vals);
}
static void hist_trigger_stacktrace_print(struct seq_file *m,
@@ -1959,8 +2469,11 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
seq_puts(m, "$common_timestamp");
- else if (field_name)
+ else if (field_name) {
+ if (hist_field->flags & HIST_FIELD_FL_VAR_REF)
+ seq_putc(m, '$');
seq_printf(m, "%s", field_name);
+ }
if (hist_field->flags) {
const char *flags_str = get_hist_field_flags(hist_field);
@@ -2100,7 +2613,11 @@ static void event_hist_trigger_free(struct event_trigger_ops *ops,
if (!data->ref) {
if (data->name)
del_named_trigger(data);
+
trigger_data_free(data);
+
+ remove_hist_vars(hist_data);
+
destroy_hist_data(hist_data);
}
}
@@ -2313,23 +2830,55 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
goto out;
}
- list_add_rcu(&data->list, &file->triggers);
ret++;
- update_cond_flag(file);
-
if (hist_data->enable_timestamps)
tracing_set_time_stamp_abs(file->tr, true);
+ out:
+ return ret;
+}
+
+static int hist_trigger_enable(struct event_trigger_data *data,
+ struct trace_event_file *file)
+{
+ int ret = 0;
+
+ list_add_tail_rcu(&data->list, &file->triggers);
+
+ update_cond_flag(file);
if (trace_event_trigger_enable_disable(file, 1) < 0) {
list_del_rcu(&data->list);
update_cond_flag(file);
ret--;
}
- out:
+
return ret;
}
+static bool hist_trigger_check_refs(struct event_trigger_data *data,
+ struct trace_event_file *file)
+{
+ struct hist_trigger_data *hist_data = data->private_data;
+ struct event_trigger_data *test, *named_data = NULL;
+
+ if (hist_data->attrs->name)
+ named_data = find_named_trigger(hist_data->attrs->name);
+
+ list_for_each_entry_rcu(test, &file->triggers, list) {
+ if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
+ if (!hist_trigger_match(data, test, named_data, false))
+ continue;
+ hist_data = test->private_data;
+ if (check_var_refs(hist_data))
+ return true;
+ break;
+ }
+ }
+
+ return false;
+}
+
static void hist_unregister_trigger(char *glob, struct event_trigger_ops *ops,
struct event_trigger_data *data,
struct trace_event_file *file)
@@ -2362,11 +2911,30 @@ static void hist_unregister_trigger(char *glob, struct event_trigger_ops *ops,
}
}
+static bool hist_file_check_refs(struct trace_event_file *file)
+{
+ struct hist_trigger_data *hist_data;
+ struct event_trigger_data *test;
+
+ list_for_each_entry_rcu(test, &file->triggers, list) {
+ if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
+ hist_data = test->private_data;
+ if (check_var_refs(hist_data))
+ return true;
+ }
+ }
+
+ return false;
+}
+
static void hist_unreg_all(struct trace_event_file *file)
{
struct event_trigger_data *test, *n;
struct hist_trigger_data *hist_data;
+ if (hist_file_check_refs(file))
+ return;
+
list_for_each_entry_safe(test, n, &file->triggers, list) {
if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
hist_data = test->private_data;
@@ -2442,6 +3010,11 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
}
if (remove) {
+ if (hist_trigger_check_refs(trigger_data, file)) {
+ ret = -EBUSY;
+ goto out_free;
+ }
+
cmd_ops->unreg(glob+1, trigger_ops, trigger_data, file);
ret = 0;
goto out_free;
@@ -2459,14 +3032,33 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
goto out_free;
} else if (ret < 0)
goto out_free;
+
+ if (get_named_trigger_data(trigger_data))
+ goto enable;
+
+ if (has_hist_vars(hist_data))
+ save_hist_vars(hist_data);
+
+ ret = tracing_map_init(hist_data->map);
+ if (ret)
+ goto out_unreg;
+enable:
+ ret = hist_trigger_enable(trigger_data, file);
+ if (ret)
+ goto out_unreg;
+
/* Just return zero, not the number of registered triggers */
ret = 0;
out:
return ret;
+ out_unreg:
+ cmd_ops->unreg(glob+1, trigger_ops, trigger_data, file);
out_free:
if (cmd_ops->set_filter)
cmd_ops->set_filter(NULL, trigger_data, NULL);
+ remove_hist_vars(hist_data);
+
kfree(trigger_data);
destroy_hist_data(hist_data);
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index 9b0fe31..a7a5bed 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -909,6 +909,12 @@ void set_named_trigger_data(struct event_trigger_data *data,
data->named_data = named_data;
}
+struct event_trigger_data *
+get_named_trigger_data(struct event_trigger_data *data)
+{
+ return data->named_data;
+}
+
static void
traceon_trigger(struct event_trigger_data *data, void *rec,
struct ring_buffer_event *event)
--
1.9.3
From 1584233678724647189@xxx Thu Nov 16 14:36:10 +0000 2017
X-GM-THRID: 1584233678724647189
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Future support for synthetic events requires hist_field 'type'
information, so add a field for that.
Also, make other hist_field attribute usage consistent (size,
is_signed, etc).
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 33 +++++++++++++++++++++++++++++++++
1 file changed, 33 insertions(+)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index db903ce..d22cdfd 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -54,6 +54,7 @@ struct hist_field {
unsigned int size;
unsigned int offset;
unsigned int is_signed;
+ const char *type;
struct hist_field *operands[HIST_FIELD_OPERANDS_MAX];
struct hist_trigger_data *hist_data;
struct hist_var var;
@@ -712,6 +713,7 @@ static void destroy_hist_field(struct hist_field *hist_field,
kfree(hist_field->var.name);
kfree(hist_field->name);
+ kfree(hist_field->type);
kfree(hist_field);
}
@@ -737,6 +739,10 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
if (flags & HIST_FIELD_FL_HITCOUNT) {
hist_field->fn = hist_field_counter;
+ hist_field->size = sizeof(u64);
+ hist_field->type = kstrdup("u64", GFP_KERNEL);
+ if (!hist_field->type)
+ goto free;
goto out;
}
@@ -750,12 +756,18 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
hist_field->fn = hist_field_log2;
hist_field->operands[0] = create_hist_field(hist_data, field, fl, NULL);
hist_field->size = hist_field->operands[0]->size;
+ hist_field->type = kstrdup(hist_field->operands[0]->type, GFP_KERNEL);
+ if (!hist_field->type)
+ goto free;
goto out;
}
if (flags & HIST_FIELD_FL_TIMESTAMP) {
hist_field->fn = hist_field_timestamp;
hist_field->size = sizeof(u64);
+ hist_field->type = kstrdup("u64", GFP_KERNEL);
+ if (!hist_field->type)
+ goto free;
goto out;
}
@@ -765,6 +777,11 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
if (is_string_field(field)) {
flags |= HIST_FIELD_FL_STRING;
+ hist_field->size = MAX_FILTER_STR_VAL;
+ hist_field->type = kstrdup(field->type, GFP_KERNEL);
+ if (!hist_field->type)
+ goto free;
+
if (field->filter_type == FILTER_STATIC_STRING)
hist_field->fn = hist_field_string;
else if (field->filter_type == FILTER_DYN_STRING)
@@ -772,6 +789,12 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
else
hist_field->fn = hist_field_pstring;
} else {
+ hist_field->size = field->size;
+ hist_field->is_signed = field->is_signed;
+ hist_field->type = kstrdup(field->type, GFP_KERNEL);
+ if (!hist_field->type)
+ goto free;
+
hist_field->fn = select_value_fn(field->size,
field->is_signed);
if (!hist_field->fn) {
@@ -981,6 +1004,11 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
expr->operands[0] = operand1;
expr->operator = FIELD_OP_UNARY_MINUS;
expr->name = expr_str(expr, 0);
+ expr->type = kstrdup(operand1->type, GFP_KERNEL);
+ if (!expr->type) {
+ ret = -ENOMEM;
+ goto free;
+ }
return expr;
free:
@@ -1070,6 +1098,11 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
expr->operands[1] = operand2;
expr->operator = field_op;
expr->name = expr_str(expr, 0);
+ expr->type = kstrdup(operand1->type, GFP_KERNEL);
+ if (!expr->type) {
+ ret = -ENOMEM;
+ goto free;
+ }
switch (field_op) {
case FIELD_OP_MINUS:
--
1.9.3
From 1583558427077108950@xxx Thu Nov 09 03:43:20 +0000 2017
X-GM-THRID: 1583483886934922232
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
Add support for simple addition, subtraction, and unary expressions
(-(expr) and expr, where expr = b-a, a+b, a+b+c) to hist triggers, in
order to support a minimal set of useful inter-event calculations.
These operations are needed for calculating latencies between events
(timestamp1-timestamp0) and for combined latencies (latencies over 3
or more events).
In the process, factor out some common code from key and value
parsing.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 513 +++++++++++++++++++++++++++++++++------
1 file changed, 440 insertions(+), 73 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index b33c2bc..f6c59a5 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -32,6 +32,13 @@ typedef u64 (*hist_field_fn_t) (struct hist_field *field, void *event,
#define HIST_FIELD_OPERANDS_MAX 2
#define HIST_FIELDS_MAX (TRACING_MAP_FIELDS_MAX + TRACING_MAP_VARS_MAX)
+enum field_op_id {
+ FIELD_OP_NONE,
+ FIELD_OP_PLUS,
+ FIELD_OP_MINUS,
+ FIELD_OP_UNARY_MINUS,
+};
+
struct hist_var {
char *name;
struct hist_trigger_data *hist_data;
@@ -48,6 +55,8 @@ struct hist_field {
struct hist_field *operands[HIST_FIELD_OPERANDS_MAX];
struct hist_trigger_data *hist_data;
struct hist_var var;
+ enum field_op_id operator;
+ char *name;
};
static u64 hist_field_none(struct hist_field *field, void *event,
@@ -98,6 +107,41 @@ static u64 hist_field_log2(struct hist_field *hist_field, void *event,
return (u64) ilog2(roundup_pow_of_two(val));
}
+static u64 hist_field_plus(struct hist_field *hist_field, void *event,
+ struct ring_buffer_event *rbe)
+{
+ struct hist_field *operand1 = hist_field->operands[0];
+ struct hist_field *operand2 = hist_field->operands[1];
+
+ u64 val1 = operand1->fn(operand1, event, rbe);
+ u64 val2 = operand2->fn(operand2, event, rbe);
+
+ return val1 + val2;
+}
+
+static u64 hist_field_minus(struct hist_field *hist_field, void *event,
+ struct ring_buffer_event *rbe)
+{
+ struct hist_field *operand1 = hist_field->operands[0];
+ struct hist_field *operand2 = hist_field->operands[1];
+
+ u64 val1 = operand1->fn(operand1, event, rbe);
+ u64 val2 = operand2->fn(operand2, event, rbe);
+
+ return val1 - val2;
+}
+
+static u64 hist_field_unary_minus(struct hist_field *hist_field, void *event,
+ struct ring_buffer_event *rbe)
+{
+ struct hist_field *operand = hist_field->operands[0];
+
+ s64 sval = (s64)operand->fn(operand, event, rbe);
+ u64 val = (u64)-sval;
+
+ return val;
+}
+
#define DEFINE_HIST_FIELD_FN(type) \
static u64 hist_field_##type(struct hist_field *hist_field, \
void *event, \
@@ -147,6 +191,7 @@ enum hist_field_flags {
HIST_FIELD_FL_TIMESTAMP = 1 << 10,
HIST_FIELD_FL_TIMESTAMP_USECS = 1 << 11,
HIST_FIELD_FL_VAR = 1 << 12,
+ HIST_FIELD_FL_EXPR = 1 << 13,
};
struct var_defs {
@@ -258,6 +303,8 @@ static const char *hist_field_name(struct hist_field *field,
field_name = hist_field_name(field->operands[0], ++level);
else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
field_name = "$common_timestamp";
+ else if (field->flags & HIST_FIELD_FL_EXPR)
+ field_name = field->name;
if (field_name == NULL)
field_name = "";
@@ -519,6 +566,93 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)
return flags_str;
}
+static char *expr_str(struct hist_field *field, unsigned int level)
+{
+ char *expr;
+
+ if (level > 1)
+ return NULL;
+
+ expr = kzalloc(MAX_FILTER_STR_VAL, GFP_KERNEL);
+ if (!expr)
+ return NULL;
+
+ if (field->operator == FIELD_OP_UNARY_MINUS) {
+ char *subexpr;
+
+ strcat(expr, "-(");
+ subexpr = expr_str(field->operands[0], ++level);
+ if (!subexpr) {
+ kfree(expr);
+ return NULL;
+ }
+ strcat(expr, subexpr);
+ strcat(expr, ")");
+
+ return expr;
+ }
+
+ strcat(expr, hist_field_name(field->operands[0], 0));
+ if (field->operands[0]->flags) {
+ const char *flags_str = get_hist_field_flags(field->operands[0]);
+
+ if (flags_str) {
+ strcat(expr, ".");
+ strcat(expr, flags_str);
+ }
+ }
+
+ switch (field->operator) {
+ case FIELD_OP_MINUS:
+ strcat(expr, "-");
+ break;
+ case FIELD_OP_PLUS:
+ strcat(expr, "+");
+ break;
+ default:
+ kfree(expr);
+ return NULL;
+ }
+
+ strcat(expr, hist_field_name(field->operands[1], 0));
+ if (field->operands[1]->flags) {
+ const char *flags_str = get_hist_field_flags(field->operands[1]);
+
+ if (flags_str) {
+ strcat(expr, ".");
+ strcat(expr, flags_str);
+ }
+ }
+
+ return expr;
+}
+
+static int contains_operator(char *str)
+{
+ enum field_op_id field_op = FIELD_OP_NONE;
+ char *op;
+
+ op = strpbrk(str, "+-");
+ if (!op)
+ return FIELD_OP_NONE;
+
+ switch (*op) {
+ case '-':
+ if (*str == '-')
+ field_op = FIELD_OP_UNARY_MINUS;
+ else
+ field_op = FIELD_OP_MINUS;
+ break;
+ case '+':
+ field_op = FIELD_OP_PLUS;
+ break;
+ default:
+ break;
+ }
+
+ return field_op;
+}
+
static void destroy_hist_field(struct hist_field *hist_field,
unsigned int level)
{
@@ -534,6 +668,7 @@ static void destroy_hist_field(struct hist_field *hist_field,
destroy_hist_field(hist_field->operands[i], level + 1);
kfree(hist_field->var.name);
+ kfree(hist_field->name);
kfree(hist_field);
}
@@ -554,6 +689,9 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
hist_field->hist_data = hist_data;
+ if (flags & HIST_FIELD_FL_EXPR)
+ goto out; /* caller will populate */
+
if (flags & HIST_FIELD_FL_HITCOUNT) {
hist_field->fn = hist_field_counter;
goto out;
@@ -626,59 +764,323 @@ static void destroy_hist_fields(struct hist_trigger_data *hist_data)
}
}
-static int create_hitcount_val(struct hist_trigger_data *hist_data)
+static char *field_name_from_var(struct hist_trigger_data *hist_data,
+ char *var_name)
{
- hist_data->fields[HITCOUNT_IDX] =
- create_hist_field(hist_data, NULL, HIST_FIELD_FL_HITCOUNT, NULL);
- if (!hist_data->fields[HITCOUNT_IDX])
- return -ENOMEM;
+ char *name, *field;
+ unsigned int i;
- hist_data->n_vals++;
- hist_data->n_fields++;
+ for (i = 0; i < hist_data->attrs->var_defs.n_vars; i++) {
+ name = hist_data->attrs->var_defs.name[i];
- if (WARN_ON(hist_data->n_vals > TRACING_MAP_VALS_MAX))
- return -EINVAL;
+ if (strcmp(var_name, name) == 0) {
+ field = hist_data->attrs->var_defs.expr[i];
+ if (contains_operator(field))
+ continue;
+ return field;
+ }
+ }
- return 0;
+ return NULL;
}
-static int __create_val_field(struct hist_trigger_data *hist_data,
- unsigned int val_idx,
- struct trace_event_file *file,
- char *var_name, char *field_str,
- unsigned long flags)
+static char *local_field_var_ref(struct hist_trigger_data *hist_data,
+ char *var_name)
+{
+ var_name++;
+
+ return field_name_from_var(hist_data, var_name);
+}
+
+static struct ftrace_event_field *
+parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
+ char *field_str, unsigned long *flags)
{
struct ftrace_event_field *field = NULL;
- char *field_name;
- int ret = 0;
+ char *field_name, *modifier, *str;
+
+ modifier = str = kstrdup(field_str, GFP_KERNEL);
+ if (!modifier)
+ return ERR_PTR(-ENOMEM);
- field_name = strsep(&field_str, ".");
- if (field_str) {
- if (strcmp(field_str, "hex") == 0)
- flags |= HIST_FIELD_FL_HEX;
+ field_name = strsep(&modifier, ".");
+ if (modifier) {
+ if (strcmp(modifier, "hex") == 0)
+ *flags |= HIST_FIELD_FL_HEX;
+ else if (strcmp(modifier, "sym") == 0)
+ *flags |= HIST_FIELD_FL_SYM;
+ else if (strcmp(modifier, "sym-offset") == 0)
+ *flags |= HIST_FIELD_FL_SYM_OFFSET;
+ else if ((strcmp(modifier, "execname") == 0) &&
+ (strcmp(field_name, "common_pid") == 0))
+ *flags |= HIST_FIELD_FL_EXECNAME;
+ else if (strcmp(modifier, "syscall") == 0)
+ *flags |= HIST_FIELD_FL_SYSCALL;
+ else if (strcmp(modifier, "log2") == 0)
+ *flags |= HIST_FIELD_FL_LOG2;
+ else if (strcmp(modifier, "usecs") == 0)
+ *flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
else {
- ret = -EINVAL;
+ field = ERR_PTR(-EINVAL);
goto out;
}
}
if (strcmp(field_name, "$common_timestamp") == 0) {
- flags |= HIST_FIELD_FL_TIMESTAMP;
+ *flags |= HIST_FIELD_FL_TIMESTAMP;
hist_data->enable_timestamps = true;
+ if (*flags & HIST_FIELD_FL_TIMESTAMP_USECS)
+ hist_data->attrs->ts_in_usecs = true;
} else {
field = trace_find_event_field(file->event_call, field_name);
if (!field || !field->size) {
- ret = -EINVAL;
+ field = ERR_PTR(-EINVAL);
goto out;
}
}
+ out:
+ kfree(str);
+
+ return field;
+}
- hist_data->fields[val_idx] = create_hist_field(hist_data, field, flags, var_name);
- if (!hist_data->fields[val_idx]) {
+struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
+ struct trace_event_file *file, char *str,
+ unsigned long *flags, char *var_name)
+{
+ char *s;
+ struct ftrace_event_field *field = NULL;
+ struct hist_field *hist_field = NULL;
+ int ret = 0;
+
+ s = local_field_var_ref(hist_data, str);
+ if (s)
+ str = s;
+
+ field = parse_field(hist_data, file, str, flags);
+ if (IS_ERR(field)) {
+ ret = PTR_ERR(field);
+ goto out;
+ }
+
+ hist_field = create_hist_field(hist_data, field, *flags, var_name);
+ if (!hist_field) {
ret = -ENOMEM;
goto out;
}
+ return hist_field;
+ out:
+ return ERR_PTR(ret);
+}
+
+static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
+ struct trace_event_file *file,
+ char *str, unsigned long flags,
+ char *var_name, unsigned int level);
+
+static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
+ struct trace_event_file *file,
+ char *str, unsigned long flags,
+ char *var_name, unsigned int level)
+{
+ struct hist_field *operand1, *expr = NULL;
+ unsigned long operand_flags;
+ int ret = 0;
+ char *s;
+
+ // we support only -(xxx) i.e. explicit parens required
+
+ if (level > 2) {
+ ret = -EINVAL;
+ goto free;
+ }
+
+ str++; // skip leading '-'
+
+ s = strchr(str, '(');
+ if (s)
+ str++;
+ else {
+ ret = -EINVAL;
+ goto free;
+ }
+
+ s = strchr(str, ')');
+ if (s)
+ *s = '\0';
+ else {
+ ret = -EINVAL; // no closing ')'
+ goto free;
+ }
+
+ strsep(&str, "(");
+ if (!str) {
+ ret = -EINVAL;
+ goto free;
+ }
+
+ flags |= HIST_FIELD_FL_EXPR;
+ expr = create_hist_field(hist_data, NULL, flags, var_name);
+ if (!expr) {
+ ret = -ENOMEM;
+ goto free;
+ }
+
+ operand_flags = 0;
+ operand1 = parse_expr(hist_data, file, str, operand_flags, NULL, ++level);
+ if (IS_ERR(operand1)) {
+ ret = PTR_ERR(operand1);
+ goto free;
+ }
+
+ expr->fn = hist_field_unary_minus;
+ expr->operands[0] = operand1;
+ expr->operator = FIELD_OP_UNARY_MINUS;
+ expr->name = expr_str(expr, 0);
+
+ return expr;
+ free:
+ destroy_hist_field(expr, 0);
+ return ERR_PTR(ret);
+}
+
+static int check_expr_operands(struct hist_field *operand1,
+ struct hist_field *operand2)
+{
+ unsigned long operand1_flags = operand1->flags;
+ unsigned long operand2_flags = operand2->flags;
+
+ if ((operand1_flags & HIST_FIELD_FL_TIMESTAMP_USECS) !=
+ (operand2_flags & HIST_FIELD_FL_TIMESTAMP_USECS))
+ return -EINVAL;
+
+ return 0;
+}
+
+static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
+ struct trace_event_file *file,
+ char *str, unsigned long flags,
+ char *var_name, unsigned int level)
+{
+ struct hist_field *operand1 = NULL, *operand2 = NULL, *expr = NULL;
+ unsigned long operand_flags;
+ int field_op, ret = -EINVAL;
+ char *sep, *operand1_str;
+
+ if (level > 2)
+ return ERR_PTR(-EINVAL);
+
+ field_op = contains_operator(str);
+
+ if (field_op == FIELD_OP_NONE)
+ return parse_atom(hist_data, file, str, &flags, var_name);
+
+ if (field_op == FIELD_OP_UNARY_MINUS)
+ return parse_unary(hist_data, file, str, flags, var_name, ++level);
+
+ switch (field_op) {
+ case FIELD_OP_MINUS:
+ sep = "-";
+ break;
+ case FIELD_OP_PLUS:
+ sep = "+";
+ break;
+ default:
+ goto free;
+ }
+
+ operand1_str = strsep(&str, sep);
+ if (!operand1_str || !str)
+ goto free;
+
+ operand_flags = 0;
+ operand1 = parse_atom(hist_data, file, operand1_str,
+ &operand_flags, NULL);
+ if (IS_ERR(operand1)) {
+ ret = PTR_ERR(operand1);
+ operand1 = NULL;
+ goto free;
+ }
+
+ // rest of string could be another expression e.g. b+c in a+b+c
+ operand_flags = 0;
+ operand2 = parse_expr(hist_data, file, str, operand_flags, NULL, ++level);
+ if (IS_ERR(operand2)) {
+ ret = PTR_ERR(operand2);
+ operand2 = NULL;
+ goto free;
+ }
+
+ ret = check_expr_operands(operand1, operand2);
+ if (ret)
+ goto free;
+
+ flags |= HIST_FIELD_FL_EXPR;
+ expr = create_hist_field(hist_data, NULL, flags, var_name);
+ if (!expr) {
+ ret = -ENOMEM;
+ goto free;
+ }
+
+ expr->operands[0] = operand1;
+ expr->operands[1] = operand2;
+ expr->operator = field_op;
+ expr->name = expr_str(expr, 0);
+
+ switch (field_op) {
+ case FIELD_OP_MINUS:
+ expr->fn = hist_field_minus;
+ break;
+ case FIELD_OP_PLUS:
+ expr->fn = hist_field_plus;
+ break;
+ default:
+ goto free;
+ }
+
+ return expr;
+ free:
+ destroy_hist_field(operand1, 0);
+ destroy_hist_field(operand2, 0);
+ destroy_hist_field(expr, 0);
+
+ return ERR_PTR(ret);
+}
+
+static int create_hitcount_val(struct hist_trigger_data *hist_data)
+{
+ hist_data->fields[HITCOUNT_IDX] =
+ create_hist_field(hist_data, NULL, HIST_FIELD_FL_HITCOUNT, NULL);
+ if (!hist_data->fields[HITCOUNT_IDX])
+ return -ENOMEM;
+
+ hist_data->n_vals++;
+ hist_data->n_fields++;
+
+ if (WARN_ON(hist_data->n_vals > TRACING_MAP_VALS_MAX))
+ return -EINVAL;
+
+ return 0;
+}
+
+static int __create_val_field(struct hist_trigger_data *hist_data,
+ unsigned int val_idx,
+ struct trace_event_file *file,
+ char *var_name, char *field_str,
+ unsigned long flags)
+{
+ struct hist_field *hist_field;
+ int ret = 0;
+
+ hist_field = parse_expr(hist_data, file, field_str, flags, var_name, 0);
+ if (IS_ERR(hist_field)) {
+ ret = PTR_ERR(hist_field);
+ goto out;
+ }
+
+ hist_data->fields[val_idx] = hist_field;
+
++hist_data->n_vals;
++hist_data->n_fields;
@@ -765,8 +1167,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
struct trace_event_file *file,
char *field_str)
{
- struct ftrace_event_field *field = NULL;
struct hist_field *hist_field = NULL;
+
unsigned long flags = 0;
unsigned int key_size;
int ret = 0;
@@ -781,60 +1183,24 @@ static int create_key_field(struct hist_trigger_data *hist_data,
key_size = sizeof(unsigned long) * HIST_STACKTRACE_DEPTH;
hist_field = create_hist_field(hist_data, NULL, flags, NULL);
} else {
- char *field_name = strsep(&field_str, ".");
-
- if (field_str) {
- if (strcmp(field_str, "hex") == 0)
- flags |= HIST_FIELD_FL_HEX;
- else if (strcmp(field_str, "sym") == 0)
- flags |= HIST_FIELD_FL_SYM;
- else if (strcmp(field_str, "sym-offset") == 0)
- flags |= HIST_FIELD_FL_SYM_OFFSET;
- else if ((strcmp(field_str, "execname") == 0) &&
- (strcmp(field_name, "common_pid") == 0))
- flags |= HIST_FIELD_FL_EXECNAME;
- else if (strcmp(field_str, "syscall") == 0)
- flags |= HIST_FIELD_FL_SYSCALL;
- else if (strcmp(field_str, "log2") == 0)
- flags |= HIST_FIELD_FL_LOG2;
- else if (strcmp(field_str, "usecs") == 0)
- flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
- else {
- ret = -EINVAL;
- goto out;
- }
+ hist_field = parse_expr(hist_data, file, field_str, flags,
+ NULL, 0);
+ if (IS_ERR(hist_field)) {
+ ret = PTR_ERR(hist_field);
+ goto out;
}
- if (strcmp(field_name, "$common_timestamp") == 0) {
- flags |= HIST_FIELD_FL_TIMESTAMP;
- hist_data->enable_timestamps = true;
- if (flags & HIST_FIELD_FL_TIMESTAMP_USECS)
- hist_data->attrs->ts_in_usecs = true;
- key_size = sizeof(u64);
- } else {
- field = trace_find_event_field(file->event_call, field_name);
- if (!field || !field->size) {
- ret = -EINVAL;
- goto out;
- }
-
- if (is_string_field(field))
- key_size = MAX_FILTER_STR_VAL;
- else
- key_size = field->size;
- }
+ key_size = hist_field->size;
}
- hist_data->fields[key_idx] = create_hist_field(hist_data, field, flags, NULL);
- if (!hist_data->fields[key_idx]) {
- ret = -ENOMEM;
- goto out;
- }
+ hist_data->fields[key_idx] = hist_field;
key_size = ALIGN(key_size, sizeof(u64));
hist_data->fields[key_idx]->size = key_size;
hist_data->fields[key_idx]->offset = key_offset;
+
hist_data->key_size += key_size;
+
if (hist_data->key_size > HIST_KEY_SIZE_MAX) {
ret = -EINVAL;
goto out;
@@ -1419,7 +1785,8 @@ static void hist_trigger_stacktrace_print(struct seq_file *m,
for (i = 1; i < hist_data->n_vals; i++) {
field_name = hist_field_name(hist_data->fields[i], 0);
- if (hist_data->fields[i]->flags & HIST_FIELD_FL_VAR)
+ if (hist_data->fields[i]->flags & HIST_FIELD_FL_VAR ||
+ hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR)
continue;
if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) {
--
1.9.3
From 1586448913734228311@xxx Mon Dec 11 01:26:23 +0000 2017
X-GM-THRID: 1586264079254857056
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread