www.kernel.org
Linux Kernel 4.20 で導入された PSI - Pressure Stall Information の /proc/pressure/io について気になることがあったので調べていました
イントロダクション
PSI を使うと CPU, メモリ, IO で stall した時間(割合) を計測できるってなことですが、どういった実装で「IO 待ち」なタスクを計測しているのかかが疑問で、社内で udzula さんあれこれ話を聞いていたのでした
ソースを読む
io_schedule_prepare() という関数を呼び出す際に current->in_iowait = 1 をセットしていて、これがポイント
int io_schedule_prepare(void)
{
int old_iowait = current->in_iowait;
current->in_iowait = 1; 👈
blk_schedule_flush_plug(current);
return old_iowait;
}
io_schedule_prepare() がどこで呼びだしされるかが重要で、後述する
current->in_iowait = 1 なタスクは psi_enqueue() で TSK_IOWAIT を付けて、psi_task_change() を呼び出す
static inline void psi_enqueue(struct task_struct *p, bool wakeup)
{
int clear = 0, set = TSK_RUNNING;
if (static_branch_likely(&psi_disabled))
return;
if (!wakeup || p->sched_psi_wake_requeue) {
if (p->flags & PF_MEMSTALL)
set |= TSK_MEMSTALL;
if (p->sched_psi_wake_requeue)
p->sched_psi_wake_requeue = 0;
} else {
if (p->in_iowait)
clear |= TSK_IOWAIT; 👈
}
psi_task_change(p, clear, set); 👈
}
psi_enqueue() は スケジューラたタスクをランキューにキューイングする際に呼び出す
更に psi_task_change() の中で task->psi_flags をセットしており、schedule_delayed_work() で非同期に PSI の統計を更新し反映する仕組みになっている
void psi_task_change(struct task_struct *task, int clear, int set)
{
int cpu = task_cpu(task);
struct psi_group *group;
bool wake_clock = true;
void *iter = NULL;
if (!task->pid)
return;
if (((task->psi_flags & set) ||
(task->psi_flags & clear) != clear) &&
!psi_bug) {
printk_deferred(KERN_ERR "psi: inconsistent task state! task=%d:%s cpu=%d psi_flags=%x clear=%x set=%x\n",
task->pid, task->comm, cpu,
task->psi_flags, clear, set);
psi_bug = 1;
}
task->psi_flags &= ~clear; 👈
task->psi_flags |= set; 👈
if (unlikely((clear & TSK_RUNNING) &&
(task->flags & PF_WQ_WORKER) &&
wq_worker_last_func(task) == psi_update_work))
wake_clock = false;
while ((group = iterate_groups(task, &iter))) {
psi_group_change(group, cpu, clear, set);
if (wake_clock && !delayed_work_pending(&group->clock_work))
schedule_delayed_work(&group->clock_work, PSI_FREQ); 👈
}
}
細かいところをはしょりまくっているが、こんな感じでソースを追っていって理解を深めた
io_schedule_prepare を呼ぶ API は?
io_schedule_prepare() を呼び出す API は以下の 5つ です
- io_schedule_timeout()
- io_schedule()
- mutex_lock_io()
- mutex_lock_io_nested()
- blkcg_maybe_throttle_blkg()
タスクがこれらの API を介してスケジューリングされると /proc/pressure/io の数値に計上される
long __sched io_schedule_timeout(long timeout)
{
int token;
long ret;
token = io_schedule_prepare(); 👈
ret = schedule_timeout(timeout);
io_schedule_finish(token);
return ret;
}
EXPORT_SYMBOL(io_schedule_timeout);
void io_schedule(void)
{
int token;
token = io_schedule_prepare(); 👈
schedule();
io_schedule_finish(token);
}
EXPORT_SYMBOL(io_schedule);
void __sched mutex_lock_io(struct mutex *lock)
{
int token;
token = io_schedule_prepare(); 👈
mutex_lock(lock);
io_schedule_finish(token);
}
EXPORT_SYMBOL_GPL(mutex_lock_io);
void __sched
mutex_lock_io_nested(struct mutex *lock, unsigned int subclass)
{
int token;
might_sleep();
token = io_schedule_prepare(); 👈
__mutex_lock_common(lock, TASK_UNINTERRUPTIBLE,
subclass, NULL, _RET_IP_, NULL, 0);
io_schedule_finish(token);
}
EXPORT_SYMBOL_GPL(mutex_lock_io_nested);
blkcg_maybe_throttle_blkg() はちょいと長いので割愛する
実験する
さて API がわかったのでカーネルモジュールを書いて実験する
まず io_schedule_timeout() と mutex_lock_io() を呼び出すカーネルモジュールを作り、これを用いて PSI - /proc/pressure/io の値が実際に変化するのかどうかを実験した
github.com
実験1: io_schedule_timeout() を使って観測する
拙作のカーネルモジュールを insmod すると、io_schedule_stuck という sysctl インタフェースが生える.
$ find /proc/sys | grep io_schedule_stuck
/proc/sys/io_schedule_stuck
このインタフェースに sysctl -w したタスクは任意の秒数間 io_schedule_timeout() で待つ (TASK_UNINTERRUPTIBLE でブロック)
root@bionic:~# sysctl -w io_schedule_stuck=10
同時に /proc/pressure/io を観測する
vagrant@bionic:~$ for i in {1..100}; do cat /proc/pressure/io | perl -nle 'printf "%s\t%s\n", scalar localtime(), $_'; sleep 1; done;
Tue Nov 12 14:53:22 2019 some avg10=0.00 avg60=2.74 avg300=2.36 total=364406988
Tue Nov 12 14:53:22 2019 full avg10=0.00 avg60=2.73 avg300=2.36 total=361087398
Tue Nov 12 14:53:23 2019 some avg10=0.00 avg60=2.74 avg300=2.36 total=364406988
Tue Nov 12 14:53:23 2019 full avg10=0.00 avg60=2.73 avg300=2.36 total=361087398
Tue Nov 12 14:53:24 2019 some avg10=0.00 avg60=2.65 avg300=2.34 total=364556987
Tue Nov 12 14:53:24 2019 full avg10=0.00 avg60=2.64 avg300=2.34 total=361236378
Tue Nov 12 14:53:25 2019 some avg10=0.00 avg60=2.65 avg300=2.34 total=365570489
Tue Nov 12 14:53:25 2019 full avg10=0.00 avg60=2.64 avg300=2.34 total=362246601
🔥 ここで sysctl -w なプロセスをスタートしていて、計上され始める
Tue Nov 12 14:53:26 2019 some avg10=13.76 avg60=5.05 avg300=2.85 total=366562074
Tue Nov 12 14:53:26 2019 full avg10=13.76 avg60=5.04 avg300=2.84 total=363236425
Tue Nov 12 14:53:27 2019 some avg10=13.76 avg60=5.05 avg300=2.85 total=367568565
Tue Nov 12 14:53:27 2019 full avg10=13.76 avg60=5.04 avg300=2.84 total=364240573
Tue Nov 12 14:53:28 2019 some avg10=29.02 avg60=8.09 avg300=3.50 total=368575956
Tue Nov 12 14:53:28 2019 full avg10=29.02 avg60=8.08 avg300=3.49 total=365246678
Tue Nov 12 14:53:29 2019 some avg10=29.02 avg60=8.09 avg300=3.50 total=369581289
Tue Nov 12 14:53:29 2019 full avg10=29.02 avg60=8.08 avg300=3.49 total=366249360
Tue Nov 12 14:53:30 2019 some avg10=41.70 avg60=11.06 avg300=4.15 total=370587139
Tue Nov 12 14:53:30 2019 full avg10=41.70 avg60=11.06 avg300=4.15 total=367253197
Tue Nov 12 14:53:31 2019 some avg10=52.08 avg60=13.94 avg300=4.80 total=371697728
Tue Nov 12 14:53:31 2019 full avg10=52.08 avg60=13.94 avg300=4.80 total=368361911
Tue Nov 12 14:53:32 2019 some avg10=52.08 avg60=13.94 avg300=4.80 total=372717875
Tue Nov 12 14:53:32 2019 full avg10=52.08 avg60=13.94 avg300=4.80 total=369380596
Tue Nov 12 14:53:33 2019 some avg10=60.40 avg60=16.69 avg300=5.44 total=373724431
Tue Nov 12 14:53:33 2019 full avg10=60.40 avg60=16.69 avg300=5.43 total=370385496
Tue Nov 12 14:53:34 2019 some avg10=60.40 avg60=16.69 avg300=5.44 total=374375911
Tue Nov 12 14:53:34 2019 full avg10=60.40 avg60=16.69 avg300=5.43 total=371036282
Tue Nov 12 14:53:35 2019 some avg10=56.52 avg60=17.42 avg300=5.67 total=374375911
Tue Nov 12 14:53:35 2019 full avg10=56.52 avg60=17.42 avg300=5.66 total=371036282
Tue Nov 12 14:53:36 2019 some avg10=56.52 avg60=17.42 avg300=5.67 total=374375911
Tue Nov 12 14:53:36 2019 full avg10=56.52 avg60=17.42 avg300=5.66 total=371036282
🔥 ここで sysctl -w のプロセスが終わっていて、avg の数値が減り始める
Tue Nov 12 14:53:37 2019 some avg10=46.28 avg60=16.85 avg300=5.63 total=374375911
Tue Nov 12 14:53:37 2019 full avg10=46.28 avg60=16.85 avg300=5.62 total=371036282
Tue Nov 12 14:53:38 2019 some avg10=46.28 avg60=16.85 avg300=5.63 total=374375911
Tue Nov 12 14:53:38 2019 full avg10=46.28 avg60=16.85 avg300=5.62 total=371036282
Tue Nov 12 14:53:39 2019 some avg10=37.89 avg60=16.30 avg300=5.59 total=374375911
Tue Nov 12 14:53:39 2019 full avg10=37.89 avg60=16.29 avg300=5.59 total=371036282
Tue Nov 12 14:53:40 2019 some avg10=37.89 avg60=16.30 avg300=5.59 total=374375911
Tue Nov 12 14:53:40 2019 full avg10=37.89 avg60=16.29 avg300=5.59 total=371036282
Tue Nov 12 14:53:41 2019 some avg10=31.03 avg60=15.76 avg300=5.55 total=374375911
Tue Nov 12 14:53:41 2019 full avg10=31.03 avg60=15.76 avg300=5.55 total=371036282
Tue Nov 12 14:53:42 2019 some avg10=31.03 avg60=15.76 avg300=5.55 total=374375911
Tue Nov 12 14:53:42 2019 full avg10=31.03 avg60=15.76 avg300=5.55 total=371036282
Tue Nov 12 14:53:43 2019 some avg10=25.41 avg60=15.25 avg300=5.51 total=374375911
Tue Nov 12 14:53:43 2019 full avg10=25.41 avg60=15.24 avg300=5.51 total=371036282
Tue Nov 12 14:53:44 2019 some avg10=25.41 avg60=15.25 avg300=5.51 total=374375911
Tue Nov 12 14:53:44 2019 full avg10=25.41 avg60=15.24 avg300=5.51 total=371036282
ふむふむ なるほど〜
実験2: mutex_lock_io() を使って PSI を観測する
mutex_lock_io() を使った場合も同様に試験できます
io_schedule_timeout() とは違って 「mutex_lock_io() で mutex を獲得しているタスクではなく、mutex_lock_io() でブロックしているタスク」 が PSI で計上されるので要注意です
実験の際には ２つ以上の sysctl -w プロセスを起動して実験します
root@bionic:~# sysctl -w mutex_lock_io_stuck=10 &
root@bionic:~# sysctl -w mutex_lock_io_stuck=10
リアルな環境では、mutex_lock_io() でロック待ちになっている状況が /proc/pressure/io で観測できるということですね
実験2 で得られる結果は、実験1 とほぼ同等なので割愛します
まとめ
- ソースを追って
/proc/pressure/io がどのように計測されるかをざっくり追った
- 自分でコントロール化においた環境で実験すると 理解が捗る
