[for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx

[for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx

[Steven Rostedt]

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

Re: [for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx

[Steven Rostedt]

On Sat, 21 Sep 2019 12:06:18 +0000
Sasha Levin <sashal@kernel.org> wrote:

> Hi,
> 
> [This is an automated email]
> 
> This commit has been processed because it contains a "Fixes:" tag,
> fixing commit: .
> 
> The bot has tested the following trees: v5.2.16, v4.19.74, v4.14.145, v4.9.193, v4.4.193.


The fixes tag is 7e8b88a30b085 which was added to mainline in 4.17.
According to this email, it applies fine to 5.2 and 4.19, but fails on
4.14 and earlier. As the commit was added in 4.17 that makes perfect
sense. Can you update your scripts to test when the fixes commit was
added, and not send spam about it not applying to stable trees where
it's not applicable.

On a git repo containing only Linus's tree, I have:

$ git describe --contains 7e8b88a30b085
v4.17-rc1~28^2~43

Which shows me when it was applied.

Thanks!

-- Steve



> 
> v5.2.16: Build OK!
> v4.19.74: Build OK!
> v4.14.145: Failed to apply! Possible dependencies:
>     00b4145298ae ("ring-buffer: Add interface for setting absolute time stamps")
>     067fe038e70f ("tracing: Add variable reference handling to hist triggers")
>     0d7a8325bf33 ("tracing: Clean up hist_field_flags enum")
>     100719dcef44 ("tracing: Add simple expression support to hist triggers")
>     30350d65ac56 ("tracing: Add variable support to hist triggers")
>     442c94846190 ("tracing: Add Documentation for log2 modifier")
>     5819eaddf35b ("tracing: Reimplement log2")
>     7e8b88a30b08 ("tracing: Add hist trigger support for variable reference aliases")
>     85013256cf01 ("tracing: Add hist_field_name() accessor")
>     860f9f6b02e9 ("tracing: Add usecs modifier for hist trigger timestamps")
>     8b7622bf94a4 ("tracing: Add cpu field for hist triggers")
>     ad42febe51ae ("tracing: Add hist trigger timestamp support")
>     b559d003a226 ("tracing: Add hist_data member to hist_field")
>     b8df4a3634e0 ("tracing: Move hist trigger Documentation to histogram.txt")
> 
> v4.9.193: Failed to apply! Possible dependencies:
>     00b4145298ae ("ring-buffer: Add interface for setting absolute time stamps")
>     067fe038e70f ("tracing: Add variable reference handling to hist triggers")
>     0d7a8325bf33 ("tracing: Clean up hist_field_flags enum")
>     100719dcef44 ("tracing: Add simple expression support to hist triggers")
>     30350d65ac56 ("tracing: Add variable support to hist triggers")
>     442c94846190 ("tracing: Add Documentation for log2 modifier")
>     5819eaddf35b ("tracing: Reimplement log2")
>     7e8b88a30b08 ("tracing: Add hist trigger support for variable reference aliases")
>     85013256cf01 ("tracing: Add hist_field_name() accessor")
>     860f9f6b02e9 ("tracing: Add usecs modifier for hist trigger timestamps")
>     8b7622bf94a4 ("tracing: Add cpu field for hist triggers")
>     ad42febe51ae ("tracing: Add hist trigger timestamp support")
>     b559d003a226 ("tracing: Add hist_data member to hist_field")
>     b8df4a3634e0 ("tracing: Move hist trigger Documentation to histogram.txt")
> 
> v4.4.193: Failed to apply! Possible dependencies:
>     08d43a5fa063 ("tracing: Add lock-free tracing_map")
>     0c4a6b4666e8 ("tracing: Add hist trigger 'hex' modifier for displaying numeric fields")
>     0fc3813ce103 ("tracing: Add 'hist' trigger Documentation")
>     52a7f16dedff ("tracing: Add support for multiple hist triggers per event")
>     5463bfda327b ("tracing: Add support for named hist triggers")
>     76a3b0c8ac34 ("tracing: Add hist trigger support for compound keys")
>     7e8b88a30b08 ("tracing: Add hist trigger support for variable reference aliases")
>     7ef224d1d0e3 ("tracing: Add 'hist' event trigger command")
>     83e99914c9e2 ("tracing: Add hist trigger support for pausing and continuing a trace")
>     8b7622bf94a4 ("tracing: Add cpu field for hist triggers")
>     b8df4a3634e0 ("tracing: Move hist trigger Documentation to histogram.txt")
>     c6afad49d127 ("tracing: Add hist trigger 'sym' and 'sym-offset' modifiers")
>     e62347d24534 ("tracing: Add hist trigger support for user-defined sorting ('sort=' param)")
>     f2606835d70d ("tracing: Add hist trigger support for multiple values ('vals=' param)")
> 
> 
> NOTE: The patch will not be queued to stable trees until it is upstream.
> 
> How should we proceed with this patch?
> 
> --
> Thanks,
> Sasha

Re: [for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx

[Sasha Levin]

On Sat, Sep 21, 2019 at 08:20:35AM -0400, Steven Rostedt wrote:
>On Sat, 21 Sep 2019 12:06:18 +0000
>Sasha Levin <sashal@kernel.org> wrote:
>
>> Hi,
>>
>> [This is an automated email]
>>
>> This commit has been processed because it contains a "Fixes:" tag,
>> fixing commit: .
>>
>> The bot has tested the following trees: v5.2.16, v4.19.74, v4.14.145, v4.9.193, v4.4.193.
>
>
>The fixes tag is 7e8b88a30b085 which was added to mainline in 4.17.
>According to this email, it applies fine to 5.2 and 4.19, but fails on
>4.14 and earlier. As the commit was added in 4.17 that makes perfect
>sense. Can you update your scripts to test when the fixes commit was
>added, and not send spam about it not applying to stable trees where
>it's not applicable.

The script already does that. What happened here is that it got confused
with your previous "Fixes:" statement in the commit message and went
haywire.

I thought that something like this shouldn't happen because I grep for
"^fixes:", but looks like something is broken. I'll go fix that...


--
Thanks,
Sasha

Re: [for-next][PATCH 3/8] tracing: Make sure variable reference alias has correct var_ref_idx

[Steven Rostedt]

On September 21, 2019 3:21:08 PM EDT, Sasha Levin <sashal@kernel.org> wrote:
>On Sat, Sep 21, 2019 at 08:20:35AM -0400, Steven Rostedt wrote:
>>On Sat, 21 Sep 2019 12:06:18 +0000
>>Sasha Levin <sashal@kernel.org> wrote:
>>
>>> Hi,
>>>
>>> [This is an automated email]
>>>
>>> This commit has been processed because it contains a "Fixes:" tag,
>>> fixing commit: .
>>>
>>> The bot has tested the following trees: v5.2.16, v4.19.74,
>v4.14.145, v4.9.193, v4.4.193.
>>
>>
>>The fixes tag is 7e8b88a30b085 which was added to mainline in 4.17.
>>According to this email, it applies fine to 5.2 and 4.19, but fails on
>>4.14 and earlier. As the commit was added in 4.17 that makes perfect
>>sense. Can you update your scripts to test when the fixes commit was
>>added, and not send spam about it not applying to stable trees where
>>it's not applicable.
>
>The script already does that. What happened here is that it got
>confused
>with your previous "Fixes:" statement in the commit message and went
>haywire.
>
>I thought that something like this shouldn't happen because I grep for
>"^fixes:", but looks like something is broken. I'll go fix that...


Thanks!

-- Steve

-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity and top posting.