[PATCH] perf trace: Fix potential u64 underflow in duration calculation

[PATCH] perf trace: Fix potential u64 underflow in duration calculation

[Michael Petlan]

Although it happens very rarely, in case of out-of-order events (i.e.
due to CPU migration when a syscall is executed), the calculation of
event duration might underflow and thus a bogus value is printed:

    2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
    2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
    2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
    2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0

Check for possible underflow first and in case of a bogus value, do
not print it.

Signed-off-by: Michael Petlan <mpetlan@redhat.com>
---
 tools/perf/builtin-trace.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index f487fbaa0ad6..c9de6bb9b0ea 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -2956,7 +2956,7 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
 		++trace->stats.vfs_getname;
 	}
 
-	if (ttrace->entry_time) {
+	if (ttrace->entry_time && sample->time > ttrace->entry_time) {
 		duration = sample->time - ttrace->entry_time;
 		if (trace__filter_duration(trace, duration))
 			goto out;
-- 
2.47.3

Re: [PATCH] perf trace: Fix potential u64 underflow in duration calculation

[Ian Rogers]

On Tue, Mar 31, 2026 at 3:10 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> Although it happens very rarely, in case of out-of-order events (i.e.
> due to CPU migration when a syscall is executed), the calculation of
> event duration might underflow and thus a bogus value is printed:
>
>     2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
>     2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
>     2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
>     2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0
>
> Check for possible underflow first and in case of a bogus value, do
> not print it.
>
> Signed-off-by: Michael Petlan <mpetlan@redhat.com>

Reviewed-by: Ian Rogers <irogers@google.com>

Sashiko notes [1] that maybe this should be >= so that 0ns system
calls still have a duration. I'm not sure how sensible that is.

Thanks,
Ian

[1] https://sashiko.dev/#/patchset/20260331101020.1270363-1-mpetlan%40redhat.com


> ---
>  tools/perf/builtin-trace.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index f487fbaa0ad6..c9de6bb9b0ea 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -2956,7 +2956,7 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
>                 ++trace->stats.vfs_getname;
>         }
>
> -       if (ttrace->entry_time) {
> +       if (ttrace->entry_time && sample->time > ttrace->entry_time) {
>                 duration = sample->time - ttrace->entry_time;
>                 if (trace__filter_duration(trace, duration))
>                         goto out;
> --
> 2.47.3
>

Re: [PATCH] perf trace: Fix potential u64 underflow in duration calculation

[Michael Petlan]

[-- Attachment #1: Type: text/plain, Size: 2171 bytes --]

On Tue, 31 Mar 2026, Ian Rogers wrote:
> On Tue, Mar 31, 2026 at 3:10 AM Michael Petlan <mpetlan@redhat.com> wrote:
> >
> > Although it happens very rarely, in case of out-of-order events (i.e.
> > due to CPU migration when a syscall is executed), the calculation of
> > event duration might underflow and thus a bogus value is printed:
> >
> >     2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
> >     2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
> >     2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
> >     2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0
> >
> > Check for possible underflow first and in case of a bogus value, do
> > not print it.
> >
> > Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> 
> Reviewed-by: Ian Rogers <irogers@google.com>
> 
> Sashiko notes [1] that maybe this should be >= so that 0ns system
> calls still have a duration. I'm not sure how sensible that is.
>
OK, although there is nothing of zero duration, coarse clock resolution
is a reasonable case. Sending v2.
Thanks.
Michael

> Thanks,
> Ian
> 
> [1] https://sashiko.dev/#/patchset/20260331101020.1270363-1-mpetlan%40redhat.com
> 
> 
> > ---
> >  tools/perf/builtin-trace.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> > index f487fbaa0ad6..c9de6bb9b0ea 100644
> > --- a/tools/perf/builtin-trace.c
> > +++ b/tools/perf/builtin-trace.c
> > @@ -2956,7 +2956,7 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
> >                 ++trace->stats.vfs_getname;
> >         }
> >
> > -       if (ttrace->entry_time) {
> > +       if (ttrace->entry_time && sample->time > ttrace->entry_time) {
> >                 duration = sample->time - ttrace->entry_time;
> >                 if (trace__filter_duration(trace, duration))
> >                         goto out;
> > --
> > 2.47.3
> >
> 
> 

[PATCH v2] perf trace: Fix potential u64 underflow in duration calculation

[Michael Petlan]

Although it happens very rarely, in case of out-of-order events (i.e.
due to CPU migration when a syscall is executed), the calculation of
event duration might underflow and thus a bogus value is printed:

    2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
    2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
    2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
    2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0

Check for possible underflow first and in case of a bogus value, do
not print it.

v2: Use greater-or-equal to handle "zero" duration calls correctly.

Signed-off-by: Michael Petlan <mpetlan@redhat.com>
---
 tools/perf/builtin-trace.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index f487fbaa0ad6..9c59969de2af 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -2956,7 +2956,7 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
 		++trace->stats.vfs_getname;
 	}
 
-	if (ttrace->entry_time) {
+	if (ttrace->entry_time && sample->time >= ttrace->entry_time) {
 		duration = sample->time - ttrace->entry_time;
 		if (trace__filter_duration(trace, duration))
 			goto out;
-- 
2.47.3

Re: [PATCH v2] perf trace: Fix potential u64 underflow in duration calculation

[Ian Rogers]

On Thu, Apr 2, 2026 at 7:51 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> Although it happens very rarely, in case of out-of-order events (i.e.
> due to CPU migration when a syscall is executed), the calculation of
> event duration might underflow and thus a bogus value is printed:
>
>     2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
>     2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
>     2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
>     2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0
>
> Check for possible underflow first and in case of a bogus value, do
> not print it.
>
> v2: Use greater-or-equal to handle "zero" duration calls correctly.

Nit: This normally comes after the signed-off-by past a "---" to
indicate it should not be included in the commit log.

> Signed-off-by: Michael Petlan <mpetlan@redhat.com>

Reviewed-by: Ian Rogers <irogers@google.com>

Thanks,
Ian

> ---
>  tools/perf/builtin-trace.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index f487fbaa0ad6..9c59969de2af 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -2956,7 +2956,7 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
>                 ++trace->stats.vfs_getname;
>         }
>
> -       if (ttrace->entry_time) {
> +       if (ttrace->entry_time && sample->time >= ttrace->entry_time) {
>                 duration = sample->time - ttrace->entry_time;
>                 if (trace__filter_duration(trace, duration))
>                         goto out;
> --
> 2.47.3
>

Re: [PATCH v2] perf trace: Fix potential u64 underflow in duration calculation

[Namhyung Kim]

On Thu, Apr 02, 2026 at 08:09:12AM -0700, Ian Rogers wrote:
> On Thu, Apr 2, 2026 at 7:51 AM Michael Petlan <mpetlan@redhat.com> wrote:
> >
> > Although it happens very rarely, in case of out-of-order events (i.e.
> > due to CPU migration when a syscall is executed), the calculation of
> > event duration might underflow and thus a bogus value is printed:
> >
> >     2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
> >     2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
> >     2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
> >     2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0
> >
> > Check for possible underflow first and in case of a bogus value, do
> > not print it.

I guess this means to leave the duration empty and print the rest.  For
clear communication, I think it's better to put examples before and
after for user-visible changes.

> >
> > v2: Use greater-or-equal to handle "zero" duration calls correctly.
> 
> Nit: This normally comes after the signed-off-by past a "---" to
> indicate it should not be included in the commit log.

+1.  I can handle that this time but please do later.

> 
> > Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> 
> Reviewed-by: Ian Rogers <irogers@google.com>

Thanks,
Namhyung

> 
> > ---
> >  tools/perf/builtin-trace.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> > index f487fbaa0ad6..9c59969de2af 100644
> > --- a/tools/perf/builtin-trace.c
> > +++ b/tools/perf/builtin-trace.c
> > @@ -2956,7 +2956,7 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
> >                 ++trace->stats.vfs_getname;
> >         }
> >
> > -       if (ttrace->entry_time) {
> > +       if (ttrace->entry_time && sample->time >= ttrace->entry_time) {
> >                 duration = sample->time - ttrace->entry_time;
> >                 if (trace__filter_duration(trace, duration))
> >                         goto out;
> > --
> > 2.47.3
> >

Re: [PATCH v2] perf trace: Fix potential u64 underflow in duration calculation

[Namhyung Kim]

On Thu, 02 Apr 2026 16:51:18 +0200, Michael Petlan wrote:
> Although it happens very rarely, in case of out-of-order events (i.e.
> due to CPU migration when a syscall is executed), the calculation of
> event duration might underflow and thus a bogus value is printed:
> 
>     2.804 ( 0.001 ms): :49553/49553 rt_sigaction(sig: QUIT, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
>     2.807 ( 0.001 ms): :49553/49553 rt_sigaction(sig: CHLD, act: 0x7fff403ed6e0, oact: 0x7fff403ed780, sigsetsize: 8) = 0
>     2.815 (18446744073709.438 ms): :49553/49553 execve(filename: 0xbb173a30, argv: 0x55aabb171930, envp: 0x55aabb171120) = 0
>     2.815 ( 0.534 ms): pwd/49553  ... [continued]: execve())                                           = 0
> 
> [...]
Applied to perf-tools-next, thanks!

Best regards,
Namhyung