* [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
@ 2024-08-19 2:47 Yang Jihong
2024-08-19 20:08 ` Namhyung Kim
2024-08-20 18:00 ` Madadi Vineeth Reddy
0 siblings, 2 replies; 5+ messages in thread
From: Yang Jihong @ 2024-08-19 2:47 UTC (permalink / raw)
To: peterz, mingo, acme, namhyung, mark.rutland, alexander.shishkin,
jolsa, irogers, adrian.hunter, kan.liang, james.clark,
linux-perf-users, linux-kernel
Cc: yangjihong
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
2024-08-19 2:47 [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time Yang Jihong
@ 2024-08-19 20:08 ` Namhyung Kim
2024-08-30 13:32 ` Arnaldo Carvalho de Melo
2024-08-20 18:00 ` Madadi Vineeth Reddy
1 sibling, 1 reply; 5+ messages in thread
From: Namhyung Kim @ 2024-08-19 20:08 UTC (permalink / raw)
To: Yang Jihong
Cc: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
irogers, adrian.hunter, kan.liang, james.clark, linux-perf-users,
linux-kernel
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
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
2024-08-19 2:47 [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time Yang Jihong
2024-08-19 20:08 ` Namhyung Kim
@ 2024-08-20 18:00 ` Madadi Vineeth Reddy
[not found] ` <CAPePreJCahzH0LwfXN_X+UdxU54_UMRPZgDgGqt7+PC+ky997Q@mail.gmail.com>
1 sibling, 1 reply; 5+ messages in thread
From: Madadi Vineeth Reddy @ 2024-08-20 18:00 UTC (permalink / raw)
To: Yang Jihong
Cc: peterz, mingo, acme, namhyung, mark.rutland, alexander.shishkin,
jolsa, irogers, adrian.hunter, kan.liang, james.clark,
linux-perf-users, linux-kernel, 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
^ permalink raw reply [flat|nested] 5+ messages in thread
* RE: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
[not found] ` <CAPePreJCahzH0LwfXN_X+UdxU54_UMRPZgDgGqt7+PC+ky997Q@mail.gmail.com>
@ 2024-08-21 10:28 ` Madadi Vineeth Reddy
0 siblings, 0 replies; 5+ messages in thread
From: Madadi Vineeth Reddy @ 2024-08-21 10:28 UTC (permalink / raw)
To: yangjihong
Cc: peterz, mingo, acme, namhyung, mark.rutland, alexander.shishkin,
jolsa, irogers, adrian.hunter, kan.liang, james.clark,
linux-perf-users, linux-kernel, Madadi Vineeth Reddy
Hi Yang Jihong,
On 21/08/24 11:46, yangjihong wrote:
> Hello,
>
> On 2024/8/21 2:00, Madadi Vineeth Reddy wrote:
>> 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.
>>
> Because the perf tool sets CPU affinity first (which causes perf process
> to migrate to the target core) and then enables events, by the time
> starts recording, task is likely to have migrated to the target core and
> started running. In this case, the sched_in event is not recorded.
>
Got it. Thanks for the explanation!
Thanks and Regards
Madadi Vineeth Reddy
> Thanks,
> Yang
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time
2024-08-19 20:08 ` Namhyung Kim
@ 2024-08-30 13:32 ` Arnaldo Carvalho de Melo
0 siblings, 0 replies; 5+ messages in thread
From: Arnaldo Carvalho de Melo @ 2024-08-30 13:32 UTC (permalink / raw)
To: Namhyung Kim
Cc: Yang Jihong, peterz, mingo, mark.rutland, alexander.shishkin,
jolsa, irogers, adrian.hunter, kan.liang, james.clark,
linux-perf-users, linux-kernel
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
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2024-08-30 13:32 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-08-19 2:47 [PATCH v2] perf sched timehist: Fixed timestamp error when unable to confirm event sched_in time Yang Jihong
2024-08-19 20:08 ` Namhyung Kim
2024-08-30 13:32 ` Arnaldo Carvalho de Melo
2024-08-20 18:00 ` Madadi Vineeth Reddy
[not found] ` <CAPePreJCahzH0LwfXN_X+UdxU54_UMRPZgDgGqt7+PC+ky997Q@mail.gmail.com>
2024-08-21 10:28 ` Madadi Vineeth Reddy
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).