From: Steven Rostedt <rostedt@goodmis.org>
To: linux-kernel@vger.kernel.org
Cc: Ingo Molnar <mingo@kernel.org>,
Andrew Morton <akpm@linux-foundation.org>,
Linux Trace Devel <linux-trace-devel@vger.kernel.org>,
linux-rt-users <linux-rt-users@vger.kernel.org>,
stable@vger.kernel.org, Tom Zanussi <zanussi@kernel.org>
Subject: [for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx
Date: Thu, 19 Sep 2019 19:23:16 -0400 [thread overview]
Message-ID: <20190919232359.825502403@goodmis.org> (raw)
In-Reply-To: 20190919232313.198902049@goodmis.org
From: Tom Zanussi <zanussi@kernel.org>
Original changelog from Steve Rostedt (except last sentence which
explains the problem, and the Fixes: tag):
I performed a three way histogram with the following commands:
echo 'irq_lat u64 lat pid_t pid' > synthetic_events
echo 'wake_lat u64 lat u64 irqlat pid_t pid' >> synthetic_events
echo 'hist:keys=common_pid:irqts=common_timestamp.usecs if function == 0xffffffff81200580' > events/timer/hrtimer_start/trigger
echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$irqts:onmatch(timer.hrtimer_start).irq_lat($lat,pid) if common_flags & 1' > events/sched/sched_waking/trigger
echo 'hist:keys=pid:wakets=common_timestamp.usecs,irqlat=lat' > events/synthetic/irq_lat/trigger
echo 'hist:keys=next_pid:lat=common_timestamp.usecs-$wakets,irqlat=$irqlat:onmatch(synthetic.irq_lat).wake_lat($lat,$irqlat,next_pid)' > events/sched/sched_switch/trigger
echo 1 > events/synthetic/wake_lat/enable
Basically I wanted to see:
hrtimer_start (calling function tick_sched_timer)
Note:
# grep tick_sched_timer /proc/kallsyms
ffffffff81200580 t tick_sched_timer
And save the time of that, and then record sched_waking if it is called
in interrupt context and with the same pid as the hrtimer_start, it
will record the latency between that and the waking event.
I then look at when the task that is woken is scheduled in, and record
the latency between the wakeup and the task running.
At the end, the wake_lat synthetic event will show the wakeup to
scheduled latency, as well as the irq latency in from hritmer_start to
the wakeup. The problem is that I found this:
<idle>-0 [007] d... 190.485261: wake_lat: lat=27 irqlat=190485230 pid=698
<idle>-0 [005] d... 190.485283: wake_lat: lat=40 irqlat=190485239 pid=10
<idle>-0 [002] d... 190.488327: wake_lat: lat=56 irqlat=190488266 pid=335
<idle>-0 [005] d... 190.489330: wake_lat: lat=64 irqlat=190489262 pid=10
<idle>-0 [003] d... 190.490312: wake_lat: lat=43 irqlat=190490265 pid=77
<idle>-0 [005] d... 190.493322: wake_lat: lat=54 irqlat=190493262 pid=10
<idle>-0 [005] d... 190.497305: wake_lat: lat=35 irqlat=190497267 pid=10
<idle>-0 [005] d... 190.501319: wake_lat: lat=50 irqlat=190501264 pid=10
The irqlat seemed quite large! Investigating this further, if I had
enabled the irq_lat synthetic event, I noticed this:
<idle>-0 [002] d.s. 249.429308: irq_lat: lat=164968 pid=335
<idle>-0 [002] d... 249.429369: wake_lat: lat=55 irqlat=249429308 pid=335
Notice that the timestamp of the irq_lat "249.429308" is awfully
similar to the reported irqlat variable. In fact, all instances were
like this. It appeared that:
irqlat=$irqlat
Wasn't assigning the old $irqlat to the new irqlat variable, but
instead was assigning the $irqts to it.
The issue is that assigning the old $irqlat to the new irqlat variable
creates a variable reference alias, but the alias creation code
forgets to make sure the alias uses the same var_ref_idx to access the
reference.
Link: http://lkml.kernel.org/r/1567375321.5282.12.camel@kernel.org
Cc: Linux Trace Devel <linux-trace-devel@vger.kernel.org>
Cc: linux-rt-users <linux-rt-users@vger.kernel.org>
Cc: stable@vger.kernel.org
Fixes: 7e8b88a30b085 ("tracing: Add hist trigger support for variable reference aliases")
Reported-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
kernel/trace/trace_events_hist.c | 2 ++
1 file changed, 2 insertions(+)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 3a6e42aa08e6..9468bd8d44a2 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -2804,6 +2804,8 @@ static struct hist_field *create_alias(struct hist_trigger_data *hist_data,
return NULL;
}
+ alias->var_ref_idx = var_ref->var_ref_idx;
+
return alias;
}
--
2.20.1
next prev parent reply other threads:[~2019-09-19 23:24 UTC|newest]
Thread overview: 15+ messages / expand[flat|nested] mbox.gz Atom feed top
2019-09-19 23:23 [for-next][PATCH 0/8] tracing: Final updates before sending to Linus Steven Rostedt
2019-09-19 23:23 ` [for-next][PATCH 1/8] ftrace: Simplify ftrace hash lookup code in clear_func_from_hash() Steven Rostedt
2019-09-19 23:23 ` [for-next][PATCH 2/8] tracing: Be more clever when dumping hex in __print_hex() Steven Rostedt
2019-09-19 23:23 ` Steven Rostedt [this message]
[not found] ` <20190921120618.DF81120665@mail.kernel.org>
2019-09-21 12:20 ` [for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx Steven Rostedt
2019-09-21 19:21 ` Sasha Levin
2019-09-21 19:23 ` Steven Rostedt
2019-09-19 23:23 ` [for-next][PATCH 4/8] tracing/kprobe: Fix NULL pointer access in trace_porbe_unlink() Steven Rostedt
2019-09-19 23:23 ` [for-next][PATCH 5/8] selftests/ftrace: Select an existing function in kprobe_eventname test Steven Rostedt
2019-09-19 23:23 ` [for-next][PATCH 6/8] tracing/probe: Fix to allow user to enable events on unloaded modules Steven Rostedt
2019-09-19 23:23 ` [for-next][PATCH 7/8] tracing/probe: Reject exactly same probe event Steven Rostedt
2019-09-23 10:42 ` Srikar Dronamraju
2019-09-23 17:15 ` Masami Hiramatsu
2019-09-23 17:42 ` Srikar Dronamraju
2019-09-19 23:23 ` [for-next][PATCH 8/8] selftests/ftrace: Update kprobe event error testcase Steven Rostedt
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20190919232359.825502403@goodmis.org \
--to=rostedt@goodmis.org \
--cc=akpm@linux-foundation.org \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-rt-users@vger.kernel.org \
--cc=linux-trace-devel@vger.kernel.org \
--cc=mingo@kernel.org \
--cc=stable@vger.kernel.org \
--cc=zanussi@kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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).