PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled

[Tomasz Grabiec <tgrabiec@scylladb.com>]

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?

Regards,
Tomasz Grabiec