2018-02-06 14:01:31

by Du, Changbin

Subject: A problem about 'perf sched latency'

Hello all,
I am using perf sched tool to analyzer sched data on my machine. But it seems that
'perf sched latency' report incorrect 'Switches'. What I did is as below.

First, record...
$ sudo perf sched record time pi 2000000 > /dev/null

Then check statistics. It says 'pi' only sched-in 1 time.
$ sudo ./perf sched latency | grep pi
compiz:4054 | 6.389 ms | 30 | avg: 0.023 ms | max: 0.122 ms | max at: 94546.021080 s
pi:4059 | 2083.241 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 94545.201435 s

But the sched event show 'pi' has been sched-in 7 times.
$ sudo ./perf sched script | grep pi:
pi 4059 [001] 94545.820858: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1:32237 [120]
kworker/1:1 32237 [001] 94545.820868: sched:sched_switch: kworker/1:1:32237 [120] R ==> pi:4059 [120]
pi 4059 [001] 94545.885412: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
kworker/1:1H 320 [001] 94545.885419: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
pi 4059 [001] 94545.907869: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
kworker/1:1H 320 [001] 94545.907875: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
pi 4059 [001] 94545.908104: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
kworker/1:1H 320 [001] 94545.908108: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
pi 4059 [001] 94545.916135: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
kworker/1:1H 320 [001] 94545.916154: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
pi 4059 [001] 94546.812856: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1:32237 [120]
kworker/1:1 32237 [001] 94546.813148: sched:sched_switch: kworker/1:1:32237 [120] R ==> pi:4059 [120]
pi 4059 [001] 94546.885227: sched:sched_switch: pi:4059 [120] S ==> i915/signal:1:207 [98]
i915/signal:1 207 [001] 94546.885232: sched:sched_switch: i915/signal:1:207 [98] D ==> pi:4059 [120]
pi 4059 [001] 94547.285049: sched:sched_switch: pi:4059 [120] x ==> swapper/1:0 [120]

Does anyone know why? Thank you! :)

--
Thanks,
Changbin Du

2018-02-08 00:58:24

by Namhyung Kim

Subject: Re: A problem about 'perf sched latency'

Hello,

On Tue, Feb 06, 2018 at 09:50:02PM +0800, Du, Changbin wrote:
> Hello all,
> I am using perf sched tool to analyzer sched data on my machine. But it seems that
> 'perf sched latency' report incorrect 'Switches'. What I did is as below.
>
> First, record...
> $ sudo perf sched record time pi 2000000 > /dev/null
>
> Then check statistics. It says 'pi' only sched-in 1 time.
> $ sudo ./perf sched latency | grep pi
> compiz:4054 | 6.389 ms | 30 | avg: 0.023 ms | max: 0.122 ms | max at: 94546.021080 s
> pi:4059 | 2083.241 ms | 1 | avg: 0.007 ms | max: 0.007 ms | max at: 94545.201435 s
>
> But the sched event show 'pi' has been sched-in 7 times.
> $ sudo ./perf sched script | grep pi:
> pi 4059 [001] 94545.820858: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1:32237 [120]
> kworker/1:1 32237 [001] 94545.820868: sched:sched_switch: kworker/1:1:32237 [120] R ==> pi:4059 [120]
> pi 4059 [001] 94545.885412: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
> kworker/1:1H 320 [001] 94545.885419: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
> pi 4059 [001] 94545.907869: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
> kworker/1:1H 320 [001] 94545.907875: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
> pi 4059 [001] 94545.908104: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
> kworker/1:1H 320 [001] 94545.908108: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
> pi 4059 [001] 94545.916135: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1H:320 [100]
> kworker/1:1H 320 [001] 94545.916154: sched:sched_switch: kworker/1:1H:320 [100] R ==> pi:4059 [120]
> pi 4059 [001] 94546.812856: sched:sched_switch: pi:4059 [120] S ==> kworker/1:1:32237 [120]
> kworker/1:1 32237 [001] 94546.813148: sched:sched_switch: kworker/1:1:32237 [120] R ==> pi:4059 [120]
> pi 4059 [001] 94546.885227: sched:sched_switch: pi:4059 [120] S ==> i915/signal:1:207 [98]
> i915/signal:1 207 [001] 94546.885232: sched:sched_switch: i915/signal:1:207 [98] D ==> pi:4059 [120]
> pi 4059 [001] 94547.285049: sched:sched_switch: pi:4059 [120] x ==> swapper/1:0 [120]
>
> Does anyone know why? Thank you! :)

It seems your data doesn't have wakeup event which is required by the
'perf sched latency'.

Thanks,
Namhyung


>
> --
> Thanks,
> Changbin Du
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html

2018-02-08 03:15:51

by Du, Changbin

Subject: Re: A problem about 'perf sched latency'

On Thu, Feb 08, 2018 at 09:57:24AM +0900, Namhyung Kim wrote:
> Hello,
>
[snip]
> > Does anyone know why? Thank you! :)
>
> It seems your data doesn't have wakeup event which is required by the
> 'perf sched latency'.
>
> Thanks,
> Namhyung
>
Hi Kim,
Thanks for your reply. I thought the 'Swicthes' is the total number of sche-in event.
Now I know it only count wakeup sched-in event. It is not documented, so confused me.

>
> >
> > --
> > Thanks,
> > Changbin Du
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> > the body of a message to [email protected]
> > More majordomo info at http://vger.kernel.org/majordomo-info.html

--
Thanks,
Changbin Du