Re: [PATCH v3] perf sched: Fix sched latency analysis incorrect

From: Mike Galbraith
Date: Tue Mar 21 2023 - 03:33:27 EST


On Fri, 2023-03-17 at 14:32 +0800, Chunxin Zang wrote:
> 'perf sched latency' is incorrect to get process schedule latency
> when it used 'sched:sched_wakeup' to analysis perf.data.
>
> Because 'perf record' prefer use 'sched:sched_waking' to
> 'sched:sched_wakeup' since commit d566a9c2d482 ("perf sched: Prefer
> sched_waking event when it exists"). It's very reasonable to
> evaluate process schedule latency.

Yeah, that makes a.. not so tiny difference. Thanks.
(off to flush large pile of.. not data)

su - mikeg -c 'google-chrome-stable https://www.youtube.com/watch?v=aqz-KE-bpKQ > /dev/null 2>&1'&
massive_intr 8 9999&
# allow time to select display size/res
sleep 10
perf sched record -a -- cyclictest -Smqi 1234 -d 0&
sleep 300
killall cyclictest
sleep 1
killall massive_intr chrome

cyclictest output
T: 0 (10255) P: 0 I:1234 C: 194367 Min: 4 Act: 55 Avg: 484 Max: 22776
T: 1 (10256) P: 0 I:1234 C: 194346 Min: 6 Act: 57 Avg: 480 Max: 18589
T: 2 (10257) P: 0 I:1234 C: 194034 Min: 5 Act: 5214 Avg: 482 Max: 18530
T: 3 (10258) P: 0 I:1234 C: 192263 Min: 5 Act: 54 Avg: 513 Max: 19385
T: 4 (10259) P: 0 I:1234 C: 193350 Min: 6 Act: 728 Avg: 492 Max: 15951
T: 5 (10260) P: 0 I:1234 C: 196233 Min: 6 Act: 56 Avg: 469 Max: 17905
T: 6 (10261) P: 0 I:1234 C: 194181 Min: 5 Act: 67 Avg: 482 Max: 17997
T: 7 (10262) P: 0 I:1234 C: 196756 Min: 7 Act: 284 Avg: 468 Max: 16287

cyclictest bits of perf sched lat -p output, sorted ala cyclictest (local hackletlet sums delay)
-----------------------------------------------------------------------------------------------------------
Task | Runtime ms | Switches | Avg delay ms | Max delay ms | Sum delay ms |
-----------------------------------------------------------------------------------------------------------
cyclictest:10255 | 1280.359 ms | 294 | avg: 0.238 ms | max: 4.929 ms | sum: 69.921 ms |
cyclictest:10256 | 1293.976 ms | 163 | avg: 0.463 ms | max: 6.619 ms | sum: 75.497 ms |
cyclictest:10257 | 1259.701 ms | 206 | avg: 0.371 ms | max: 5.659 ms | sum: 76.453 ms |
cyclictest:10258 | 1299.337 ms | 171 | avg: 0.440 ms | max: 4.210 ms | sum: 75.267 ms |
cyclictest:10259 | 1436.543 ms | 181 | avg: 0.472 ms | max: 8.466 ms | sum: 85.473 ms |
cyclictest:10260 | 1401.824 ms | 210 | avg: 0.386 ms | max: 7.007 ms | sum: 81.036 ms |
cyclictest:10261 | 1336.621 ms | 190 | avg: 0.387 ms | max: 4.244 ms | sum: 73.593 ms |
cyclictest:10262 | 1393.249 ms | 283 | avg: 0.268 ms | max: 4.381 ms | sum: 75.778 ms |
+patchlet
cyclictest:10252 | 218.546 ms | 28657 | avg: 0.437 ms | max: 12.616 ms | sum:12514.777 ms | <== *poof*
cyclictest:10255 | 1280.359 ms | 194661 | avg: 0.431 ms | max: 22.722 ms | sum:83954.384 ms |
cyclictest:10256 | 1293.976 ms | 194509 | avg: 0.427 ms | max: 18.537 ms | sum:83115.895 ms |
cyclictest:10257 | 1259.701 ms | 194240 | avg: 0.429 ms | max: 18.509 ms | sum:83408.424 ms |
cyclictest:10258 | 1299.337 ms | 192434 | avg: 0.460 ms | max: 19.331 ms | sum:88555.775 ms |
cyclictest:10259 | 1436.543 ms | 193531 | avg: 0.439 ms | max: 15.897 ms | sum:84989.121 ms |
cyclictest:10260 | 1401.824 ms | 196443 | avg: 0.417 ms | max: 17.852 ms | sum:81818.898 ms |
cyclictest:10261 | 1336.621 ms | 194371 | avg: 0.429 ms | max: 17.944 ms | sum:83443.732 ms |
cyclictest:10262 | 1393.249 ms | 197039 | avg: 0.415 ms | max: 16.232 ms | sum:81752.473 ms |


-Mike