Re: [PATCH v2 2/3] trace-cmd library: Add check before applying tsc2nsec offset

[Tzvetomir Stoyanov <tz.stoyanov@gmail.com>]

On Fri, Apr 16, 2021 at 11:12 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 16 Apr 2021 13:34:08 +0300
> "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>
> > When converting TSC timestamps to nanoseconds, an offset is used. That
> > offset is subtracted from each TSC timestamp, before the conversion.
> > However, if the timestamp is lower that the offset this causes an
> > overflow, as both timestamp and offset are unsigned long integers. A
> > check is added to verify the subtraction will not cause an overflow. In
> > case of an overflow, the timestamp is set to 0 and a warning message is
> > printed.
> >
> > Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> > ---
> >  lib/trace-cmd/trace-input.c | 10 ++++++++--
> >  1 file changed, 8 insertions(+), 2 deletions(-)
> >
> > diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> > index 974879e8..991abd5f 100644
> > --- a/lib/trace-cmd/trace-input.c
> > +++ b/lib/trace-cmd/trace-input.c
> > @@ -1230,8 +1230,14 @@ static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
> >               ts *= handle->ts2secs;
> >       } else if (handle->tsc_calc.mult) {
> >               /* auto calculated TSC clock frequency */
> > -             ts -= handle->tsc_calc.offset;
> > -             ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
> > +             if (ts > handle->tsc_calc.offset) {
> > +                     ts -= handle->tsc_calc.offset;
> > +                     ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
> > +             } else {
> > +                     tracecmd_warning("Timestamp $llu is before the initial offset %llu, set it to 0",
>
>    $llu  ??
>
> Are you testing these? The bad trace files that I supplied triggers this.
>
>
> > +                                      ts, handle->tsc_calc.offset);
> > +                     ts = 0;
>
> We should turn off the offset and not just zero out the timestamps,
> otherwise we just have useless data:
>
>   Timestamp $llu is before the initial offset 20094822433105, set it to 0
>   Timestamp $llu is before the initial offset 20094822433105, set it to 0
>   Timestamp $llu is before the initial offset 20094822460994, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094822961507, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094822967292, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094823302351, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094823306954, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094824963751, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094824965723, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094824972124, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094824972697, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094828868305, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094828871264, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094828881104, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094828882014, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094831874377, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094831876734, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094831881252, set it to 0
> [..]
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094832060068, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094835262757, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094835265223, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094835270122, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094835273058, set it to 0
> libtracecmd: File exists
>   Timestamp $llu is before the initial offset 20094835273614, set it to 0
> cpus=2
>        trace-cmd-3196  [000]     0.000000: sched_stat_runtime:   comm=trace-cmd pid=3196 runtime=85576 [ns] vruntime=12853032342 [ns]
>        trace-cmd-3196  [000]     0.000000: sched_switch:         trace-cmd:3196 [120] S ==> trace-cmd:3199 [120]
>        trace-cmd-3199  [000]     0.000000: sched_stat_runtime:   comm=trace-cmd pid=3199 runtime=156103 [ns] vruntime=12857102867 [ns]
>        trace-cmd-3199  [000]     0.000000: sched_switch:         trace-cmd:3199 [120] S ==> trace-cmd:3198 [120]
>        trace-cmd-3198  [000]     0.000000: sched_stat_runtime:   comm=trace-cmd pid=3198 runtime=100540 [ns] vruntime=12858890364 [ns]
>        trace-cmd-3198  [000]     0.000000: sched_switch:         trace-cmd:3198 [120] S ==> swapper/0:0 [120]
>           <idle>-0     [000]     0.000000: hrtimer_cancel:       hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]     0.000000: hrtimer_expire_entry: hrtimer=0xffff8cc5bd41f780 now=1444054745103 function=tick_sched_timer/0x0
>           <idle>-0     [000]     0.000000: hrtimer_expire_exit:  hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]     0.000000: hrtimer_start:        hrtimer=0xffff8cc5bd41f780 function=tick_sched_timer/0x0 expires=1444055726117 softexpires=1444055726117
>           <idle>-0     [000]     0.000000: hrtimer_cancel:       hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]     0.000000: hrtimer_expire_entry: hrtimer=0xffff8cc5bd41f780 now=1444055895819 function=tick_sched_timer/0x0
>           <idle>-0     [000]     0.000000: hrtimer_expire_exit:  hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]     0.000000: hrtimer_start:        hrtimer=0xffff8cc5bd41f780 function=tick_sched_timer/0x0 expires=1444056726117 softexpires=1444056726117
>           <idle>-0     [000]     0.000000: hrtimer_cancel:       hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]     0.000000: hrtimer_expire_entry: hrtimer=0xffff8cc5bd41f780 now=1444056782207 function=tick_sched_timer/0x0
>           <idle>-0     [000]     0.000000: softirq_raise:        vec=1 [action=TIMER]
>           <idle>-0     [000]     0.000000: hrtimer_expire_exit:  hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]     0.000000: hrtimer_start:        hrtimer=0xffff8cc5bd41f780 function=tick_sched_timer/0x0 expires=1444057726117 softexpires=1444057726117
>           <idle>-0     [000]     0.000000: softirq_entry:        vec=1 [action=TIMER]
>           <idle>-0     [000]     0.000000: timer_cancel:         timer=0xffffa61a0006be40
>           <idle>-0     [000]     0.000000: timer_expire_entry:   timer=0xffffa61a0006be40 function=process_timeout now=4296111312 baseclk=4296111312
>           <idle>-0     [000]     0.000000: sched_waking:         comm=rcu_sched pid=12 prio=120 target_cpu=000
>
> We don't want all timestamps zero. We want to disable the starting event.
>
> By having this instead:
>
>                 } else {
>                         tracecmd_warning("Timestamp %llu is before the initial offset %llu\n"
>                                          "\tSetting offset to 0",
>                                          ts, handle->tsc_calc.offset);
>                         handle->tsc_calc.offset = 0;
>                         ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
>                 }
>

This will set the guest offset to 0, will not change the offsets of
the other files. The result is that the files will not be displayed in
sync, because of these few broken events. As this is only a sanity
check, and should not happen if the patch "trace-cmd: Get the
timestamp of the first recorded event as TSC offset" is applied, I
would suggest to zero the broken timestamps and to advise the user to
use "--raw-ts" option instead:
 "Timestamp %llu is before the initial offset %llu, set it to 0.
Display the files with --raw-ts option to see the original
timestamps.\n"


> We get this as output:
>
>   Timestamp 20094822433105 is before the initial offset 20159736262966
>         Setting offset to 0
> cpus=2
>        trace-cmd-3196  [000]  5923.651995: sched_stat_runtime:   comm=trace-cmd pid=3196 runtime=85576 [ns] vruntime=12853032342 [ns]
>        trace-cmd-3196  [000]  5923.652004: sched_switch:         trace-cmd:3196 [120] S ==> trace-cmd:3199 [120]
>        trace-cmd-3199  [000]  5923.652151: sched_stat_runtime:   comm=trace-cmd pid=3199 runtime=156103 [ns] vruntime=12857102867 [ns]
>        trace-cmd-3199  [000]  5923.652153: sched_switch:         trace-cmd:3199 [120] S ==> trace-cmd:3198 [120]
>        trace-cmd-3198  [000]  5923.652252: sched_stat_runtime:   comm=trace-cmd pid=3198 runtime=100540 [ns] vruntime=12858890364 [ns]
>        trace-cmd-3198  [000]  5923.652253: sched_switch:         trace-cmd:3198 [120] S ==> swapper/0:0 [120]
>           <idle>-0     [000]  5923.652741: hrtimer_cancel:       hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]  5923.652742: hrtimer_expire_entry: hrtimer=0xffff8cc5bd41f780 now=1444054745103 function=tick_sched_timer/0x0
>           <idle>-0     [000]  5923.652744: hrtimer_expire_exit:  hrtimer=0xffff8cc5bd41f780
>           <idle>-0     [000]  5923.652744: hrtimer_start:        hrtimer=0xffff8cc5bd41f780 function=tick_sched_timer/0x0 expires=1444055726117 softexpires=1444055726117
>           <idle>-0     [000]  5923.653892: hrtimer_cancel:       hrtimer=0xffff8cc5bd41f780
>
> Much more usable.
>
> -- Steve
>
>
> > +             }
> >       }
> >
> >       /* User specified time offset with --ts-offset or --date options */
>


-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center