Re: PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled

[Tomasz Grabiec]

On Sun, May 8, 2016 at 2:19 AM, Wanpeng Li <kernellwp@xxxxxxxxx> wrote:
>
> 2016-05-06 23:43 GMT+08:00 Tomasz Grabiec <tgrabiec@xxxxxxxxxxxx>:
> > Hi,
> >
> > System details:
> >
> >   Kernel: 4.2.0-27-generic #32~14.04.1-Ubuntu SMP Fri Jan 22 15:32:26
> > UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
> >   CPU: 2 sockets, 8 cores per socket, 2 threads per core
> >   CPU Model: Intel(R) Xeon(R) CPU E5-2630 v3 @ 2.40GHz
> >
> > I was trying to reduce scheduling delays below 1/HZ, which is 4ms
> > for our kernel. I enabled HRTICK scheduler feature and set
> > scheduler tunables to:
> >
> >   sched_latency_ns: 1000000
> >   sched_min_granularity_ns: 400000
> >   sched_wakeup_granularity_ns: 400000
> >   sched_autogroup_enabled: 0
> >   sched_tunable_scaling: 1
> >   sched_cfs_bandwidth_slice_us: 5000
> >   sched_child_runs_first: 0
> >   sched_migration_cost_ns: 500000
> >   sched_nr_migrate: 32
> >   sched_rr_timeslice_ms: 25
> >   sched_rt_period_us: 1000000
> >   sched_rt_runtime_us: 950000
> >   sched_shares_window_ns: 1000000
> >   sched_time_avg_ms: 1000
> >
> > Note that scheduling latency is set to 1ms and min_granularity to 0.4ms.
> >
> > The test case I used was to run two processes competing for CPU
> > pinned to a single core, like this:
> >
> >   python -c "import math; math.factorial(100000000)" &
> >   pid1=$!
> >   python -c "import math; math.factorial(100000000)" &
> >   pid2=$!
> >   sleep 1
> >   sudo taskset -cap 2 $pid1
> >   sudo taskset -cap 2 $pid2
> >
> > Using perf I've found that scheduling delays do not stay around
> > 0.5ms as could be expected from scheduling latency, but switch
> > between modes of 0.5ms and 4ms back and forth.
> >
> > For example (perf script):
> >
> >   python 147208 [002] 3272129.329011: sched:sched_stat_wait:
> > comm=python pid=147207 delay=504875 [ns]
> >   python 147207 [002] 3272129.329515: sched:sched_stat_wait:
> > comm=python pid=147208 delay=504096 [ns]
> >   python 147208 [002] 3272129.330019: sched:sched_stat_wait:
> > comm=python pid=147207 delay=503936 [ns]
> >   python 147207 [002] 3272129.330523: sched:sched_stat_wait:
> > comm=python pid=147208 delay=503888 [ns]
> >   python 147208 [002] 3272129.331067: sched:sched_stat_wait:
> > comm=python pid=147207 delay=543902 [ns]
> >   python 147207 [002] 3272129.334047: sched:sched_stat_wait:
> > comm=python pid=147208 delay=2980114 [ns]
> >   python 147208 [002] 3272129.338048: sched:sched_stat_wait:
> > comm=python pid=147207 delay=4000695 [ns]
> >   python 147207 [002] 3272129.342051: sched:sched_stat_wait:
> > comm=python pid=147208 delay=4002851 [ns]
> >   python 147208 [002] 3272129.346055: sched:sched_stat_wait:
> > comm=python pid=147207 delay=4004720 [ns]
> >   python 147207 [002] 3272129.350058: sched:sched_stat_wait:
> > comm=python pid=147208 delay=4002403 [ns]
> >   python 147208 [002] 3272129.354064: sched:sched_stat_wait:
> > comm=python pid=147207 delay=4006037 [ns]
> >   python 147207 [002] 3272129.358064: sched:sched_stat_wait:
> > comm=python pid=147208 delay=3999730 [ns]
> >
> > More detailed trace around such transition point looks like this:
> >
> >   perf record \
> >     -e sched:sched_stat_runtime \
> >     -e sched:sched_stat_wait \
> >     -e sched:sched_switch \
> >     -e probe:hrtick \
> >     -e probe:hrtick_start \
> >     -e probe:scheduler_tick -C 2
> >
> >   python   873 [002] 3273334.927836: probe:hrtick: (ffffffff8109b430)
> >   python   873 [002] 3273334.927837: sched:sched_stat_runtime:
> > comm=python pid=873 runtime=502915 [ns] vruntime=1549788940847739 [ns]
> >   python   873 [002] 3273334.927837: sched:sched_stat_runtime:
> > comm=python pid=873 runtime=880 [ns] vruntime=1549788940848619 [ns]
> >   python   873 [002] 3273334.927838: sched:sched_stat_wait:
> > comm=python pid=874 delay=503795 [ns]
> >   python   873 [002] 3273334.927838: probe:hrtick_start: (ffffffff8109f4f0)
> >   python   873 [002] 3273334.927839: sched:sched_switch:
> > prev_comm=python prev_pid=873 prev_prio=120 prev_state=R ==>
> > next_comm=python next_pid=874 next_prio=120
> >   python   874 [002] 3273334.928233: probe:scheduler_tick: (ffffffff810a1f30)
> >   python   874 [002] 3273334.928233: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=395992 [ns] vruntime=1549788941220502 [ns]
> >   python   874 [002] 3273334.928236: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=2278 [ns] vruntime=1549788941222780 [ns]
> >   python   874 [002] 3273334.928238: sched:sched_stat_wait:
> > comm=kworker/2:0 pid=93149 delay=0 [ns]
> >   python   874 [002] 3273334.928238: probe:hrtick_start: (ffffffff8109f4f0)
> >   python   874 [002] 3273334.928239: sched:sched_switch:
> > prev_comm=python prev_pid=874 prev_prio=120 prev_state=R ==>
> > next_comm=kworker/2:0 next_pid=93149 next_prio=120
> >   kworker/2:0 93149 [002] 3273334.928242: sched:sched_stat_runtime:
> > comm=kworker/2:0 pid=93149 runtime=5827 [ns] vruntime=1549788940354446
> > [ns]
> >   kworker/2:0 93149 [002] 3273334.928242: probe:hrtick_start: (ffffffff8109f4f0)
> >   kworker/2:0 93149 [002] 3273334.928243: sched:sched_stat_wait:
> > comm=python pid=874 delay=5827 [ns]
> >   kworker/2:0 93149 [002] 3273334.928244: probe:hrtick_start: (ffffffff8109f4f0)
> >   kworker/2:0 93149 [002] 3273334.928244: sched:sched_switch:
> > prev_comm=kworker/2:0 prev_pid=93149 prev_prio=120 prev_state=S ==>
> > next_comm=python next_pid=874 next_prio=120
> >   python   874 [002] 3273334.928745: probe:hrtick: (ffffffff8109b430)
> >   python   874 [002] 3273334.928745: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=503888 [ns] vruntime=1549788941726668 [ns]
> >   python   874 [002] 3273334.928746: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=910 [ns] vruntime=1549788941727578 [ns]
> >   python   874 [002] 3273334.928747: sched:sched_stat_wait:
> > comm=python pid=873 delay=908895 [ns]
> >   python   874 [002] 3273334.928747: probe:hrtick_start: (ffffffff8109f4f0)
> >   python   874 [002] 3273334.928748: sched:sched_switch:
> > prev_comm=python prev_pid=874 prev_prio=120 prev_state=R ==>
> > next_comm=python next_pid=873 next_prio=120
> >   python   873 [002] 3273334.929249: probe:hrtick: (ffffffff8109b430)
> >   python   873 [002] 3273334.929249: sched:sched_stat_runtime:
> > comm=python pid=873 runtime=502850 [ns] vruntime=1549788941351469 [ns]
> >   python   873 [002] 3273334.929250: sched:sched_stat_runtime:
> > comm=python pid=873 runtime=918 [ns] vruntime=1549788941352387 [ns]
> >   python   873 [002] 3273334.932236: probe:scheduler_tick: (ffffffff810a1f30)
> >   python   873 [002] 3273334.932237: sched:sched_stat_runtime:
> > comm=python pid=873 runtime=2986981 [ns] vruntime=1549788944339368
> > [ns]
> >   python   873 [002] 3273334.932239: sched:sched_stat_runtime:
> > comm=python pid=873 runtime=1685 [ns] vruntime=1549788944341053 [ns]
> >   python   873 [002] 3273334.932239: sched:sched_stat_wait:
> > comm=python pid=874 delay=3492434 [ns]
> >   python   873 [002] 3273334.932240: probe:hrtick_start: (ffffffff8109f4f0)
> >   python   873 [002] 3273334.932240: sched:sched_switch:
> > prev_comm=python prev_pid=873 prev_prio=120 prev_state=R ==>
> > next_comm=python next_pid=874 next_prio=120
> >   python   874 [002] 3273334.932741: probe:hrtick: (ffffffff8109b430)
> >   python   874 [002] 3273334.932742: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=503174 [ns] vruntime=1549788942230752 [ns]
> >   python   874 [002] 3273334.932743: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=948 [ns] vruntime=1549788942231700 [ns]
> >   python   874 [002] 3273334.936240: probe:scheduler_tick: (ffffffff810a1f30)
> >   python   874 [002] 3273334.936241: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=3497530 [ns] vruntime=1549788945729230
> > [ns]
> >   python   874 [002] 3273334.936249: sched:sched_stat_runtime:
> > comm=python pid=874 runtime=8553 [ns] vruntime=1549788945737783 [ns]
> >   python   874 [002] 3273334.936250: sched:sched_stat_wait:
> > comm=python pid=873 delay=4010205 [ns]
> >   python   874 [002] 3273334.936250: probe:hrtick_start: (ffffffff8109f4f0)
> >   python   874 [002] 3273334.936251: sched:sched_switch:
> > prev_comm=python prev_pid=874 prev_prio=120 prev_state=R ==>
> > next_comm=python next_pid=873 next_prio=120
> >
> >
> > Please advise, is this a bug?
> >
>
> Could you cat /sys/kernel/debug/sched_features?

Here it goes:

$ sudo cat /sys/kernel/debug/sched_features | xargs -n 1 echo
GENTLE_FAIR_SLEEPERS
START_DEBIT
NO_NEXT_BUDDY
LAST_BUDDY
CACHE_HOT_BUDDY
WAKEUP_PREEMPTION
ARCH_CAPACITY
HRTICK
NO_DOUBLE_TICK
LB_BIAS
NONTASK_CAPACITY
TTWU_QUEUE
RT_PUSH_IPI
NO_FORCE_SD_OVERLAP
RT_RUNTIME_SHARE
NO_LB_MIN
NUMA
NUMA_FAVOUR_HIGHER
NO_NUMA_RESIST_LOWER