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

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

On Mon, Apr 19, 2021 at 6:14 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 19 Apr 2021 09:45:43 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
>
> > That is:
> >
> >       max = 0;
> >       for each stream:
> >               ret = read first event, compared to offset
> >               if (!ret) {
> >                       /* ret will be how much off by offset */
> >                       if (ret > max)
> >                               max = ret;
> >               }
> >       if (max) {
> >               for each stream:
> >                       Update offset by subtracting max
> >       }
> >
> > Look at each stream, and have some callback give you how much ahead the
> > first event is from its given offset. Take the biggest value from reading
> > all the streams, then tell all the streams to subtract its offset by that
> > max value. The end result is that all streams now start at a positive value.
>
> From our call, here's the pseudo code that I was talking about:
>
> > diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> > index b17b36e0..f03dadd3 100644
> > --- a/lib/trace-cmd/trace-input.c
> > +++ b/lib/trace-cmd/trace-input.c
> > @@ -1302,7 +1302,7 @@ static unsigned long long timestamp_host_sync(unsigned long long ts, int cpu,
> >                                        &tsync->ts_samples[mid+1]);
> >  }
> >
> > -static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
> > +static unsigned long long pre_timestamp_calc(unsigned long long ts, int cpu,
> >                                        struct tracecmd_input *handle)
>
> I pulled out the timestamp_calc into a helper function.
>
> >  {
> >       /* do not modify raw timestamps */
> > @@ -1318,17 +1318,44 @@ 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;
>
> And removed the calc offset.
>
> >               ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
> >       }
> >
> >       /* User specified time offset with --ts-offset or --date options */
> > -     if (handle->ts_offset)
> > -             ts += handle->ts_offset;
> > +     ts += handle->ts_offset;
>
> As we mentioned (and this can be a separate patch), the if statement is
> useless.
>
> >
> >       return ts;
> >  }
> >
> > +static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
> > +                                      struct tracecmd_input *handle)
> > +{
> > +     static int once;
> > +
> > +     ts = pre_timestamp_calc(ts, cpu, handle);
> > +     if (!once && ts > handle->start_ts_offset) {
> > +             once++;
> > +             tracecmd_warning();
> > +     }
> > +     ts -= handle->start_ts_offset;
>
> After looking at this more, I think we should just have the ts_offset and
> start_ts_offset be the same. And remove the ts += handle->ts_offset, from
> the pre_timestamp_calc() above, and have this check test just ts_offset.
>
> So now the timestamp_calc() will get the timestamp and then apply the
> ts_offset separately (and warn if the offset is greater than the ts).
>
> > +}
> > +
> > +
> > +
> > +long long tracecmd_cpu_first_ts_offset(struct tracecmd_input *handle, int cpu)
> > +}
> > +     struct tep_record rec;
> > +
> > +     rec = first_event(handle, cpu);
> > +     return pre_timestamp_calc(rec->ts, cpu, handle) - handle->ts_offset;
> > +}
>
> Add an API that shows the difference between the first stream event
> timestamp against the user supplied (or file supplied) ts_offset.
>
>
> > +
> > +int tracecmd_modify_ts_offset(struct tracecmd_input *handle, long long offset)
> > +{
> > +     handle->ts_offset += offset;
> > +}
>
> Allow the user to tweak that offset. As we already have:
>
> tracecmd_set_ts_offset(handle, offset) to set ts_offset, if the user found
> that the offset was before, it could tweak it.
>
> > +
> > +
> >  /*
> >   * Page is mapped, now read in the page header info.
> >   */
> >
>
>
> That is, in the options, we would need to have the calc offset from the
> file (doing the sync), do:
>
>         handle->ts_offset -= start_offset.
>
> Or something like that. I'll let you look at this code and see what you
> come up with, and we can discuss this further.
>
> -- Steve

On Thu, Apr 22, 2021 at 11:25 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 16 Apr 2021 10:01:18 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
> > On Fri, 16 Apr 2021 09:59:08 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > >
> > > As for pr_stat(), I think we should rename it to tep_info() and tep_vinfo()
> > > that acts just like tep_warning(), except it is for informational output
> > > (stdout instead of stderr). This is similar to what the kernel has.
> > >
> > > Since tep_vwarning() takes a name, so can tep_vinfo(), and I was thinking
> > > that we should expose this string to the application.
> > >
> >
> > Oh, and we could add a tep_critical() and tep_vcritical() which means that
> > the error is something really bad happened, (like failed to allocate).
>
> Any thoughts on this?

These changes are superseded by "RFC [PATCH 0/5] tsc2nsec fixes",
where some of these suggestions are implemented.
https://lore.kernel.org/linux-trace-devel/20210428122839.805296-1-tz.stoyanov@gmail.com/




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