strace -c を使う際に -w オプションを使い分けよう

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.

-w を一緒につける

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 でリリースされたようだ

github.com

strace.io

時間の計測方法

ざっくり調べただけなので詳細は書けないのだが ...

-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 だということを長らくちゃんと理解せずに使っていた
  • 直面している問題に合わせて -w を付けたり外したりして、観測/計測していくとよいだろう
  • ところで -c は、ペパボ だと pyama くんがバキバキ使い倒している

CentOS6 は 4.8 でまだ使えなかったみたいだが、 CentOS7 では 4.12 なので使えたはず. が、 長らく気がつかずに過ごしてしまった。これ知ってれば解決に導けたm問題も多かったろうなぁ ... という感想

Linux Kernel: PSI - Pressure Stall Information /proc/pressure/io で IO 待ちを観察する

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() を呼び出す

/*
 * 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 は?

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 の数値に計上される

/*
 * 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 の値が実際に変化するのかどうかを実験した

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

ふむふむ なるほど〜

実験2: mutex_lock_io() を使って PSI を観測する

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 がどのように計測されるかをざっくり追った
  • 自分でコントロール化においた環境で実験すると 理解が捗る

Linux Kernel: cgroup v1 の制限下で slab_out_of_memory を発生させて観察する

イントロダクション

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

再現

1. cgroup v1 で memory.kmem.limit_in_bytes だけ制限を課します

root@bionic:~# echo $$   > /sys/fs/cgroup/memory/000/tasks 
root@bionic:~# echo 100M > /sys/fs/cgroup/memory/000/memory.kmem.limit_in_bytes 

2. negative dentry (slab) を大量に生成する

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
続きを読む

Linux Kernel: カーネルモードで CPU 掴んでるタスクのバックトレースをとりたい

表題の通りなのだが、結論からいうと sysrq-trigger を使うのがいいみたい

「特定のタスクがクリティカルセクションを実行していてボトルネックとなっているが、どのタスクなのか分からない」という事象を正確に観測したくて、このテーマで調べました

カーネルモードで CPU 掴んでるタスクを作る

まず実験用にカーネルモジュールをこしらえた

github.com

debugfs 上のファイルを read(2) したタスクが spinlock を掴んだまま無限ループに突入する、という単にバグってるカーネルモジュールになる. これでカーネルモードで刺さっているタスクを擬似的に再現する

実験

上記のカーネルモジュールをインストールすると /sys/kernel/debug/foreverspin が生えるので、これを cat する

vagrant@bionic:/ $ sudo cat /sys/kernel/debug/foreverspin

cat プロセスがカーネルモードで CPU を掴みっぱなしになり、 %system CPU がグンっと上がる

f:id:hiboma:20191108124701p:plain

このプロセスを観察してみましょう

/proc/$pid/stack を見てみる

この状態で /proc/$pid/stack を見ても バックトレースは採取できない

vagrant@bionic:/ $ sudo cat /proc/$( pgrep cat )/stack
[<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[<0>] 0xffffffffffffffff

無念!!!1

strace

strace でトレースしても何もトレースできないし、Ctrl + C による SIGINT シグナルもブロックされる ( これはシステムコール実行中にシグナルをブロックするという strace の挙動かな ? )

vagrant@bionic:/ $ sudo strace -p $(pgrep cat)
strace: Process 2182 attached
^C^C^C

システムコール呼んでないですしね。何にもとれないですよね。ユーザランドのトレースツールだもんね

無念!!!

echo l > /proc/sysrq-trigger

sysrq-trigger でバックトレースを採取する. wikipedia にちょうどいい解説が載っています

ja.wikipedia.org

設定を有効にして

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

👈 で確認できますね! やったー

まとめ

  • Proof of Cocenprt は達成できたかな
  • リアルな障害の調査に役立てたい
  • どうも NMI で割り込んでバックとレースを取っているっぽいけど、どういう仕組みなのかはまた別の機会に調べます

Linux Kernel: rtnl_mutex を長時間 ロックして刺さった状態を観察する (2) with bpftrace

前回の続き

hiboma.hatenadiary.jp

rtnl_mutex でロックを獲得してクリティカルセクションを実行中のタスクを何らかの方法でトレースしたり、時間を計測したいと思って、あれこれ調べたり、試行錯誤していた

最終的に bpftrace でがちゃがちゃと試すまでを記していく

続きを読む

八ヶ岳〜清里〜野辺山〜軽井沢 🚴‍♀️

ちょっと前に書いて出し忘れていた 10月5日(土) の記録

f:id:hiboma:20191014231327p:plain

甲府八ヶ岳清里〜野辺山〜軽井沢のコースを走った. 今年の5月にも同じ場所を走ったのだが途中のコースをかえて楽しんだ

hiboma.hatenadiary.jp

台風でたいへんなことになった千曲川沿いも走ってたんだな ....

走行距離 121km 獲得標高1462m

続きを読む