11/2(土) 〜11/4(月) 二泊三日の松本旅行の2日目
松本から安曇野〜木崎湖〜白馬まで走った. 後半は天気が崩れてしまった
ちょいと消化不良だったので、来年またリベンジだな
走行距離 79km 獲得標高 977m
続きを読むstrace を使う際に -c をつけると、システムコール呼び出しの統計を取れる
vagrant@xenial:~$ strace -c find >/dev/null % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 47.43 0.033697 145 232 getdents 46.00 0.032676 141 232 newfstatat 6.08 0.004320 9 474 close 0.49 0.000349 0 1045 fcntl 0.00 0.000000 0 10 read 0.00 0.000000 0 4 write 0.00 0.000000 0 15 4 open 0.00 0.000000 0 129 fstat 0.00 0.000000 0 21 mmap 0.00 0.000000 0 14 mprotect 0.00 0.000000 0 1 munmap 0.00 0.000000 0 3 brk 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 3 2 ioctl 0.00 0.000000 0 8 8 access 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 uname 0.00 0.000000 0 1 fchdir 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 2 2 statfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 118 openat 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.071042 2321 16 total
-c が計上するのは system time だと man に書いてあります
-c Count time, calls, and errors for each system call and report a summary on program exit. On Linux, this attempts to show system time (CPU time spent running in the kernel) inde‐ pendent of wall clock time. If -c is used with -f or -F (below), only aggregate totals for all traced processes are kept.
strace -c と一緒に -w をつけると「システムコール呼び出しにかかった時間を計測できる」
-w Summarise the time difference between the beginning and end of each system call. The default is to summarise the system time.
-w
を付けた場合にどう変化がでるかは sleep 1
を strace して nanosleep(2) を見ると理解が早い
vagrant@xenial:~$ strace -c -w sleep 1 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 99.76 1.042157 1042157 1 nanosleep 👈 0.05 0.000525 66 8 mmap 0.04 0.000419 419 1 execve 0.03 0.000327 109 3 brk 0.02 0.000251 63 4 mprotect 0.02 0.000219 73 3 open 0.02 0.000211 70 3 fstat 0.02 0.000200 67 3 3 access 0.02 0.000190 38 5 close 0.01 0.000064 64 1 read 0.01 0.000062 62 1 arch_prctl 0.00 0.000050 50 1 munmap ------ ----------- ----------- --------- --------- ---------------- 100.00 1.044675 34 3 total
-w
を外した場合
vagrant@xenial:~$ strace -c sleep 1 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 1 read 0.00 0.000000 0 3 open 0.00 0.000000 0 5 close 0.00 0.000000 0 3 fstat 0.00 0.000000 0 8 mmap 0.00 0.000000 0 4 mprotect 0.00 0.000000 0 1 munmap 0.00 0.000000 0 3 brk 0.00 0.000000 0 3 3 access 0.00 0.000000 0 1 nanosleep 👈 0.00 0.000000 0 1 execve 0.00 0.000000 0 1 arch_prctl ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 34 3 total
ね? ブロックする時間が長いシステムコール呼び出しを追いかける際に便利そう
-w オプションが実装されたのは下記のコミットで、 4.9 でリリースされたようだ
ざっくり調べただけなので詳細は書けないのだが ...
-w 付けた場合は clock_gettime(2) + CLOCK_MONOTONIC でシステムコールを開始した時間を記録し計測しているらしい
void syscall_entering_finish(struct tcb *tcp, int res) { ... /* Measure the entrance time as late as possible to avoid errors. */ if ((Tflag || cflag) && !filtered(tcp)) clock_gettime(CLOCK_MONOTONIC, &tcp->etime); 👈
-w をつけない場合の system time は、どうやら wait4(2) の第三引数 struct rusage *rusage
を通して取っているらしい
static const struct tcb_wait_data * next_event(void) { ... next_event_wait_next: pid = wait4(-1, &status, __WALL | WNOHANG, (cflag ? &ru : NULL)); wait_errno = errno; wait_nohang = true;
-c
が出す時間が system time だということを長らくちゃんと理解せずに使っていた-c
は、ペパボ だと pyama くんがバキバキ使い倒しているCentOS6 は 4.8 でまだ使えなかったみたいだが、 CentOS7 では 4.12 なので使えたはず. が、 長らく気がつかずに過ごしてしまった。これ知ってれば解決に導けたm問題も多かったろうなぁ ... という感想
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() を呼び出す
/* * PSI tracks state that persists across sleeps, such as iowaits and * memory stalls. As a result, it has to distinguish between sleeps, * where a task's runnable state changes, and requeues, where a task * and its state are being moved between CPUs and runqueues. */ 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; 👈 /* * Periodic aggregation shuts off if there is a period of no * task changes, so we wake it back up if necessary. However, * don't do this if the task change is the aggregation worker * itself going to sleep, or we'll ping-pong forever. */ 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 は以下の 5つ です
タスクがこれらの API を介してスケジューリングされると /proc/pressure/io
の数値に計上される
/* * This task is about to go to sleep on IO. Increment rq->nr_iowait so * that process accounting knows that this is a task in IO wait state. */ 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);
/** * mutex_lock_io() - Acquire the mutex and mark the process as waiting for I/O * @lock: The mutex to be acquired. * * Lock the mutex like mutex_lock(). While the task is waiting for this * mutex, it will be accounted as being in the IO wait state by the * scheduler. * * Context: Process context. */ 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
の値が実際に変化するのかどうかを実験した
拙作のカーネルモジュールを 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 # io_schedule_timeout() で 10秒間ブロックする
同時に /proc/pressure/io
を観測する
# /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
ふむふむ なるほど〜
mutex_lock_io() を使った場合も同様に試験できます
io_schedule_timeout() とは違って 「mutex_lock_io() で mutex を獲得しているタスクではなく、mutex_lock_io() でブロックしているタスク」 が PSI で計上されるので要注意です
実験の際には 2つ以上の sysctl -w プロセスを起動して実験します
root@bionic:~# sysctl -w mutex_lock_io_stuck=10 & # 1個目のタスクは mutex_lock_io で mutex を獲得し 10秒間 sleep する root@bionic:~# sysctl -w mutex_lock_io_stuck=10 # 2個目のタスクは 1個目のタスクによって約 10秒間ブロックされる
リアルな環境では、mutex_lock_io() でロック待ちになっている状況が /proc/pressure/io
で観測できるということですね
実験2 で得られる結果は、実験1 とほぼ同等なので割愛します
/proc/pressure/io
がどのように計測されるかをざっくり追ったcgroup v1 の memory コントローラーで memory.kmem.limit_in_bytes
を制限すると slab_out_of_memory を起こすことができるので、それを調べたり観察したエントリです
不具合・バグの調査ではないです
ソースやコマンドの結果を大量に貼り付けているので めんどうな人は流し読みしてください
vagrant@bionic:~$ uname -a Linux bionic 4.15.0-66-generic #75-Ubuntu SMP Tue Oct 1 05:24:09 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
root@bionic:~# echo $$ > /sys/fs/cgroup/memory/000/tasks root@bionic:~# echo 100M > /sys/fs/cgroup/memory/000/memory.kmem.limit_in_bytes
memory.kmem.limit_in_bytes に制限を課したプロセスで、存在しないパスに stat(2) を呼び出しをして negative dentry (slab) を大量に生成します
# # https://hiboma.hatenadiary.jp/entry/20140212/1392131530 # root@bionic:~# perl -e 'stat "/$_" for 1..10000000' ^C続きを読む
表題の通りなのだが、結論からいうと sysrq-trigger を使うのがいいみたい
「特定のタスクがクリティカルセクションを実行していてボトルネックとなっているが、どのタスクなのか分からない」という事象を正確に観測したくて、このテーマで調べました
まず実験用にカーネルモジュールをこしらえた
debugfs 上のファイルを read(2) したタスクが spinlock を掴んだまま無限ループに突入する、という単にバグってるカーネルモジュールになる. これでカーネルモードで刺さっているタスクを擬似的に再現する
上記のカーネルモジュールをインストールすると /sys/kernel/debug/foreverspin
が生えるので、これを cat する
vagrant@bionic:/ $ sudo cat /sys/kernel/debug/foreverspin
cat プロセスがカーネルモードで CPU を掴みっぱなしになり、 %system CPU がグンっと上がる
このプロセスを観察してみましょう
この状態で /proc/$pid/stack
を見ても バックトレースは採取できない
vagrant@bionic:/ $ sudo cat /proc/$( pgrep cat )/stack [<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [<0>] 0xffffffffffffffff
無念!!!1
strace でトレースしても何もトレースできないし、Ctrl + C による SIGINT シグナルもブロックされる ( これはシステムコール実行中にシグナルをブロックするという strace の挙動かな ? )
vagrant@bionic:/ $ sudo strace -p $(pgrep cat) strace: Process 2182 attached ^C^C^C
システムコール呼んでないですしね。何にもとれないですよね。ユーザランドのトレースツールだもんね
無念!!!
sysrq-trigger でバックトレースを採取する. wikipedia にちょうどいい解説が載っています
設定を有効にして
root@bionic:~# sysctl kernel.sysrq=1 kernel.sysrq = 1
えいっ
root@bionic:~# echo l > /proc/sysrq-trigger
dmesg に以下のようなログが出るはずです
[Thu Nov 7 08:15:34 2019] sysrq: SysRq : Show backtrace of all active CPUs [Thu Nov 7 08:15:34 2019] NMI backtrace for cpu 3 [Thu Nov 7 08:15:34 2019] CPU: 3 PID: 1846 Comm: bash Tainted: G OE 4.15.0-29-generic #31-Ubuntu [Thu Nov 7 08:15:34 2019] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [Thu Nov 7 08:15:34 2019] Call Trace: [Thu Nov 7 08:15:34 2019] dump_stack+0x63/0x8b [Thu Nov 7 08:15:34 2019] nmi_cpu_backtrace+0xca/0xd0 [Thu Nov 7 08:15:34 2019] ? lapic_can_unplug_cpu+0xb0/0xb0 [Thu Nov 7 08:15:34 2019] nmi_trigger_cpumask_backtrace+0xe6/0x130 [Thu Nov 7 08:15:34 2019] arch_trigger_cpumask_backtrace+0x19/0x20 [Thu Nov 7 08:15:34 2019] sysrq_handle_showallcpus+0x17/0x20 [Thu Nov 7 08:15:34 2019] __handle_sysrq+0x9f/0x170 [Thu Nov 7 08:15:34 2019] write_sysrq_trigger+0x34/0x40 [Thu Nov 7 08:15:34 2019] proc_reg_write+0x45/0x70 [Thu Nov 7 08:15:34 2019] __vfs_write+0x1b/0x40 [Thu Nov 7 08:15:34 2019] vfs_write+0xb1/0x1a0 [Thu Nov 7 08:15:34 2019] SyS_write+0x55/0xc0 [Thu Nov 7 08:15:34 2019] do_syscall_64+0x73/0x130 [Thu Nov 7 08:15:34 2019] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 [Thu Nov 7 08:15:34 2019] RIP: 0033:0x7f14c47b7154 [Thu Nov 7 08:15:34 2019] RSP: 002b:00007ffffe191ff8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 [Thu Nov 7 08:15:34 2019] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f14c47b7154 [Thu Nov 7 08:15:34 2019] RDX: 0000000000000002 RSI: 0000558e776dc940 RDI: 0000000000000001 [Thu Nov 7 08:15:34 2019] RBP: 0000558e776dc940 R08: 000000000000000a R09: 0000000000000001 [Thu Nov 7 08:15:34 2019] R10: 000000000000000a R11: 0000000000000246 R12: 00007f14c4a93760 [Thu Nov 7 08:15:34 2019] R13: 0000000000000002 R14: 00007f14c4a8f2a0 R15: 00007f14c4a8e760 [Thu Nov 7 08:15:34 2019] Sending NMI from CPU 3 to CPUs 0-2: [Thu Nov 7 08:15:34 2019] NMI backtrace for cpu 0 [Thu Nov 7 08:15:34 2019] CPU: 0 PID: 1872 Comm: cat Tainted: G OE 4.15.0-29-generic #31-Ubuntu [Thu Nov 7 08:15:34 2019] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006 [Thu Nov 7 08:15:34 2019] RIP: 🔥 0010:debugfs_foreverspin_read+0x15/0x17 [foreverspin] [Thu Nov 7 08:15:34 2019] RSP: 0018:ffffa7b9c11ffe58 EFLAGS: 00000246 [Thu Nov 7 08:15:34 2019] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffa7b9c11ffef8 [Thu Nov 7 08:15:34 2019] RDX: 0000000000000001 RSI: 00007efc03883000 RDI: ffffffffc0948448 [Thu Nov 7 08:15:34 2019] RBP: ffffa7b9c11ffe58 R08: ffff92d344a69100 R09: 0000000000000000 [Thu Nov 7 08:15:34 2019] R10: 0000000000000000 R11: 0000000000000000 R12: ffff92d346ca2f00 [Thu Nov 7 08:15:34 2019] R13: ffff92d34351f100 R14: 0000000000020000 R15: ffffa7b9c11ffef8 [Thu Nov 7 08:15:34 2019] FS: 00007efc038a5540(0000) GS:ffff92d353c00000(0000) knlGS:0000000000000000 [Thu Nov 7 08:15:34 2019] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [Thu Nov 7 08:15:34 2019] CR2: 00007efc03882000 CR3: 0000000207b3a006 CR4: 00000000000606f0 [Thu Nov 7 08:15:34 2019] Call Trace: [Thu Nov 7 08:15:34 2019] full_proxy_read+0x5c/0x90 👈 [Thu Nov 7 08:15:34 2019] __vfs_read+0x1b/0x40 👈 [Thu Nov 7 08:15:34 2019] vfs_read+0x8e/0x130 👈 [Thu Nov 7 08:15:34 2019] SyS_read+0x55/0xc0 👈 [Thu Nov 7 08:15:34 2019] do_syscall_64+0x73/0x130 👈 [Thu Nov 7 08:15:34 2019] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 👈 [Thu Nov 7 08:15:34 2019] RIP: 0033:0x7efc033aa081 [Thu Nov 7 08:15:34 2019] RSP: 002b:00007ffdd251fe78 EFLAGS: 00000246 ORIG_RAX: 0000000000000000 [Thu Nov 7 08:15:34 2019] RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007efc033aa081 [Thu Nov 7 08:15:34 2019] RDX: 0000000000020000 RSI: 00007efc03883000 RDI: 0000000000000003 [Thu Nov 7 08:15:34 2019] RBP: 0000000000020000 R08: 00000000ffffffff R09: 0000000000000000 [Thu Nov 7 08:15:34 2019] R10: 0000000000000022 R11: 0000000000000246 R12: 00007efc03883000 [Thu Nov 7 08:15:34 2019] R13: 0000000000000003 R14: 00007efc0388300f R15: 0000000000020000 [Thu Nov 7 08:15:34 2019] Code: <eb> fe 55 48 8b 3d 21 24 00 00 48 89 e5 e8 69 ce 05 dd 5d c3 00 00 [Thu Nov 7 08:15:34 2019] NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0x6/0x10 [Thu Nov 7 08:15:34 2019] NMI backtrace for cpu 2 skipped: idling at native_safe_halt+0x6/0x10
👈 で確認できますね! やったー
前回の続き
rtnl_mutex でロックを獲得してクリティカルセクションを実行中のタスクを何らかの方法でトレースしたり、時間を計測したいと思って、あれこれ調べたり、試行錯誤していた
最終的に bpftrace でがちゃがちゃと試すまでを記していく
続きを読む