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

[Madadi Vineeth Reddy]

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