* [PATCH 0/3] A few hist trigger fixes
@ 2019-04-18 15:18 Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 1/3] tracing: Prevent hist_field_var_ref() from accessing NULL tracing_map_elts Tom Zanussi
` (2 more replies)
0 siblings, 3 replies; 6+ messages in thread
From: Tom Zanussi @ 2019-04-18 15:18 UTC (permalink / raw)
To: rostedt; +Cc: vincent, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Hi Steve,
Here's a fix for a problem I found with the hist trigger snapshot
action related to the refactoring in the later versions of the
patchset ('[PATCH 3/3] tracing: Add a check_val() check before updating
cond_snapshot() track_val').
I also added v2 of 2 other patches that I previously submitted [1] but
realized hadn't gotten picked up. ('[PATCH v2 1/3] tracing: Prevent
hist_field_var_ref() from accessing NULL tracing_map_elts' and '[PATCH
v2 2/3] tracing: Check keys for variable references in expressions
too').
One of them I had to rebase ('[PATCH v2 2/3] tracing: Check keys for
variable references in expressions too') because of the error_log
changes since then, but the original ones still apply to versions
before that).
So in summary, all of these patches apply to current ftrace/core,
while only '[PATCH 3/3] tracing: Add a check_val() check before
updating cond_snapshot() track_val' and the previous 2 original
patches in [1] apply to mainline.
Thanks,
Tom
[1] https://lore.kernel.org/lkml/cover.1541687121.git.tom.zanussi@linux.intel.com/
The following changes since commit c8faaa4c594f55ddf903d61180029a3ea1da5286:
rcu: validate arguments for rcu tracepoints (2019-04-03 08:26:38 -0400)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/key-ref-fix-v2
Tom Zanussi (3):
tracing: Prevent hist_field_var_ref() from accessing NULL
tracing_map_elts
tracing: Check keys for variable references in expressions too
tracing: Add a check_val() check before updating cond_snapshot()
track_val
kernel/trace/trace_events_hist.c | 13 +++++++++++--
1 file changed, 11 insertions(+), 2 deletions(-)
--
2.14.1
^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v2 1/3] tracing: Prevent hist_field_var_ref() from accessing NULL tracing_map_elts
2019-04-18 15:18 [PATCH 0/3] A few hist trigger fixes Tom Zanussi
@ 2019-04-18 15:18 ` Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 2/3] tracing: Check keys for variable references in expressions too Tom Zanussi
2019-04-18 15:18 ` [PATCH 3/3] tracing: Add a check_val() check before updating cond_snapshot() track_val Tom Zanussi
2 siblings, 0 replies; 6+ messages in thread
From: Tom Zanussi @ 2019-04-18 15:18 UTC (permalink / raw)
To: rostedt; +Cc: vincent, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
hist_field_var_ref() is an implementation of hist_field_fn_t(), which
can be called with a null tracing_map_elt elt param when assembling a
key in event_hist_trigger().
In the case of hist_field_var_ref() this doesn't make sense, because a
variable can only be resolved by looking it up using an already
assembled key i.e. a variable can't be used to assemble a key since
the key is required in order to access the variable.
Upper layers should prevent the user from constructing a key using a
variable in the first place, but in case one slips through, it
shouldn't cause a NULL pointer dereference. Also if one does slip
through, we want to know about it, so emit a one-time warning in that
case.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Reported-by: Vincent Bernat <vincent@bernat.ch>
---
kernel/trace/trace_events_hist.c | 3 +++
1 file changed, 3 insertions(+)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index a1136e043f17..453f51ef83ca 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1854,6 +1854,9 @@ static u64 hist_field_var_ref(struct hist_field *hist_field,
struct hist_elt_data *elt_data;
u64 var_val = 0;
+ if (WARN_ON_ONCE(!elt))
+ return var_val;
+
elt_data = elt->private_data;
var_val = elt_data->var_ref_vals[hist_field->var_ref_idx];
--
2.14.1
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [PATCH v2 2/3] tracing: Check keys for variable references in expressions too
2019-04-18 15:18 [PATCH 0/3] A few hist trigger fixes Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 1/3] tracing: Prevent hist_field_var_ref() from accessing NULL tracing_map_elts Tom Zanussi
@ 2019-04-18 15:18 ` Tom Zanussi
2019-04-18 15:18 ` [PATCH 3/3] tracing: Add a check_val() check before updating cond_snapshot() track_val Tom Zanussi
2 siblings, 0 replies; 6+ messages in thread
From: Tom Zanussi @ 2019-04-18 15:18 UTC (permalink / raw)
To: rostedt; +Cc: vincent, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
There's an existing check for variable references in keys, but it
doesn't go far enough. It checks whether a key field is a variable
reference but doesn't check whether it's an expression containing
variable references, which can cause the same problems for callers.
Use the existing field_has_hist_vars() function rather than a direct
top-level flag check to catch all possible variable references.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Reported-by: Vincent Bernat <vincent@bernat.ch>
---
kernel/trace/trace_events_hist.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 453f51ef83ca..cb56c7c456fa 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -59,7 +59,7 @@
C(NO_CLOSING_PAREN, "No closing paren found"), \
C(SUBSYS_NOT_FOUND, "Missing subsystem"), \
C(INVALID_SUBSYS_EVENT, "Invalid subsystem or event name"), \
- C(INVALID_REF_KEY, "Using variable references as keys not supported"), \
+ C(INVALID_REF_KEY, "Using variable references in keys not supported"), \
C(VAR_NOT_FOUND, "Couldn't find variable"), \
C(FIELD_NOT_FOUND, "Couldn't find field"),
@@ -4506,7 +4506,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
goto out;
}
- if (hist_field->flags & HIST_FIELD_FL_VAR_REF) {
+ if (field_has_hist_vars(hist_field, 0)) {
hist_err(tr, HIST_ERR_INVALID_REF_KEY, errpos(field_str));
destroy_hist_field(hist_field, 0);
ret = -EINVAL;
--
2.14.1
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [PATCH 3/3] tracing: Add a check_val() check before updating cond_snapshot() track_val
2019-04-18 15:18 [PATCH 0/3] A few hist trigger fixes Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 1/3] tracing: Prevent hist_field_var_ref() from accessing NULL tracing_map_elts Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 2/3] tracing: Check keys for variable references in expressions too Tom Zanussi
@ 2019-04-18 15:18 ` Tom Zanussi
2 siblings, 0 replies; 6+ messages in thread
From: Tom Zanussi @ 2019-04-18 15:18 UTC (permalink / raw)
To: rostedt; +Cc: vincent, linux-kernel, linux-rt-users
From: Tom Zanussi <tom.zanussi@linux.intel.com>
Without this check a snapshot is taken whenever a bucket's max is hit,
rather than only when the global max is hit, as it should be.
Before:
In this example, we do a first run of the workload (cyclictest),
examine the output, note the max ('triggering value') (347), then do
a second run and note the max again.
In this case, the max in the second run (39) is below the max in the
first run, but since we haven't cleared the histogram, the first max
is still in the histogram and is higher than any other max, so it
should still be the max for the snapshot. It isn't however - the
value should still be 347 after the second run.
# 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_prio,next_comm,prev_pid,prev_prio,prev_comm):onmax($wakeup_lat).snapshot() if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# cyclictest -p 80 -n -s -t 2 -D 2
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
{ next_pid: 2143 } hitcount: 199
max: 44 next_prio: 120 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/4
{ next_pid: 2145 } hitcount: 1325
max: 38 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/2
{ next_pid: 2144 } hitcount: 1982
max: 347 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
Snapshot taken (see tracing/snapshot). Details:
triggering value { onmax($wakeup_lat) }: 347
triggered by event with key: { next_pid: 2144 }
# cyclictest -p 80 -n -s -t 2 -D 2
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
{ next_pid: 2143 } hitcount: 199
max: 44 next_prio: 120 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/4
{ next_pid: 2148 } hitcount: 199
max: 16 next_prio: 120 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
{ next_pid: 2145 } hitcount: 1325
max: 38 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/2
{ next_pid: 2150 } hitcount: 1326
max: 39 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/4
{ next_pid: 2144 } hitcount: 1982
max: 347 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
{ next_pid: 2149 } hitcount: 1983
max: 130 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/0
Snapshot taken (see tracing/snapshot). Details:
triggering value { onmax($wakeup_lat) }: 39
triggered by event with key: { next_pid: 2150 }
After:
In this example, we do a first run of the workload (cyclictest),
examine the output, note the max ('triggering value') (375), then do
a second run and note the max again.
In this case, the max in the second run is still 375, the highest in
any bucket, as it should be.
# cyclictest -p 80 -n -s -t 2 -D 2
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
{ next_pid: 2072 } hitcount: 200
max: 28 next_prio: 120 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/5
{ next_pid: 2074 } hitcount: 1323
max: 375 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/2
{ next_pid: 2073 } hitcount: 1980
max: 153 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
Snapshot taken (see tracing/snapshot). Details:
triggering value { onmax($wakeup_lat) }: 375
triggered by event with key: { next_pid: 2074 }
# cyclictest -p 80 -n -s -t 2 -D 2
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
{ next_pid: 2101 } hitcount: 199
max: 49 next_prio: 120 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
{ next_pid: 2072 } hitcount: 200
max: 28 next_prio: 120 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/5
{ next_pid: 2074 } hitcount: 1323
max: 375 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/2
{ next_pid: 2103 } hitcount: 1325
max: 74 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/4
{ next_pid: 2073 } hitcount: 1980
max: 153 next_prio: 19 next_comm: cyclictest
prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
{ next_pid: 2102 } hitcount: 1981
max: 84 next_prio: 19 next_comm: cyclictest
prev_pid: 12 prev_prio: 120 prev_comm: kworker/0:1
Snapshot taken (see tracing/snapshot). Details:
triggering value { onmax($wakeup_lat) }: 375
triggered by event with key: { next_pid: 2074 }
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace_events_hist.c | 6 ++++++
1 file changed, 6 insertions(+)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index cb56c7c456fa..61b58c906489 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -3585,14 +3585,20 @@ static bool cond_snapshot_update(struct trace_array *tr, void *cond_data)
struct track_data *track_data = tr->cond_snapshot->cond_data;
struct hist_elt_data *elt_data, *track_elt_data;
struct snapshot_context *context = cond_data;
+ struct action_data *action;
u64 track_val;
if (!track_data)
return false;
+ action = track_data->action_data;
+
track_val = get_track_val(track_data->hist_data, context->elt,
track_data->action_data);
+ if (!action->track_data.check_val(track_data->track_val, track_val))
+ return false;
+
track_data->track_val = track_val;
memcpy(track_data->key, context->key, track_data->key_len);
--
2.14.1
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH 0/3] A few hist trigger fixes
2018-04-27 1:04 [PATCH 0/3] A few hist trigger fixes Tom Zanussi
@ 2018-04-27 1:40 ` Steven Rostedt
0 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2018-04-27 1:40 UTC (permalink / raw)
To: Tom Zanussi
Cc: tglx, mhiramat, namhyung, vedang.patel, bigeasy, joel.opensrc,
joelaf, mathieu.desnoyers, baohong.liu, rajvi.jingar, julia,
fengguang.wu, linux-kernel, linux-rt-users
On Thu, 26 Apr 2018 20:04:46 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> Hi Steve,
>
> Here are a few patches that fix some problems found when testing the
> hist trigger inter-event (e.g. latency) support patches.
>
> The first fixes a problem I noticed when printing flags.
>
> The remaining two add some hist_err() calls for fields, the first
> reported by Masami, the second something I noticed when fixing the
> first.
>
They look good and I queued them up.
Thanks!
-- Steve
^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH 0/3] A few hist trigger fixes
@ 2018-04-27 1:04 Tom Zanussi
2018-04-27 1:40 ` Steven Rostedt
0 siblings, 1 reply; 6+ messages in thread
From: Tom Zanussi @ 2018-04-27 1:04 UTC (permalink / raw)
To: rostedt
Cc: tglx, mhiramat, namhyung, vedang.patel, bigeasy, joel.opensrc,
joelaf, mathieu.desnoyers, baohong.liu, rajvi.jingar, julia,
fengguang.wu, linux-kernel, linux-rt-users, Tom Zanussi
Hi Steve,
Here are a few patches that fix some problems found when testing the
hist trigger inter-event (e.g. latency) support patches.
The first fixes a problem I noticed when printing flags.
The remaining two add some hist_err() calls for fields, the first
reported by Masami, the second something I noticed when fixing the
first.
Thanks,
Tom
The following changes since commit 0566e40ce7c493d39006cdd7edf17bfdc52eb2ac:
tracing: initcall: Ordered comparison of function pointers (2018-04-26 15:02:46 -0400)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/hist-fixes-1
Tom Zanussi (3):
tracing: Restore proper field flag printing when displaying triggers
tracing: Add field parsing hist error for hist triggers
tracing: Add field modifier parsing hist error for hist triggers
kernel/trace/trace_events_hist.c | 12 ++++++++++++
1 file changed, 12 insertions(+)
--
1.9.3
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2019-04-18 15:19 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-04-18 15:18 [PATCH 0/3] A few hist trigger fixes Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 1/3] tracing: Prevent hist_field_var_ref() from accessing NULL tracing_map_elts Tom Zanussi
2019-04-18 15:18 ` [PATCH v2 2/3] tracing: Check keys for variable references in expressions too Tom Zanussi
2019-04-18 15:18 ` [PATCH 3/3] tracing: Add a check_val() check before updating cond_snapshot() track_val Tom Zanussi
-- strict thread matches above, loose matches on Subject: below --
2018-04-27 1:04 [PATCH 0/3] A few hist trigger fixes Tom Zanussi
2018-04-27 1:40 ` Steven Rostedt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).