Re: [PATCH v6 8/9] trace-cmd: Implemented new option in trace.dat file: TRACECMD_OPTION_TIME_SHIFT

[Slavomir Kaslev <kaslevs@vmware.com>]

On Fri, Mar 15, 2019 at 10:38 AM Tzvetomir Stoyanov
<tstoyanov@vmware.com> wrote:
>
> The TRACECMD_OPTION_TIME_SHIFT is used when synchronizing trace time stamps between
> two trace.dat files. It contains multiple long long (time, offset) pairs, describing
> time stamps _offset_, measured in the given local _time_. The content of the option
> buffer is:
>  first 4 bytes - integer, count of timestamp offsets
>  long long array of size _count_, local time in which the offset is measured
>  long long array of size _count_, offset of the time stamps
>
> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> ---
>  include/trace-cmd/trace-cmd.h |   1 +
>  lib/trace-cmd/trace-input.c   | 119 +++++++++++++++++++++++++++++++++-
>  2 files changed, 118 insertions(+), 2 deletions(-)
>
> diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
> index f7c043a..5552396 100644
> --- a/include/trace-cmd/trace-cmd.h
> +++ b/include/trace-cmd/trace-cmd.h
> @@ -82,6 +82,7 @@ enum {
>         TRACECMD_OPTION_HOOK,
>         TRACECMD_OPTION_OFFSET,
>         TRACECMD_OPTION_CPUCOUNT,
> +       TRACECMD_OPTION_TIME_SHIFT,
>  };
>
>  enum {
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index 0a6e820..714f01c 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -75,6 +75,11 @@ struct input_buffer_instance {
>         size_t                  offset;
>  };
>
> +struct ts_offset_corr {
> +       long long       time;
> +       long long       offset;
> +};
> +
>  struct tracecmd_input {
>         struct tep_handle       *pevent;
>         struct tep_plugin_list  *plugin_list;
> @@ -92,6 +97,8 @@ struct tracecmd_input {
>         bool                    use_pipe;
>         struct cpu_data         *cpu_data;
>         long long               ts_offset;
> +       int                     ts_corr_count;
> +       struct ts_offset_corr   *ts_corr;
>         double                  ts2secs;
>         char *                  cpustats;
>         char *                  uname;
> @@ -1028,6 +1035,68 @@ static void free_next(struct tracecmd_input *handle, int cpu)
>         free_record(record);
>  }
>
> +static inline unsigned long long
> +timestamp_correction_calc(unsigned long long ts, struct ts_offset_corr *min,
> +                         struct ts_offset_corr *max)
> +{
> +       long long tscor = min->offset +
> +                       (((((long long)ts) - min->time)*
> +                       (max->offset-min->offset))/(max->time-min->time));
> +
> +       if (tscor < 0)
> +               return ts - llabs(tscor);
> +
> +       return ts + tscor;
> +
> +}
> +
> +static unsigned long long timestamp_correct(unsigned long long ts,
> +                                           struct tracecmd_input *handle)
> +{
> +       static int min = -1;
> +       static int max = -1;
> +       int i;
> +
> +       if (handle->ts_offset)
> +               return ts + handle->ts_offset;
> +       if (!handle->ts_corr_count || !handle->ts_corr)
> +               return ts;
> +
> +       /* We have only one offset, nothing to calc here */
> +       if (handle->ts_corr_count == 1)
> +               return ts + handle->ts_corr[0].offset;
> +
> +       /* We have two offsets, nothing to search here */
> +       if (handle->ts_corr_count == 2)
> +               return timestamp_correction_calc(ts, &handle->ts_corr[0],
> +                                                &handle->ts_corr[1]);
> +
> +       /* We have more than two offsets */
> +       /* check if current ts fits in the last found time frame */
> +       if (min >= 0 && max >= 0 &&
> +           ts >= handle->ts_corr[min].time &&
> +           ts <= handle->ts_corr[max].time) {
> +               return timestamp_correction_calc(ts, &handle->ts_corr[min],
> +                                                &handle->ts_corr[max]);
> +       }
> +       min = -1;
> +       max = -1;
> +       for (i = 0; i < handle->ts_corr_count; i++) {
> +               if (ts > handle->ts_corr[i].time)
> +                       min = i;
> +               else if (ts <= handle->ts_corr[i].time) {
> +                       max = i;
> +                       break;
> +               }
> +       }
> +       if (min >= 0 && max >= 0 && min != max &&
> +           min < handle->ts_corr_count && max < handle->ts_corr_count)
> +               return timestamp_correction_calc(ts, &handle->ts_corr[min],
> +                                                &handle->ts_corr[max]);
> +
> +       return ts;
> +}
> +
>  /*
>   * Page is mapped, now read in the page header info.
>   */
> @@ -1049,7 +1118,7 @@ static int update_page_info(struct tracecmd_input *handle, int cpu)
>                     kbuffer_subbuffer_size(kbuf));
>                 return -1;
>         }
> -       handle->cpu_data[cpu].timestamp = kbuffer_timestamp(kbuf) + handle->ts_offset;
> +       handle->cpu_data[cpu].timestamp = timestamp_correct(kbuffer_timestamp(kbuf), handle);
>
>         if (handle->ts2secs)
>                 handle->cpu_data[cpu].timestamp *= handle->ts2secs;
> @@ -1776,7 +1845,7 @@ read_again:
>                 goto read_again;
>         }
>
> -       handle->cpu_data[cpu].timestamp = ts + handle->ts_offset;
> +       handle->cpu_data[cpu].timestamp = timestamp_correct(ts, handle);
>
>         if (handle->ts2secs) {
>                 handle->cpu_data[cpu].timestamp *= handle->ts2secs;
> @@ -2101,6 +2170,34 @@ void tracecmd_set_ts2secs(struct tracecmd_input *handle,
>         handle->use_trace_clock = false;
>  }
>
> +static int tsync_offset_cmp(const void *a, const void *b)
> +{
> +       struct ts_offset_corr *ts_a = (struct ts_offset_corr *)a;
> +       struct ts_offset_corr *ts_b = (struct ts_offset_corr *)b;
> +
> +       if (ts_a->time > ts_b->time)
> +               return 1;
> +       if (ts_a->time < ts_b->time)
> +               return -1;
> +       return 0;
> +}
> +
> +static void tsync_offset_load(struct tracecmd_input *handle, char *buf)
> +{
> +       int i;
> +       long long *buf8 = (long long *)buf;
> +
> +       for (i = 0; i < handle->ts_corr_count; i++) {
> +               handle->ts_corr[i].time = tep_read_number(handle->pevent,
> +                                                         buf8+i, 8);
> +               handle->ts_corr[i].offset = tep_read_number(handle->pevent,
> +                                               buf8+handle->ts_corr_count+i, 8);
> +       }
> +       qsort(handle->ts_corr,
> +             handle->ts_corr_count, sizeof(struct ts_offset_corr),
> +             tsync_offset_cmp);
> +}
> +
>  static int handle_options(struct tracecmd_input *handle)
>  {
>         long long offset;
> @@ -2111,6 +2208,7 @@ static int handle_options(struct tracecmd_input *handle)
>         struct input_buffer_instance *buffer;
>         struct hook_list *hook;
>         char *buf;
> +       int tsync;
>         int cpus;
>
>         for (;;) {
> @@ -2155,6 +2253,23 @@ static int handle_options(struct tracecmd_input *handle)
>                         offset = strtoll(buf, NULL, 0);
>                         handle->ts_offset += offset;
>                         break;
> +               case TRACECMD_OPTION_TIME_SHIFT:

We have to also check `handle->flags & TRACECMD_FL_IGNORE_DATE` and
skip loading offset samples and correcting as in the two cases above.

> +                       /*
> +                        * int (4 bytes) count of timestamp offsets.
> +                        * long long array of size [count] of times,
> +                        *      when the offsets were calculated.
> +                        * long long array of size [count] of timestamp offsets.
> +                        */
> +                       handle->ts_corr_count = tep_read_number(handle->pevent,
> +                                                               buf, 4);
> +                       tsync = (sizeof(long long)*handle->ts_corr_count);
> +                       if (size != (4+(2*tsync)))
> +                               break;
> +                       handle->ts_corr = malloc(2*tsync);
> +                       if (!handle->ts_corr)
> +                               return -ENOMEM;
> +                       tsync_offset_load(handle, buf+4);
> +                       break;
>                 case TRACECMD_OPTION_CPUSTAT:
>                         buf[size-1] = '\n';
>                         cpustats = realloc(cpustats, cpustats_size + size + 1);
> --
> 2.20.1
>