Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1395950 > unrolled thread

PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled

Started byTomasz Grabiec <tgrabiec@scylladb.com>
First post2016-05-06 17:50 +0200
Last post2016-05-11 03:00 +0200
Articles 5 — 2 participants

Back to article view | Back to linux.kernel

Contents

  PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled Tomasz Grabiec <tgrabiec@scylladb.com> - 2016-05-06 17:50 +0200
    Re: PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled Wanpeng Li <kernellwp@gmail.com> - 2016-05-08 02:20 +0200
      Re: PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled Tomasz Grabiec <tgrabiec@scylladb.com> - 2016-05-09 11:00 +0200
    Re: PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled Wanpeng Li <kernellwp@gmail.com> - 2016-05-11 03:00 +0200
    Re: PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled Wanpeng Li <kernellwp@gmail.com> - 2016-05-11 03:00 +0200

#1395950 — PROBLEM: Scheduling latency not respected in CFS with HRTICK enabled

FromTomasz Grabiec <tgrabiec@scylladb.com>
Date2016-05-06 17:50 +0200
SubjectPROBLEM: Scheduling latency not respected in CFS with HRTICK enabled
Message-ID<rvQaT-7UW-9@gated-at.bofh.it>
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

[toc] | [next] | [standalone]

#1396370

FromWanpeng Li <kernellwp@gmail.com>
Date2016-05-08 02:20 +0200
Message-ID<rwkBX-3ak-5@gated-at.bofh.it>
In reply to#1395950
2016-05-06 23:43 GMT+08:00 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?
>

Could you cat /sys/kernel/debug/sched_features?

Regards,
Wanpeng Li

[toc] | [prev] | [next] | [standalone]

#1396864

FromTomasz Grabiec <tgrabiec@scylladb.com>
Date2016-05-09 11:00 +0200
Message-ID<rwPcL-1Kc-23@gated-at.bofh.it>
In reply to#1396370
On Sun, May 8, 2016 at 2:19 AM, Wanpeng Li <kernellwp@gmail.com> wrote:
>
> 2016-05-06 23:43 GMT+08:00 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?
> >
>
> 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

[toc] | [prev] | [next] | [standalone]

#1398618

FromWanpeng Li <kernellwp@gmail.com>
Date2016-05-11 03:00 +0200
Message-ID<rxqFj-5B4-1@gated-at.bofh.it>
In reply to#1395950
2016-05-11 8:53 GMT+08:00 Wanpeng Li <kernellwp@gmail.com>:
> 2016-05-06 23:43 GMT+08:00 Tomasz Grabiec <tgrabiec@scylladb.com>:
> [...]
>> 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]
>
> hrtick fire after almost 0.5ms(the time slice process 874 get).
>
>>   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]
>
> continue to run another 3.4ms until next normal scheduler tick fire.
>
>>   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
>
> So the process 874 continue to run util next scheduler fick event if

s/fick event if/tick even if

[toc] | [prev] | [next] | [standalone]

#1398620

FromWanpeng Li <kernellwp@gmail.com>
Date2016-05-11 03:00 +0200
Message-ID<rxqFj-5B4-3@gated-at.bofh.it>
In reply to#1395950
2016-05-06 23:43 GMT+08:00 Tomasz Grabiec <tgrabiec@scylladb.com>:
[...]
> 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]

hrtick fire after almost 0.5ms(the time slice process 874 get).

>   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]

continue to run another 3.4ms until next normal scheduler tick fire.

>   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

So the process 874 continue to run util next scheduler fick event if
hrtick has already fired. I think Peterz can give any light.

Ping Peterz :-)

Regards,
Wanpeng Li

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web