sched: Too many IPIs while running context_switch2 within the same core

[gautshen]

@antonblanchard pointed out that we were observing way too many IPIs when we run context_switch2 benchmark (https://ozlabs.org/~anton/junkcode/context_switch2.c) with the threads pinned to CPUs 0 1 compared to when they were pinned to CPUs 0 8.

#./context_switch2 0 1 --timeout=5
317818
318326
317944
318452
316468

CPU 0
		  16 [XIVE-IPI 0 Edge IPI] = 197212 times
CPU 1
		  16 [XIVE-IPI 0 Edge IPI] = 171036 times

Compared to

#../context_switch2 0 8 --timeout=5
289384
289924
289358
289602
289410

CPU 0
		  16 [XIVE-IPI 0 Edge IPI] = 105 times
CPU 8
		  16 [XIVE-IPI 0 Edge IPI] = 286 times

Figure out the reason for the humongous number of IPIs in the 0 1 case.

[gautshen]

Created perf probe for the following two functions smp_send_reschedule and arch_send_call_function_single_ipi which is used by the scheduler to send IPIs.

In the 0 1 case,

CPUA=0
CPUB=1

#perf record -C $CPUA,$CPUB \
 -e probe:smp_send_reschedule,probe:arch_send_call_function_single_ipi \
 -g -o perf.data.$CPUA-$CPUB\
./context_switch2 $CPUA $CPUB --timeout=5

Analysing the perf.data.0-1 we can see that event smp_send_reschedule was hit 353194 times while event arch_send_call_function_single_ipi was hit 15940 times.

With 0 8 case as follows

CPUA=0
CPUB=8

#perf record -C $CPUA,$CPUB \
  -e probe:smp_send_reschedule,probe:arch_send_call_function_single_ipi \
  -g -o perf.data.$CPUA-$CPUB\
./context_switch2 $CPUA $CPUB --timeout=5

from perf.data.0-8 we can see that event smp_send_reschedule was hit 13 times while event arch_send_call_function_single_ipi was hit 449 times.

So we are seeing these IPIs from the scheduler.

[gautshen]

For the 0 1 case, for smp_send_reschedule (Approx count = 353194)

 51.73%     0.00%  :18850           [kernel.vmlinux]    [k] ksys_write
            |
            ---ksys_write
               vfs_write
               new_sync_write
               pipe_write
               __wake_up_common_lock
               __wake_up_common
               autoremove_wake_function
               try_to_wake_up
               ttwu_do_wakeup
               check_preempt_curr
               resched_curr
               smp_send_reschedule

    48.27%     0.00%  :18849           [kernel.vmlinux]    [k] ksys_write
            |
            ---ksys_write
               vfs_write
               new_sync_write
               pipe_write
               __wake_up_common_lock
               __wake_up_common
               autoremove_wake_function
               try_to_wake_up
               ttwu_do_wakeup
               check_preempt_curr
               resched_curr
               smp_send_reschedule

while for arch_send_call_function_single_ipi (approx count = 15940)

92.94%     0.00%  :18850           [kernel.vmlinux]            [k] system_call_common
            |
            ---system_call_common
               |          
                --92.92%--system_call_exception
                          |          
                          |--91.68%--ksys_write
                          |          |          
                          |           --91.51%--vfs_write
                          |                     |          
                          |                      --91.41%--new_sync_write
                          |                                pipe_write
                          |                                |          
                          |                                 --91.28%--__wake_up_common_lock
                          |                                           |          
                          |                                            --90.85%--__wake_up_common
                          |                                                      autoremove_wake_function
                          |                                                      try_to_wake_up
                          |                                                      ttwu_queue_wakelist
                          |                                                      __smp_call_single_queue
                          |                                                      send_call_function_single_ipi
                          |                                                      arch_send_call_function_single_ipi

[gautshen]

For the 0 8 case, the smp_send_reschedule are only 13 in number.

While we have 449 cases of arch_send_call_function_single_ipi

              |          |--62.81%--0x76cb0c438464
               |          |          system_call_common
               |          |          system_call_exception
               |          |          |          
               |          |          |--62.14%--ksys_write
               |          |          |          |          
               |          |          |           --61.69%--vfs_write
               |          |          |                     |          
               |          |          |                     |--60.58%--new_sync_write
               |          |          |                     |          pipe_write
               |          |          |                     |          __wake_up_common_lock
               |          |          |                     |          |          
               |          |          |                     |          |--59.69%--__wake_up_common
               |          |          |                     |          |          autoremove_wake_function
               |          |          |                     |          |          try_to_wake_up
               |          |          |                     |          |          ttwu_queue_wakelist
               |          |          |                     |          |          __smp_call_single_queue
               |          |          |                     |          |          send_call_function_single_ipi
               |          |          |                     |          |          arch_send_call_function_single_ipi


           |                      --22.27%--0x76cb0c438464
               |                                system_call_common
               |                                system_call_exception
               |                                |          
               |                                |--21.16%--ksys_write
               |                                |          |          
               |                                |           --20.94%--vfs_write
               |                                |                     new_sync_write
               |                                |                     pipe_write
               |                                |                     |          
               |                                |                      --20.71%--__wake_up_common_lock
               |                                |                                |          
               |                                |                                |--19.15%--__wake_up_common
               |                                |                                |          autoremove_wake_function
               |                                |                                |          try_to_wake_up
               |                                |                                |          ttwu_queue_wakelist
               |                                |                                |          __smp_call_single_queue
               |                                |                                |          send_call_function_single_ipi
               |                                |                                |          arch_send_call_function_single_ipi

[gautshen]

Srikar suggested echo NO_TTWU_QUEUE > /sys/kernel/debug/sched_features. With this,

CPUA=0
CPUB=1

#perf record -C $CPUA,$CPUB \
 -e probe:smp_send_reschedule,probe:arch_send_call_function_single_ipi \
 -g -o perf.data.$CPUA-$CPUB\
./context_switch2 $CPUA $CPUB --timeout=5
321562
323160
324762
321612
321428

 =========================== IPI details ================================
CPU 0
		  16 [XIVE-IPI 0 Edge IPI] = 240727 times
CPU 1
		  16 [XIVE-IPI 0 Edge IPI] = 77740 times

From the perf-data

=================== Scheduler IPI events ===========================

Event smp_send_reschedule was hit 318398 times


Event arch_send_call_function_single_ipi was hit 886 times

====================== snooze residency Details ============================

Thus, with NO_TTWU_QUEUE the number of arch_send_call_function_single_ipi reduces, it does not impact smp_send_reschedule.

[gautshen]

Withecho NO_TTWU_QUEUE > /sys/kernel/debug/sched_features, in the 0 8 case,

CPUA=0
CPUB=8

#perf record -C $CPUA,$CPUB \
  -e probe:smp_send_reschedule,probe:arch_send_call_function_single_ipi \
  -g -o perf.data.$CPUA-$CPUB\
./context_switch2 $CPUA $CPUB --timeout=5
277246
277376
277410
278068
277124

IPI details

 =========================== IPI details ================================
CPU 0
		  16 [XIVE-IPI 0 Edge IPI] = 95 times
CPU 8
		  16 [XIVE-IPI 0 Edge IPI] = 208 times

From the perf.data

=================== Scheduler IPI events ===========================

Event smp_send_reschedule was hit 264 times


Event arch_send_call_function_single_ipi was hit 82 times

We see an increase in the number of smp_send_reschedule while the count of arch_send_call_function_single_ipi decreases.

[gautshen]

From the idle-state residency perspective, we can see that in the 0 8 case the CPUs enter snooze_loop lot more compared to the 0 1 case. Since we set the TIF_POLLING flag inside snooze_loop() and check for need_resched(), the waker of an idle CPU does not have to send an IPI.

In the 0 8 case

CPU 0:
State snooze : Disabled = 0: Usage = 693535 times(859899 us)
State CEDE : Disabled = 0: Usage = 24 times(95895 us)

CPU 8:
State snooze : Disabled = 0: Usage = 693384 times(826166 us)
State CEDE : Disabled = 0: Usage = 16 times(256806 us)

while in the 0 1 case

CPU 0:
State snooze : Disabled = 0: Usage = 403098 times(151279 us)
State CEDE : Disabled = 0: Usage = 13 times(51911 us)

CPU 1:
State snooze : Disabled = 0: Usage = 349374 times(222318 us)
State CEDE : Disabled = 0: Usage = 8 times(25107 us)

Thus the residency inside the snooze_loop is 4-5x higher in 0 8 case compared to the 0 1 case.