1. Patchew
  2. linux
  3. View series

[PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time

Yang Jihong posted 1 patch 1 year, 5 months ago 
tools/perf/builtin-sched.c | 5 ++++-
1 file changed, 4 insertions(+), 1 deletion(-)
[PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
Posted by Yang Jihong 1 year, 5 months ago 
If sched_in event for current task is not recorded, sched_in timestamp
will be set to end_time of time window interest, causing an error in
timestamp show. In this case, we choose to ignore this event.

Test scenario:
  perf[1229608] does not record the first sched_in event, run time and sch delay are both 0

  # perf sched timehist
  Samples of sched_switch event do not have callchains.
             time    cpu  task name                       wait time  sch delay   run time
                          [tid/pid]                          (msec)     (msec)     (msec)
  --------------- ------  ------------------------------  ---------  ---------  ---------
   2090450.763231 [0000]  perf[1229608]                       0.000      0.000      0.000
   2090450.763235 [0000]  migration/0[15]                     0.000      0.001      0.003
   2090450.763263 [0001]  perf[1229608]                       0.000      0.000      0.000
   2090450.763268 [0001]  migration/1[21]                     0.000      0.001      0.004
   2090450.763302 [0002]  perf[1229608]                       0.000      0.000      0.000
   2090450.763309 [0002]  migration/2[27]                     0.000      0.001      0.007
   2090450.763338 [0003]  perf[1229608]                       0.000      0.000      0.000
   2090450.763343 [0003]  migration/3[33]                     0.000      0.001      0.004

Before:
  arbitrarily specify a time window of interest, timestamp will be set to an incorrect value

  # perf sched timehist --time 100,200
  Samples of sched_switch event do not have callchains.
             time    cpu  task name                       wait time  sch delay   run time
                          [tid/pid]                          (msec)     (msec)     (msec)
  --------------- ------  ------------------------------  ---------  ---------  ---------
       200.000000 [0000]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0001]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0002]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0003]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0004]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0005]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0006]  perf[1229608]                       0.000      0.000      0.000
       200.000000 [0007]  perf[1229608]                       0.000      0.000      0.000

 After:

  # perf sched timehist --time 100,200
  Samples of sched_switch event do not have callchains.
             time    cpu  task name                       wait time  sch delay   run time
                          [tid/pid]                          (msec)     (msec)     (msec)
  --------------- ------  ------------------------------  ---------  ---------  ---------

Fixes: 853b74071110 ("perf sched timehist: Add option to specify time window of interest")
Signed-off-by: Yang Jihong <yangjihong@bytedance.com>
---

Changes since v1:
 - Simplify conditional judgment. (suggested-by Namhyung)

 tools/perf/builtin-sched.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 9c1276dc8ef6..1c386ebe4b98 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -2683,9 +2683,12 @@ static int timehist_sched_change_event(const struct perf_tool *tool,
 	 * - previous sched event is out of window - we are done
 	 * - sample time is beyond window user cares about - reset it
 	 *   to close out stats for time window interest
+	 * - If tprev is 0, that is, sched_in event for current task is
+	 *   not recorded, cannot determine whether sched_in event is
+	 *   within time window interest - ignore it
 	 */
 	if (ptime->end) {
-		if (tprev > ptime->end)
+		if (!tprev || tprev > ptime->end)
 			goto out;
 
 		if (t > ptime->end)
-- 
2.25.1
Re: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
Posted by Madadi Vineeth Reddy 1 year, 5 months ago 
Hi Yang Jihong,

On 19/08/24 08:17, Yang Jihong wrote:
> If sched_in event for current task is not recorded, sched_in timestamp
> will be set to end_time of time window interest, causing an error in
> timestamp show. In this case, we choose to ignore this event.
> 

Why sched-in is not happening for the perf task continuously

perf sched record -a sleep 5

perf sched script
            perf   19593 [000] 42668.450179: sched:sched_stat_runtime: comm=perf pid=19593 runtime=69449 [ns] vruntime=7303687 [ns]
            perf   19593 [000] 42668.450190: sched:sched_stat_runtime: comm=perf pid=19593 runtime=6039 [ns] vruntime=7309726 [ns]
            perf   19593 [000] 42668.450191:       sched:sched_waking: comm=migration/0 pid=19 prio=0 target_cpu=000
            perf   19593 [000] 42668.450192: sched:sched_stat_runtime: comm=perf pid=19593 runtime=2397 [ns] vruntime=7312123 [ns]
            perf   19593 [000] 42668.450193:       sched:sched_switch: perf:19593 [120] R ==> migration/0:19 [0]
     migration/0      19 [000] 42668.450195: sched:sched_migrate_task: comm=perf pid=19593 prio=120 orig_cpu=0 dest_cpu=1
     migration/0      19 [000] 42668.450200:       sched:sched_switch: migration/0:19 [0] S ==> swapper/0:0 [120]
            perf   19593 [001] 42668.450308: sched:sched_stat_runtime: comm=perf pid=19593 runtime=112515 [ns] vruntime=9972397 [ns]
            perf   19593 [001] 42668.450311:       sched:sched_waking: comm=migration/1 pid=24 prio=0 target_cpu=001
            perf   19593 [001] 42668.450313: sched:sched_stat_runtime: comm=perf pid=19593 runtime=4690 [ns] vruntime=9977087 [ns]
            perf   19593 [001] 42668.450314:       sched:sched_switch: perf:19593 [120] R ==> migration/1:24 [0]
     migration/1      24 [001] 42668.450316: sched:sched_migrate_task: comm=perf pid=19593 prio=120 orig_cpu=1 dest_cpu=2
     migration/1      24 [001] 42668.450322:       sched:sched_switch: migration/1:24 [0] S ==> swapper/1:0 [120]
            perf   19593 [002] 42668.450385: sched:sched_stat_runtime: comm=perf pid=19593 runtime=67379 [ns] vruntime=2885994 [ns]
            perf   19593 [002] 42668.450389:       sched:sched_waking: comm=migration/2 pid=30 prio=0 target_cpu=002
            perf   19593 [002] 42668.450391: sched:sched_stat_runtime: comm=perf pid=19593 runtime=5526 [ns] vruntime=2891520 [ns]
            perf   19593 [002] 42668.450392:       sched:sched_switch: perf:19593 [120] R ==> migration/2:30 [0]

The perf task (PID 19593) is being switched out without being switched in after CPU migration. The task migrates to a different CPU,
and then immediately switches out without a sched_in event in between.

Thanks and Regards
Madadi Vineeth Reddy

> Test scenario:
>   perf[1229608] does not record the first sched_in event, run time and sch delay are both 0
Re: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
Posted by Namhyung Kim 1 year, 5 months ago 
Hello,

On Sun, Aug 18, 2024 at 7:47 PM Yang Jihong <yangjihong@bytedance.com> wrote:
>
> If sched_in event for current task is not recorded, sched_in timestamp
> will be set to end_time of time window interest, causing an error in
> timestamp show. In this case, we choose to ignore this event.
>
> Test scenario:
>   perf[1229608] does not record the first sched_in event, run time and sch delay are both 0
>
>   # perf sched timehist
>   Samples of sched_switch event do not have callchains.
>              time    cpu  task name                       wait time  sch delay   run time
>                           [tid/pid]                          (msec)     (msec)     (msec)
>   --------------- ------  ------------------------------  ---------  ---------  ---------
>    2090450.763231 [0000]  perf[1229608]                       0.000      0.000      0.000
>    2090450.763235 [0000]  migration/0[15]                     0.000      0.001      0.003
>    2090450.763263 [0001]  perf[1229608]                       0.000      0.000      0.000
>    2090450.763268 [0001]  migration/1[21]                     0.000      0.001      0.004
>    2090450.763302 [0002]  perf[1229608]                       0.000      0.000      0.000
>    2090450.763309 [0002]  migration/2[27]                     0.000      0.001      0.007
>    2090450.763338 [0003]  perf[1229608]                       0.000      0.000      0.000
>    2090450.763343 [0003]  migration/3[33]                     0.000      0.001      0.004
>
> Before:
>   arbitrarily specify a time window of interest, timestamp will be set to an incorrect value
>
>   # perf sched timehist --time 100,200
>   Samples of sched_switch event do not have callchains.
>              time    cpu  task name                       wait time  sch delay   run time
>                           [tid/pid]                          (msec)     (msec)     (msec)
>   --------------- ------  ------------------------------  ---------  ---------  ---------
>        200.000000 [0000]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0001]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0002]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0003]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0004]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0005]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0006]  perf[1229608]                       0.000      0.000      0.000
>        200.000000 [0007]  perf[1229608]                       0.000      0.000      0.000
>
>  After:
>
>   # perf sched timehist --time 100,200
>   Samples of sched_switch event do not have callchains.
>              time    cpu  task name                       wait time  sch delay   run time
>                           [tid/pid]                          (msec)     (msec)     (msec)
>   --------------- ------  ------------------------------  ---------  ---------  ---------
>
> Fixes: 853b74071110 ("perf sched timehist: Add option to specify time window of interest")
> Signed-off-by: Yang Jihong <yangjihong@bytedance.com>

Acked-by: Namhyung Kim <namhyung@kernel.org>

Thanks,
Namhyung

> ---
>
> Changes since v1:
>  - Simplify conditional judgment. (suggested-by Namhyung)
>
>  tools/perf/builtin-sched.c | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
>
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 9c1276dc8ef6..1c386ebe4b98 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -2683,9 +2683,12 @@ static int timehist_sched_change_event(const struct perf_tool *tool,
>          * - previous sched event is out of window - we are done
>          * - sample time is beyond window user cares about - reset it
>          *   to close out stats for time window interest
> +        * - If tprev is 0, that is, sched_in event for current task is
> +        *   not recorded, cannot determine whether sched_in event is
> +        *   within time window interest - ignore it
>          */
>         if (ptime->end) {
> -               if (tprev > ptime->end)
> +               if (!tprev || tprev > ptime->end)
>                         goto out;
>
>                 if (t > ptime->end)
> --
> 2.25.1
>
Re: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
Posted by Arnaldo Carvalho de Melo 1 year, 5 months ago 
On Mon, Aug 19, 2024 at 01:08:57PM -0700, Namhyung Kim wrote:
> On Sun, Aug 18, 2024 at 7:47 PM Yang Jihong <yangjihong@bytedance.com> wrote:
> > Fixes: 853b74071110 ("perf sched timehist: Add option to specify time window of interest")
> > Signed-off-by: Yang Jihong <yangjihong@bytedance.com>
 
> Acked-by: Namhyung Kim <namhyung@kernel.org>

Thanks, applied to perf-tools-next,

- Arnaldo

Patchew 2.1-devel-b67e4c2

© 2016 - 2026 Red Hat, Inc.