All of lore.kernel.org
 help / color / mirror / Atom feed
From: Steven Rostedt <rostedt@goodmis.org>
To: "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com>
Cc: linux-trace-devel@vger.kernel.org
Subject: Re: [PATCH v2 2/3] trace-cmd library: Add check before applying tsc2nsec offset
Date: Fri, 16 Apr 2021 16:12:21 -0400	[thread overview]
Message-ID: <20210416161221.031d1f5d@gandalf.local.home> (raw)
In-Reply-To: <20210416103409.24597-3-tz.stoyanov@gmail.com>

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);
		}

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 */


  reply	other threads:[~2021-04-16 20:12 UTC|newest]

Thread overview: 10+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2021-04-16 10:34 [PATCH v2 0/3] Fix overflow when applying tsc2nsec calculations Tzvetomir Stoyanov (VMware)
2021-04-16 10:34 ` [PATCH v2 1/3] trace-cmd library: Add new trace-cmd library APIs for guest ts corrections Tzvetomir Stoyanov (VMware)
2021-04-16 10:34 ` [PATCH v2 2/3] trace-cmd library: Add check before applying tsc2nsec offset Tzvetomir Stoyanov (VMware)
2021-04-16 20:12   ` Steven Rostedt [this message]
2021-04-19  8:08     ` Tzvetomir Stoyanov
2021-04-19 13:45       ` Steven Rostedt
2021-04-19 15:14         ` Steven Rostedt
2021-04-28 12:31           ` Tzvetomir Stoyanov
2021-04-16 10:34 ` [PATCH v2 3/3] trace-cmd: Get the timestamp of the first recorded event as TSC offset Tzvetomir Stoyanov (VMware)
2021-04-16 19:28   ` 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=20210416161221.031d1f5d@gandalf.local.home \
    --to=rostedt@goodmis.org \
    --cc=linux-trace-devel@vger.kernel.org \
    --cc=tz.stoyanov@gmail.com \
    /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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.