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日(土) の記録

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

hiboma.hatenadiary.jp

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

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

続きを読む

strace 5.2 で追加された -z -Z オプション

strace.io

strace 5.2 で追加された -z -Z オプションが面白かったので書いておきます (注意: この記事を書いた時点では 5.3 が最新です )

-Z

失敗したシステムコールだけフィルターしてくれるオプション

root@xenial:~/strace-5.3# ./strace -Z ls >/dev/null
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
statfs("/sys/fs/selinux", 0x7ffe56406c30) = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7ffe56406c30)      = -1 ENOENT (No such file or directory)
ioctl(1, TCGETS, 0x7ffe56406890)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(1, TIOCGWINSZ, 0x7ffe56406950)    = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(1, TCGETS, 0x7ffe56404350)        = -1 ENOTTY (Inappropriate ioctl for device)
+++ exited with 0 +++

膨大なシステムコールの中から失敗したものだけに着目したいというユースケースはよくあるので、便利そうです

-z

成功したシステムコールだけフィルターしてくれるオプション. でも通常の実行と区別がつきにくいかな?

root@xenial:~/strace-5.3# ./strace -z ls >/dev/null
execve("/bin/ls", ["ls"], 0x7ffcc2dff938 /* 17 vars */) = 0
brk(NULL)                               = 0x161e000
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=46096, ...}) = 0
mmap(NULL, 46096, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7723d73000
close(3)                                = 0
open("/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260Z\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=130224, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7723d72000
mmap(NULL, 2234080, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7723938000
mprotect(0x7f7723957000, 2093056, PROT_NONE) = 0
mmap(0x7f7723b56000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e000) = 0x7f7723b56000
mmap(0x7f7723b58000, 5856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7723b58000
close(3)                                = 0

...

失敗したシステムコールが多くて (例: PerlRuby なんかでライブラリを探す際に stat(2), lstat(2) あたり が ENOENT を大量に出す場合など ) ノイズになる場合に使えそう

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

Linux Kernel で struct net_device や Routing Netlink の処理を排他制御する mutex である  rtnl_mutex を任意の時間 ロックするカーネルモジュールを作成して、rtnl_mutex のロックがユーザランドのプロセスやカーネルスレッド等にどういった影響を及ぼすかを観察する

... というエントリです

Linux カーネルの話や、strace, gdb, /proc/$pid/stack を使ったデバッグ方法に興味あるかた向けです

続きを読む

Proof of Concept: Linux カーネルモジュールで特定のディレクトリ以下の dentry キャッシュを破棄する (2)

hiboma.hatenadiary.jp

前回の続きのエントリです

カーネルのバージョンを変えつつ ソースを読み込んでみたところ理解が進んだ点が2つあったのでまとめます

  1. ファイルシステム(マウントポイント?) を remount すると dentry を破棄できる
  2. evict_inodes() を呼んで inode のキャッシュ を破棄できる

この二点についてまとめます

1. ファイルシステムを remount すると dentry を破棄する

ファイルシステムを remount する際にカーネル内で reconfigure_super() (古いカーネルでは do_remount_sb() ) を呼び出すが、その中で shrink_dcache_sb() を呼び出して dcache を破棄する処理が入っているのを確認した

/**
 * reconfigure_super - asks filesystem to change superblock parameters
 * @fc: The superblock and configuration
 *
 * Alters the configuration parameters of a live superblock.
 */
int reconfigure_super(struct fs_context *fc)
{
    struct super_block *sb = fc->root->d_sb;
    int retval;
    bool remount_ro = false;
    bool force = fc->sb_flags & SB_FORCE;

...

    shrink_dcache_sb(sb); 👈

shrink_dcache_sb() の定義は下記のような感じ

/**
 * shrink_dcache_sb - shrink dcache for a superblock
 * @sb: superblock
 *
 * Shrink the dcache for the specified super block. This is used to free
 * the dcache before unmounting a file system.
 */
void shrink_dcache_sb(struct super_block *sb)
{
    do {
        LIST_HEAD(dispose);

        list_lru_walk(&sb->s_dentry_lru,
            dentry_lru_isolate_shrink, &dispose, 1024);
        shrink_dentry_list(&dispose);
    } while (list_lru_count(&sb->s_dentry_lru) > 0);
}
EXPORT_SYMBOL(shrink_dcache_sb);

remount する? それ、役に立つの?

「特定のファイルシステム/マウントポイントの dentry cache を飛ばしたい + mount ポイントが remount できる」 という特殊な条件が揃うようなケースがありえるのかどうか分からないが ... そういう時には使える。

あまり有用でない感じする. 無念

2. evict_inodes() を呼んで VFS inode キャッシュ を破棄する

evict_inodes() という関数で、対象としているファイルシステムの superblock にぶら下がる inode キャッシュを全て破棄(?)できるぽい

/**
 * evict_inodes    - evict all evictable inodes for a superblock
 * @sb:        superblock to operate on
 *
 * Make sure that no inodes with zero refcount are retained.  This is
 * called by superblock shutdown after having SB_ACTIVE flag removed,
 * so any inode reaching zero refcount during or after that call will
 * be immediately evicted.
 */
void evict_inodes(struct super_block *sb)
{
    struct inode *inode, *next;
    LIST_HEAD(dispose);

again:
    spin_lock(&sb->s_inode_list_lock);
    list_for_each_entry_safe(inode, next, &sb->s_inodes, i_sb_list) {
        if (atomic_read(&inode->i_count))
            continue;

        spin_lock(&inode->i_lock);
        if (inode->i_state & (I_NEW | I_FREEING | I_WILL_FREE)) {
            spin_unlock(&inode->i_lock);
            continue;
        }

        inode->i_state |= I_FREEING;
        inode_lru_list_del(inode);
        spin_unlock(&inode->i_lock);
        list_add(&inode->i_lru, &dispose);

        /*
        * We can have a ton of inodes to evict at unmount time given
        * enough memory, check to see if we need to go to sleep for a
        * bit so we don't livelock.
        */
        if (need_resched()) {
            spin_unlock(&sb->s_inode_list_lock);
            cond_resched();
            dispose_list(&dispose);
            goto again;
        }
    }
    spin_unlock(&sb->s_inode_list_lock);

    dispose_list(&dispose);
}
EXPORT_SYMBOL_GPL(evict_inodes);

4.13.3 から EXPORT_SYMBOL_GPL が付いている

lore.kernel.org

4.13.3 からは EXPORT_SYMBOL_GPL が付いているので他のカーネルモジュールからも呼び出し可能な API として再定義されている.

evict_inodes() を呼び出す際の注意

コメントに注意書きが記してある

 * Make sure that no inodes with zero refcount are retained.  This is
 * called by superblock shutdown after having SB_ACTIVE flag removed,
 * so any inode reaching zero refcount during or after that call will
 * be immediately evicted.
 */

呼び出し側が上記の条件を保証する必要があるらしくて、ここの条件の成立のさせ方が正しいのかを確かめるすべがわからない.

evict_inodes() を呼び出すコードに generic_shutdown_super() があるが dirty な inode の処理などは呼び出す側の責務っぽい。書き込みが発生している場合には慎重に扱わないとファイルシステムの不整合を招く感じする

/**
 * generic_shutdown_super  -   common helper for ->kill_sb()
 * @sb: superblock to kill
 *
 * generic_shutdown_super() does all fs-independent work on superblock
 * shutdown.  Typical ->kill_sb() should pick all fs-specific objects
 * that need destruction out of superblock, call generic_shutdown_super()
 * and release aforementioned objects.  Note: dentries and inodes _are_
 * taken care of and do not need specific handling.
 *
 * Upon calling this function, the filesystem may no longer alter or
 * rearrange the set of dentries belonging to this super_block, nor may it
 * change the attachments of dentries to inodes.
 */
void generic_shutdown_super(struct super_block *sb)
{
    const struct super_operations *sop = sb->s_op;

    if (sb->s_root) {
        shrink_dcache_for_umount(sb);
        sync_filesystem(sb);
        sb->s_flags &= ~SB_ACTIVE;

        fsnotify_sb_delete(sb);
        cgroup_writeback_umount();

        evict_inodes(sb); 👈

...

ファイルシステムが readonly ならどうだろ???

今回調べているユースケースで、実は 対象のファイルシステムが実は「readonly でマウントしている」という隠れ条件 があったのでした (後出しジャンケンですいません)


おそらく、ファイルシステムが readonly でマウントされていたら dirty な inode は存在しえないだろうし、 slab キャッシュをばーんと消しても安全に扱えそうなきがする

... ということで readonly なファイルシステムを対象に evict_inodes() をカーネルモジュールから呼び出す Proofe of Conept を書いてみた

github.com

実験

XFS で looopback のファイルシステムを作成して、ディレクトリとファイルを作成しまくる

dd if=/dev/zero of=/tmp/disk bs=1M count=1000
mkfs.ext4 /tmp/disk 
sudo mount -t xfs /tmp/disk /mnt
for i in $(seq 1 1000); do sudo mkdir -pv /mnt/$i/{1..100}; done
for i in $(seq 1 1000); do sudo touch /mnt/$i/{1..100}/test.txt; done

readonly で remount しなおす

sudo mount -o remount -r -t xfs /mnt

dentry と xfs_inode を貯めるべく find する

sudo find /mnt >/dev/null

この時点で slabtop すると、以下の slab が溜まっている

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME                   
201042 201042 100%    0.94K  11826       17    189216K xfs_inode
104192 101602  97%    0.50K   6512       16     52096K kmalloc-512
229383 224847  98%    0.19K  10923       21     43692K dentry

...

拙作のカーネルモジュールで dentry と inode (xfs_inode) を破棄する

# /mnt の superblock を対象にして dentry と xfs_inode を破棄する (はず
echo /mnt | sudo tee /sys/kernel/debug/shrink_super_block_cache

slabtop しなおすと dentry と xfs_inode が消えた ( kmalloc-512 もなくなったな??? )

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME                   
 16107  15673  97%    0.59K   1239       13      9912K inode_cache
  8325   7409  88%    1.06K    555       15      8880K ext4_inode_cache
 50430  50127  99%    0.13K   1681       30      6724K kernfs_node_cache
 29883  24224  81%    0.19K   1423       21      5692K dentry

 ...

dentry cache と inode ( xfs_inode ) を破棄することに成功したぽい.


ext4 でも同様の結果を得ている. slab キャッシュの生成とキャッシュの破棄とを並列にするなどして kernel panic 等を起こさないかも試し中

まとめ

  • とりあえずやりたいことは成功した
  • カーネル内部の API 呼び出しは、呼び出す側がどういう条件を満たしれいれば安全なのかを把握するのが大変
  • バージョンを変えてみるとカーネルの 内部 API に変更が入ってたりするので いろいろ見てみないといけない