Re: EEVDF/vhost regression (bisected to 86bfbb7ce4f6 sched/fair: Add lag based placement)

[Bagas Sanjaya <bagasdotme@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 18726 bytes --]

On Thu, Nov 16, 2023 at 07:58:18PM +0100, Tobias Huschle wrote:
> Hi,
> 
> when testing the EEVDF scheduler we stumbled upon a performance regression
> in a uperf scenario and would like to
> kindly ask for feedback on whether we are going into the right direction
> with our analysis so far.
> 
> The base scenario are two KVM guests running on an s390 LPAR. One guest
> hosts the uperf server, one the uperf client.
> With EEVDF we observe a regression of ~50% for a strburst test.
> For a more detailed description of the setup see the section TEST SUMMARY at
> the bottom.
> 
> Bisecting led us to the following commit which appears to introduce the
> regression:
> 86bfbb7ce4f6 sched/fair: Add lag based placement
> 
> We then compared the last good commit we identified with a recent level of
> the devel branch.
> The issue still persists on 6.7 rc1 although there is some improvement (down
> from 62% regression to 49%)
> 
> All analysis described further are based on a 6.6 rc7 kernel.
> 
> We sampled perf data to get an idea on what is going wrong and ended up
> seeing an dramatic increase in the maximum
> wait times from 3ms up to 366ms. See section WAIT DELAYS below for more
> details.
> 
> We then collected tracing data to get a better insight into what is going
> on.
> The trace excerpt in section TRACE EXCERPT shows one example (of multiple
> per test run) of the problematic scenario where
> a kworker(pid=6525) has to wait for 39,718 ms.
> 
> Short summary:
> The mentioned kworker has been scheduled to CPU 14 before the tracing was
> enabled.
> A vhost process is migrated onto CPU 14.
> The vruntimes of kworker and vhost differ significantly (86642125805 vs
> 4242563284 -> factor 20)
> The vhost process wants to wake up the kworker, therefore the kworker is
> placed onto the runqueue again and set to runnable.
> The vhost process continues to execute, waking up other vhost processes on
> other CPUs.
> 
> So far this behavior is not different to what we see on pre-EEVDF kernels.
> 
> On timestamp 576.162767, the vhost process triggers the last wake up of
> another vhost on another CPU.
> Until timestamp 576.171155, we see no other activity. Now, the vhost process
> ends its time slice.
> Then, vhost gets re-assigned new time slices 4 times and gets then migrated
> off to CPU 15.
> This does not occur with older kernels.
> The kworker has to wait for the migration to happen in order to be able to
> execute again.
> This is due to the fact, that the vruntime of the kworker is significantly
> larger than the one of vhost.
> 
> 
> We observed the large difference in vruntime between kworker and vhost in
> the same magnitude on
> a kernel built based on the parent of the commit mentioned above.
> With EEVDF, the kworker is doomed to wait until the vhost either catches up
> on vruntime (which would take 86 seconds)
> or the vhost is migrated off of the CPU.
> 
> We found some options which sound plausible but we are not sure if they are
> valid or not:
> 
> 1. The wake up path has a dependency on the vruntime metrics that now delays
> the execution of the kworker.
> 2. The previous commit af4cf40470c2 (sched/fair: Add cfs_rq::avg_vruntime)
> which updates the way cfs_rq->min_vruntime and
>     cfs_rq->avg_runtime are set might have introduced an issue which is
> uncovered with the commit mentioned above.
> 3. An assumption in the vhost code which causes vhost to rely on being
> scheduled off in time to allow the kworker to proceed.
> 
> We also stumbled upon the following mailing thread:
> https://lore.kernel.org/lkml/ZORaUsd+So+tnyMV@chenyu5-mobl2/
> That conversation, and the patches derived from it lead to the assumption
> that the wake up path might be adjustable in a way
> that this case in particular can be addressed.
> At the same time, the vast difference in vruntimes is concerning since, at
> least for some time frame, both processes are on the runqueue.
> 
> We would be glad to hear some feedback on which paths to pursue and which
> might just be a dead end in the first place.
> 
> 
> #################### TRACE EXCERPT ####################
> The sched_place trace event was added to the end of the place_entity
> function and outputs:
> sev -> sched_entity vruntime
> sed -> sched_entity deadline
> sel -> sched_entity vlag
> avg -> cfs_rq avg_vruntime
> min -> cfs_rq min_vruntime
> cpu -> cpu of cfs_rq
> nr  -> cfs_rq nr_running
> ---
>     CPU 3/KVM-2950    [014] d....   576.161432: sched_migrate_task:
> comm=vhost-2920 pid=2941 prio=120 orig_cpu=15 dest_cpu=14
> --> migrates task from cpu 15 to 14
>     CPU 3/KVM-2950    [014] d....   576.161433: sched_place: comm=vhost-2920
> pid=2941 sev=4242563284 sed=4245563284 sel=0 avg=4242563284 min=4242563284
> cpu=14 nr=0
> --> places vhost 2920 on CPU 14 with vruntime 4242563284
>     CPU 3/KVM-2950    [014] d....   576.161433: sched_place: comm= pid=0
> sev=16329848593 sed=16334604010 sel=0 avg=16329848593 min=16329848593 cpu=14
> nr=0
>     CPU 3/KVM-2950    [014] d....   576.161433: sched_place: comm= pid=0
> sev=42560661157 sed=42627443765 sel=0 avg=42560661157 min=42560661157 cpu=14
> nr=0
>     CPU 3/KVM-2950    [014] d....   576.161434: sched_place: comm= pid=0
> sev=53846627372 sed=54125900099 sel=0 avg=53846627372 min=53846627372 cpu=14
> nr=0
>     CPU 3/KVM-2950    [014] d....   576.161434: sched_place: comm= pid=0
> sev=86640641980 sed=87255041979 sel=0 avg=86640641980 min=86640641980 cpu=14
> nr=0
>     CPU 3/KVM-2950    [014] dN...   576.161434: sched_stat_wait:
> comm=vhost-2920 pid=2941 delay=9958 [ns]
>     CPU 3/KVM-2950    [014] d....   576.161435: sched_switch: prev_comm=CPU
> 3/KVM prev_pid=2950 prev_prio=120 prev_state=S ==> next_comm=vhost-2920
> next_pid=2941 next_prio=120
>    vhost-2920-2941    [014] D....   576.161439: sched_waking:
> comm=vhost-2286 pid=2309 prio=120 target_cpu=008
>    vhost-2920-2941    [014] d....   576.161446: sched_waking:
> comm=kworker/14:0 pid=6525 prio=120 target_cpu=014
>    vhost-2920-2941    [014] d....   576.161447: sched_place:
> comm=kworker/14:0 pid=6525 sev=86642125805 sed=86645125805 sel=0
> avg=86642125805 min=86642125805 cpu=14 nr=1
> --> places kworker 6525 on cpu 14 with vruntime 86642125805
> -->  which is far larger than vhost vruntime of  4242563284
>    vhost-2920-2941    [014] d....   576.161447: sched_stat_blocked:
> comm=kworker/14:0 pid=6525 delay=10143757 [ns]
>    vhost-2920-2941    [014] dN...   576.161447: sched_wakeup:
> comm=kworker/14:0 pid=6525 prio=120 target_cpu=014
>    vhost-2920-2941    [014] dN...   576.161448: sched_stat_runtime:
> comm=vhost-2920 pid=2941 runtime=13884 [ns] vruntime=4242577168 [ns]
> --> vhost 2920 finishes after 13884 ns of runtime
>    vhost-2920-2941    [014] dN...   576.161448: sched_stat_wait:
> comm=kworker/14:0 pid=6525 delay=0 [ns]
>    vhost-2920-2941    [014] d....   576.161448: sched_switch:
> prev_comm=vhost-2920 prev_pid=2941 prev_prio=120 prev_state=R+ ==>
> next_comm=kworker/14:0 next_pid=6525 next_prio=120
> --> switch to kworker
>  kworker/14:0-6525    [014] d....   576.161449: sched_waking: comm=CPU 2/KVM
> pid=2949 prio=120 target_cpu=007
>  kworker/14:0-6525    [014] d....   576.161450: sched_stat_runtime:
> comm=kworker/14:0 pid=6525 runtime=3714 [ns] vruntime=86642129519 [ns]
> --> kworker finshes after 3714 ns of runtime
>  kworker/14:0-6525    [014] d....   576.161450: sched_stat_wait:
> comm=vhost-2920 pid=2941 delay=3714 [ns]
>  kworker/14:0-6525    [014] d....   576.161451: sched_switch:
> prev_comm=kworker/14:0 prev_pid=6525 prev_prio=120 prev_state=I ==>
> next_comm=vhost-2920 next_pid=2941 next_prio=120
> --> switch back to vhost
>    vhost-2920-2941    [014] d....   576.161478: sched_waking:
> comm=kworker/14:0 pid=6525 prio=120 target_cpu=014
>    vhost-2920-2941    [014] d....   576.161478: sched_place:
> comm=kworker/14:0 pid=6525 sev=86642191859 sed=86645191859 sel=-1150
> avg=86642188144 min=86642188144 cpu=14 nr=1
> --> kworker placed again on cpu 14 with vruntime 86642191859, the problem
> occurs only if lag <= 0, having lag=0 does not always hit the problem though
>    vhost-2920-2941    [014] d....   576.161478: sched_stat_blocked:
> comm=kworker/14:0 pid=6525 delay=27943 [ns]
>    vhost-2920-2941    [014] d....   576.161479: sched_wakeup:
> comm=kworker/14:0 pid=6525 prio=120 target_cpu=014
>    vhost-2920-2941    [014] D....   576.161511: sched_waking:
> comm=vhost-2286 pid=2308 prio=120 target_cpu=006
>    vhost-2920-2941    [014] D....   576.161512: sched_waking:
> comm=vhost-2286 pid=2309 prio=120 target_cpu=008
>    vhost-2920-2941    [014] D....   576.161516: sched_waking:
> comm=vhost-2286 pid=2308 prio=120 target_cpu=006
>    vhost-2920-2941    [014] D....   576.161773: sched_waking:
> comm=vhost-2286 pid=2308 prio=120 target_cpu=006
>    vhost-2920-2941    [014] D....   576.161775: sched_waking:
> comm=vhost-2286 pid=2309 prio=120 target_cpu=008
>    vhost-2920-2941    [014] D....   576.162103: sched_waking:
> comm=vhost-2286 pid=2308 prio=120 target_cpu=006
>    vhost-2920-2941    [014] D....   576.162105: sched_waking:
> comm=vhost-2286 pid=2307 prio=120 target_cpu=021
>    vhost-2920-2941    [014] D....   576.162326: sched_waking:
> comm=vhost-2286 pid=2305 prio=120 target_cpu=004
>    vhost-2920-2941    [014] D....   576.162437: sched_waking:
> comm=vhost-2286 pid=2308 prio=120 target_cpu=006
>    vhost-2920-2941    [014] D....   576.162767: sched_waking:
> comm=vhost-2286 pid=2305 prio=120 target_cpu=004
>    vhost-2920-2941    [014] d.h..   576.171155: sched_stat_runtime:
> comm=vhost-2920 pid=2941 runtime=9704465 [ns] vruntime=4252281633 [ns]
>    vhost-2920-2941    [014] d.h..   576.181155: sched_stat_runtime:
> comm=vhost-2920 pid=2941 runtime=10000377 [ns] vruntime=4262282010 [ns]
>    vhost-2920-2941    [014] d.h..   576.191154: sched_stat_runtime:
> comm=vhost-2920 pid=2941 runtime=9999514 [ns] vruntime=4272281524 [ns]
>    vhost-2920-2941    [014] d.h..   576.201155: sched_stat_runtime:
> comm=vhost-2920 pid=2941 runtime=10000246 [ns] vruntime=4282281770 [ns]
> --> vhost gets rescheduled multiple times because its vruntime is
> significantly smaller than the vruntime of the kworker
>    vhost-2920-2941    [014] dNh..   576.201176: sched_wakeup:
> comm=migration/14 pid=85 prio=0 target_cpu=014
>    vhost-2920-2941    [014] dN...   576.201191: sched_stat_runtime:
> comm=vhost-2920 pid=2941 runtime=25190 [ns] vruntime=4282306960 [ns]
>    vhost-2920-2941    [014] d....   576.201192: sched_switch:
> prev_comm=vhost-2920 prev_pid=2941 prev_prio=120 prev_state=R+ ==>
> next_comm=migration/14 next_pid=85 next_prio=0
>  migration/14-85      [014] d..1.   576.201194: sched_migrate_task:
> comm=vhost-2920 pid=2941 prio=120 orig_cpu=14 dest_cpu=15
> --> vhost gets migrated off of cpu 14
>  migration/14-85      [014] d..1.   576.201194: sched_place: comm=vhost-2920
> pid=2941 sev=3198666923 sed=3201666923 sel=0 avg=3198666923 min=3198666923
> cpu=15 nr=0
>  migration/14-85      [014] d..1.   576.201195: sched_place: comm= pid=0
> sev=12775683594 sed=12779398224 sel=0 avg=12775683594 min=12775683594 cpu=15
> nr=0
>  migration/14-85      [014] d..1.   576.201195: sched_place: comm= pid=0
> sev=33655559178 sed=33661025369 sel=0 avg=33655559178 min=33655559178 cpu=15
> nr=0
>  migration/14-85      [014] d..1.   576.201195: sched_place: comm= pid=0
> sev=42240572785 sed=42244083642 sel=0 avg=42240572785 min=42240572785 cpu=15
> nr=0
>  migration/14-85      [014] d..1.   576.201196: sched_place: comm= pid=0
> sev=70190876523 sed=70194789898 sel=-13068763 avg=70190876523
> min=70190876523 cpu=15 nr=0
>  migration/14-85      [014] d....   576.201198: sched_stat_wait:
> comm=kworker/14:0 pid=6525 delay=39718472 [ns]
>  migration/14-85      [014] d....   576.201198: sched_switch:
> prev_comm=migration/14 prev_pid=85 prev_prio=0 prev_state=S ==>
> next_comm=kworker/14:0 next_pid=6525 next_prio=120
>  --> only now, kworker is eligible to run again, after a delay of 39718472
> ns
>  kworker/14:0-6525    [014] d....   576.201200: sched_waking: comm=CPU 0/KVM
> pid=2947 prio=120 target_cpu=012
>  kworker/14:0-6525    [014] d....   576.201290: sched_stat_runtime:
> comm=kworker/14:0 pid=6525 runtime=92941 [ns] vruntime=86642284800 [ns]
> 
> #################### WAIT DELAYS - PERF LATENCY ####################
> last good commit --> perf sched latency -s max
> -------------------------------------------------------------------------------------------------------------------------------------------
>   Task                  |   Runtime ms  | Switches | Avg delay ms    | Max
> delay ms    | Max delay start           | Max delay end          |
> -------------------------------------------------------------------------------------------------------------------------------------------
>   CPU 2/KVM:(2)         |   5399.650 ms |   108698 | avg:   0.003 ms | max:
> 3.077 ms | max start:   544.090322 s | max end:   544.093399 s
>   CPU 7/KVM:(2)         |   5111.132 ms |    69632 | avg:   0.003 ms | max:
> 2.980 ms | max start:   544.690994 s | max end:   544.693974 s
>   kworker/22:3-ev:723   |    342.944 ms |    63417 | avg:   0.005 ms | max:
> 1.880 ms | max start:   545.235430 s | max end:   545.237310 s
>   CPU 0/KVM:(2)         |   8171.431 ms |   433099 | avg:   0.003 ms | max:
> 1.004 ms | max start:   547.970344 s | max end:   547.971348 s
>   CPU 1/KVM:(2)         |   5486.260 ms |   258702 | avg:   0.003 ms | max:
> 1.002 ms | max start:   548.782514 s | max end:   548.783516 s
>   CPU 5/KVM:(2)         |   4766.143 ms |    65727 | avg:   0.003 ms | max:
> 0.997 ms | max start:   545.313610 s | max end:   545.314607 s
>   vhost-2268:(6)        |  13206.503 ms |   315030 | avg:   0.003 ms | max:
> 0.989 ms | max start:   550.887761 s | max end:   550.888749 s
>   vhost-2892:(6)        |  14467.268 ms |   214005 | avg:   0.003 ms | max:
> 0.981 ms | max start:   545.213819 s | max end:   545.214800 s
>   CPU 3/KVM:(2)         |   5538.908 ms |    85105 | avg:   0.003 ms | max:
> 0.883 ms | max start:   547.138139 s | max end:   547.139023 s
>   CPU 6/KVM:(2)         |   5289.827 ms |    72301 | avg:   0.003 ms | max:
> 0.836 ms | max start:   551.094590 s | max end:   551.095425 s
> 
> 6.6 rc7 --> perf sched latency -s max
> -------------------------------------------------------------------------------------------------------------------------------------------
>   Task                  |   Runtime ms  | Switches | Avg delay ms    | Max
> delay ms    | Max delay start           | Max delay end          |
> -------------------------------------------------------------------------------------------------------------------------------------------
>   kworker/19:2-ev:1071  |     69.482 ms |    12700 | avg:   0.050 ms | max:
> 366.314 ms | max start: 54705.674294 s | max end: 54706.040607 s
>   kworker/13:1-ev:184   |     78.048 ms |    14645 | avg:   0.067 ms | max:
> 287.738 ms | max start: 54710.312863 s | max end: 54710.600602 s
>   kworker/12:1-ev:46148 |    138.488 ms |    26660 | avg:   0.021 ms | max:
> 147.414 ms | max start: 54706.133161 s | max end: 54706.280576 s
>   kworker/16:2-ev:33076 |    149.175 ms |    29491 | avg:   0.026 ms | max:
> 139.752 ms | max start: 54708.410845 s | max end: 54708.550597 s
>   CPU 3/KVM:(2)         |   1934.714 ms |    41896 | avg:   0.007 ms | max:
> 92.126 ms | max start: 54713.158498 s | max end: 54713.250624 s
>   kworker/7:2-eve:17001 |     68.164 ms |    11820 | avg:   0.045 ms | max:
> 69.717 ms | max start: 54707.100903 s | max end: 54707.170619 s
>   kworker/17:1-ev:46510 |     68.804 ms |    13328 | avg:   0.037 ms | max:
> 67.894 ms | max start: 54711.022711 s | max end: 54711.090605 s
>   kworker/21:1-ev:45782 |     68.906 ms |    13215 | avg:   0.021 ms | max:
> 59.473 ms | max start: 54709.351135 s | max end: 54709.410608 s
>   ksoftirqd/17:101      |      0.041 ms |        2 | avg:  25.028 ms | max:
> 50.047 ms | max start: 54711.040578 s | max end: 54711.090625 s
> 
> #################### TEST SUMMARY ####################
>  Setup description:
> - single KVM host with 2 identical guests
> - guests are connected virtually via Open vSwitch
> - guests run uperf streaming read workload with 50 parallel connections
> - one guests acts as uperf client, the other one as uperf server
> 
> Regression:
> kernel-6.5.0-rc2: 78 Gb/s (before 86bfbb7ce4f6 sched/fair: Add lag based
> placement)
> kernel-6.5.0-rc2: 29 Gb/s (with 86bfbb7ce4f6 sched/fair: Add lag based
> placement)
> kernel-6.7.0-rc1: 41 Gb/s
> 
> KVM host:
> - 12 dedicated IFLs, SMT-2 (24 Linux CPUs)
> - 64 GiB memory
> - FEDORA 38
> - kernel commandline: transparent_hugepage=never audit_enable=0 audit=0
> audit_debug=0 selinux=0
> 
> KVM guests:
> - 8 vCPUs
> - 8 GiB memory
> - RHEL 9.2
> - kernel: 5.14.0-162.6.1.el9_1.s390x
> - kernel commandline: transparent_hugepage=never audit_enable=0 audit=0
> audit_debug=0 selinux=0
> 
> Open vSwitch:
> - Open vSwitch with 2 ports, each with mtu=32768 and qlen=15000
> - Open vSwitch ports attached to guests via virtio-net
> - each guest has 4 vhost-queues
> 
> Domain xml snippet for Open vSwitch port:
> <interface type="bridge" dev="OVS">
>   <source bridge="vswitch0"/>
>   <mac address="02:bb:97:28:02:02"/>
>   <virtualport type="openvswitch"/>
>   <model type="virtio"/>
>   <target dev="vport1"/>
>   <driver name="vhost" queues="4"/>
>   <address type="ccw" cssid="0xfe" ssid="0x0" devno="0x0002"/>
> </interface>
> 
> Benchmark: uperf
> - workload: str-readx30k, 50 active parallel connections
> - uperf server permanently sends data in 30720-byte chunks
> - uperf client receives and acknowledges this data
> - Server: uperf -s
> - Client: uperf -a -i 30 -m uperf.xml
> 
> uperf.xml:
> <?xml version="1.0"?>
> <profile name="strburst">
>   <group nprocs="50">
>     <transaction iterations="1">
>       <flowop type="connect" options="remotehost=10.161.28.3 protocol=tcp
> "/>
>     </transaction>
>     <transaction duration="300">
>       <flowop type="read" options="count=640 size=30k"/>
>     </transaction>
>     <transaction iterations="1">
>       <flowop type="disconnect" />
>     </transaction>
>   </group>
> </profile>

Thanks for the regression report. I'm adding it to regzbot:

#regzbot ^introduced: 86bfbb7ce4f67a

-- 
An old man doll... just what I always wanted! - Clara

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 228 bytes --]