倚天剑(Perf)和屠龙刀(Ebpf)出马,手撕 Linux sync 卡死问题

1 背景

最近陆续有 “Linux Lab” ( http://tinylab.org
) 用户报告偶发 firefox 跑不起来,偶发执行 sync 命令后不返回的情况,本文是这个 bug ( https://gitee.com/tinylab/linux-lab/issues/I1GGG1
) 的分析报告。
有部分 Linux Lab 开发者参与了现象收集和初步分析工作,最后由我汇总如下文。在此感谢他们的付出。

2 现象收集与汇总

我们陆续收到的现象汇总如下:

2.1 异常环境信息

Product: Gigabyte、ASUSTeK 、Hasee
ARCH: x86_64
CPU: i5-6500、i5-4210U
RAM: 7915 MiB
System: Deepin 20 Beta、 Ubuntu 18.04 LTS、Ubuntu 20.04 LTS
Kernel: 5.3、5.4
Docker: 19.03
Shell: 5.0

2.2 正常环境信息

Product: VMware、Lenovo Y50-70、X555LI、VBox
ARCH: x86_64
CPU: i7-8550U、i5-4210H、i7-6700K、i7-8550U
RAM: 3934 MiB、 2906 MiB
System: Ubuntu 16.04、Ubuntu 18.04、CentOS Linux release 7.7.1908、Deepin 15.11
Kernel: 4.4、4.15、4.19、5.0、5.2、5.3
Docker: 18.09、19.03
Shell: 4.2、4.4、5.0

3 问题初步分析

3.1 寻找必现路径

启动 lab
登录 lab
stop lab
systemctl stop docker
sync 卡死

3.2 调用栈初步分析

  • 用下面的命令分别抓取了正常情况和异常情况下 sync 的调用信息

    sudo perf  ftrace -t function_graph -G ksys_sync sync > 1.txt
    

    通过分析,发现异常情况下,最后停在了这个位置:

     0)   0.364 us    |      _raw_spin_lock();
     0)               |      down_read() {
     0)               |        _cond_resched() {
     0)   0.239 us    |          rcu_all_qs();
     0)   0.887 us    |        }
     0)               |        rwsem_down_read_slowpath() {
     0)   0.186 us    |          _raw_spin_lock_irq();
     0)   0.373 us    |          wake_up_q();
     0)               |          schedule() {
     0)               |            rcu_note_context_switch() {
     0)   0.391 us    |              rcu_qs();
     0)   0.889 us    |            }
     0)   0.197 us    |            _raw_spin_lock();
     0)   0.202 us    |            update_rq_clock();
    

4 问题深入分析

4.1 获取第一现场

  • 为了深入分析,我在笔记本上全新安装了 ubuntu 20.04 和 Linux Lab。
  • 等到我的 ubuntu 20.04 装好,Linux Lab 装好,迫不及待的尝试了一下。非常神奇的现象出现了:sync 卡死了,有了第一现场的信息!

4.2 分析第一现场

  • 根据多年的嵌入式研发经验,简单的命令卡死,第一反应当然是看 cpu、mem、io、 /proc//status
    /proc//stack
    gdb attach
    上去看看。发现 cpu、mem、IO 消耗都很低,sync 卡死在 ksys_sync
    里面的 iterate_supers
    中,状态是 disk sleep,gdb 也卡死了。

    void ksys_sync(void)
    {
        int nowait = 0, wait = 1;
    
        wakeup_flusher_threads(WB_REASON_SYNC);
        iterate_supers(sync_inodes_one_sb, NULL);
        iterate_supers(sync_fs_one_sb, &nowait);
        iterate_supers(sync_fs_one_sb, &wait);
        iterate_bdevs(fdatawrite_one_bdev, NULL);
        iterate_bdevs(fdatawait_one_bdev, NULL);
        if (unlikely(laptop_mode))
            laptop_sync_completion();
    }
    
  • 此时感觉和 Linux 内核还是有一定关系的(毕竟卡死在内核了)。

4.3 排除干扰,寻找元凶

  • 我们逐个排查了 cloud-lab 下 configs/linux-lab/tools/container-run
    中加载的模块: loop minix nfsd 9pnet_virtio kvm $kvm_dri
    。发现加载 nfsd 的时候有异常。

  • kernel image 是通过 apt upgrade
    方式升级的,nfsd 模块是 upgrade 的时候自带的,不是 Linux Lab 中的。因此,可以先确认一下在 host 里面开启 nfs 服务并且挂载 nfs 文件系统,看有没有问题。如果没有问题,再看 Linux Lab 中的配置和 host 有什么区别。

  • 经过验证,在 host 中加载 nfsd 没有问题。但是 Linux Lab 中 /etc/exports
    和 host 中的 exports 有差异。统一配置后,在 Linux Lab 中挂载 nfsd 还是有问题。只能在 Linux Lab 中一步步的执行、排查。

  • 实验如下( vbox ubuntu 18.04 kernel v5.3 ):

    luo@luo:~/linux/cloud-lab@
    l
    u
    o
    
     :
    
     E
    
     126
    
     E
    
     l
    
     i
    
     n
    
     u
    
     x
    
     c
    
     l
    
     o
    
     u
    
     d
    
     E
    
     45
    
     E
    
     l
    
     a
    
     b
    lsmodgrepnsfdluo@luoEElinuxcloudEElab ./tools/docker/run linux-lab
    LOG: Current Lab is linux-lab
    LOG: Open the running linux-lab
    LOG: Current Lab is linux-lab
    LOG: Available login methods:

    bash ssh vnc webssh webvnc

    LOG: Switch to another method:

    .//home/luo/linux/cloud-lab/tools/docker/login LOGIN_METHOD

    LOG: Running 'tools/docker/bash'

    LOG: Current Lab is linux-lab
    LOG: Running ' docker exec -it -w //labs/linux-lab -u ubuntu 'linux-lab-10410' //bin/bash'
    ubuntu@linux-lab:/labs/linux-lab@ l i n u x E 45 E l a b : l a b s l i n u x E 45 E l a b sudomodprobeEEdmnfsdubuntu@linuxEElablabslinuxEElab echo @ l i n u x E 45 E l a b : l a b s l i n u x E 45 E l a b 137ubuntu@linuxEElablabslinuxEElab
  • 执行 modprobe nfsd,返回值137,说明执行失败。查看 dmesg,发现如下异常信息:

    [  304.086144] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
    [  304.086228] BUG: kernel NULL pointer dereference, address: 0000000000000058
    [  304.086231] #PF: supervisor write access in kernel mode
    [  304.086233] #PF: error_code(0x0002) - not-present page
    [  304.086234] PGD 0 P4D 0
    [  304.086238] Oops: 0002 [#1] SMP PTI
    [  304.086241] CPU: 3 PID: 9151 Comm: modprobe Tainted: G           O      5.3.0-51-generic #44~18.04.2-Ubuntu
    [  304.086242] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
    [  304.086257] RIP: 0010:nfsd_fill_super+0x71/0x90 [nfsd]
    [  304.086260] Code: 85 c0 89 c3 74 09 89 d8 5b 41 5c 41 5d 5d c3 49 8b 7c 24 68 31 f6 48 c7 c2 70 84 a0 c0 e8 97 fe ff ff 48 3d 00 f0 ff ff 77 0d  89 45 58 89 d8 5b 41 5c 41 5d 5d c3 89 c3 eb cb 0f 1f 40 00 66
    [  304.086261] RSP: 0018:ffffba6945edfaa8 EFLAGS: 00010287
    [  304.086263] RAX: ffff9256d671e600 RBX: 0000000000000000 RCX: 0000000000000002
    [  304.086265] RDX: 0000000000000000 RSI: 0000000000000100 RDI: ffff9256cf8309e0
    [  304.086267] RBP: ffffba6945edfac0 R08: ffff9256d671e620 R09: 0000000000000000
    [  304.086268] R10: 0000000000000000 R11: fefefefefefefeff R12: ffff925796085000
    [  304.086269] R13: 0000000000000000 R14: ffffffffc09cf4d0 R15: ffff92579b344680
    [  304.086272] FS:  00007fb55e4b9740(0000) GS:ffff92579bb80000(0000) knlGS:0000000000000000
    [  304.086273] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [  304.086275] CR2: 0000000000000058 CR3: 0000000056ab4000 CR4: 00000000000406e0
    [  304.086281] Call Trace:
    [  304.086288]  vfs_get_super+0x5b/0xe0
    [  304.086292]  ? vfs_parse_fs_param+0xdc/0x1c0
    [  304.086302]  nfsd_fs_get_tree+0x2c/0x30 [nfsd]
    [  304.086305]  vfs_get_tree+0x2a/0x100
    [  304.086308]  fc_mount+0x12/0x40
    [  304.086310]  vfs_kern_mount.part.31+0x76/0x90
    [  304.086312]  vfs_kern_mount+0x13/0x20
    [  304.086321]  nfsd_init_net+0x101/0x140 [nfsd]
    [  304.086325]  ops_init+0x44/0x120
    [  304.086327]  register_pernet_operations+0xed/0x200
    [  304.086339]  ? trace_event_define_fields_nfsd_stateid_class+0xb3/0xb3 [nfsd]
    [  304.086341]  register_pernet_subsys+0x28/0x40
    [  304.086352]  init_nfsd+0x22/0xcbc [nfsd]
    [  304.086355]  do_one_initcall+0x4a/0x1fa
    [  304.086357]  ? _cond_resched+0x19/0x40
    [  304.086361]  ? kmem_cache_alloc_trace+0x15c/0x210
    [  304.086365]  do_init_module+0x5f/0x227
    [  304.086368]  load_module+0x1aa4/0x2140
    [  304.086372]  __do_sys_finit_module+0xfc/0x120
    [  304.086375]  ? __do_sys_finit_module+0xfc/0x120
    [  304.086379]  __x64_sys_finit_module+0x1a/0x20
    [  304.086381]  do_syscall_64+0x5a/0x130
    [  304.086383]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
    [  304.086386] RIP: 0033:0x7fb55dfd93c9
    [  304.086388] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05  3d 01 f0 ff ff 73 01 c3 48 8b 0d 8f 9a 2c 00 f7 d8 64 89 01 48
    [  304.086390] RSP: 002b:00007ffd8171ba08 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
    [  304.086392] RAX: ffffffffffffffda RBX: 000056544ce0eee9 RCX: 00007fb55dfd93c9
    [  304.086393] RDX: 0000000000000000 RSI: 000056544ce0eee9 RDI: 0000000000000003
    [  304.086395] RBP: 0000000000000000 R08: 0000000000000000 R09: 000056544d238150
    [  304.086396] R10: 0000000000000003 R11: 0000000000000246 R12: 000056544d230250
    [  304.086398] R13: 000056544d233b20 R14: 000056544d2382f0 R15: 0000000000040000
    [  304.086400] Modules linked in: nfsd(+) auth_rpcgss nfs_acl lockd grace kvm irqbypass 9pnet_virtio 9pnet minix xt_nat xt_tcpudp veth xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c bpfilter br_netfilter bridge stp llc nls_utf8 isofs vboxsf(O) aufs overlay intel_rapl_msr snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi vboxvideo snd_seq snd_seq_device snd_timer drm_vram_helper snd ttm drm_kms_helper drm fb_sys_fops soundcore syscopyarea joydev sysfillrect intel_rapl_common sysimgblt crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 crypto_simd cryptd glue_helper vboxguest(O) input_leds intel_rapl_perf serio_raw mac_hid binfmt_misc sch_fq_codel cuse parport_pc ppdev sunrpc lp parport ip_tables x_tables autofs4 hid_generic usbhid hid ahci i2c_piix4 psmouse libahci video e1000 pata_acpi
    [  304.086436] CR2: 0000000000000058
    [  304.086439] ---[ end trace 0deb363709117b2c ]---
    [  304.086449] RIP: 0010:nfsd_fill_super+0x71/0x90 [nfsd]
    [  304.086451] Code: 85 c0 89 c3 74 09 89 d8 5b 41 5c 41 5d 5d c3 49 8b 7c 24 68 31 f6 48 c7 c2 70 84 a0 c0 e8 97 fe ff ff 48 3d 00 f0 ff ff 77 0d  89 45 58 89 d8 5b 41 5c 41 5d 5d c3 89 c3 eb cb 0f 1f 40 00 66
    [  304.086453] RSP: 0018:ffffba6945edfaa8 EFLAGS: 00010287
    [  304.086454] RAX: ffff9256d671e600 RBX: 0000000000000000 RCX: 0000000000000002
    [  304.086456] RDX: 0000000000000000 RSI: 0000000000000100 RDI: ffff9256cf8309e0
    [  304.086457] RBP: ffffba6945edfac0 R08: ffff9256d671e620 R09: 0000000000000000
    [  304.086459] R10: 0000000000000000 R11: fefefefefefefeff R12: ffff925796085000
    [  304.086460] R13: 0000000000000000 R14: ffffffffc09cf4d0 R15: ffff92579b344680
    [  304.086462] FS:  00007fb55e4b9740(0000) GS:ffff92579bb80000(0000) knlGS:0000000000000000
    [  304.086463] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [  304.086465] CR2: 0000000000000058 CR3: 0000000056ab4000 CR4: 00000000000406e0
    
  • 刚开始加载模块的时候,kernel NULL pointer dereference
  • supervisor write access in kernel mode,error_code(0x0002) – not-present page,PGD 0 P4D 0
  • Oops:backtrace 中有 init_nfsd,初始化 nfsd 失败。
  • sync 卡死可能和在 docker 容器中加载 nfsd 模块失败有关系。

5 寻找第一现场和第二现场的直接联系

5.1 sync 卡死时请求获取的锁被谁持有?

  • 用 perf ftrace 跟踪到 sync 卡死的时候,运行在 ksys_sync
    下面的第一个 iterate_supers
    中。相关代码如下:

    void ksys_sync(void)
    {
        int nowait = 0, wait = 1;
    
        wakeup_flusher_threads(WB_REASON_SYNC);
        iterate_supers(sync_inodes_one_sb, NULL);
        iterate_supers(sync_fs_one_sb, &nowait);
        iterate_supers(sync_fs_one_sb, &wait);
        iterate_bdevs(fdatawrite_one_bdev, NULL);
        iterate_bdevs(fdatawait_one_bdev, NULL);
        if (unlikely(laptop_mode))
            laptop_sync_completion();
    }
    
    void iterate_supers(void (*f)(struct super_block *, void *), void *arg)
    {
        struct super_block *sb, *p = NULL;
    
        spin_lock(&sb_lock);
        list_for_each_entry(sb, &super_blocks, s_list) {
            if (hlist_unhashed(&sb->s_instances))
                continue;
            sb->s_count++;
            spin_unlock(&sb_lock);
    
            down_read(&sb->s_umount);
            if (sb->s_root && (sb->s_flags & SB_BORN))
                f(sb, arg);
            up_read(&sb->s_umount);
    
            spin_lock(&sb_lock);
            if (p)
                __put_super(p);
            p = sb;
        }
        if (p)
            __put_super(p);
        spin_unlock(&sb_lock);
    }
    
  • iterate_supers
    遍历 super_blocks
    链表,执行 f(sb, arg)
    。perf ftrace 最后结果显示卡死在 down_read(&sb->s_umount)
    下。也就是说在拿这个读写信号量锁的时候卡死了,肯定是有人 down_write
    了,一直没有 up_write
    (写者一直持有锁,读者只能一直等)。

  • 问题:谁持有该锁?找到它就相当于找到了导致 sync 卡死的元凶!

    void __sched down_read(struct rw_semaphore *sem)
    {
        might_sleep();
        rwsem_acquire_read(&sem->dep_map, 0, 0, _RET_IP_);
      
        LOCK_CONTENDED(sem, __down_read_trylock, __down_read);
    }
    EXPORT_SYMBOL(down_read);
    
    #define LOCK_CONTENDED(_lock, try, lock) \
        lock(_lock)
    
    inline void __down_read(struct rw_semaphore *sem)
    {
        if (!rwsem_read_trylock(sem)) {
            rwsem_down_read_slowpath(sem, TASK_UNINTERRUPTIBLE);
         DEBUG_RWSEMS_WARN_ON(!is_rwsem_reader_owned(sem), sem);
        } else {
            rwsem_set_reader_owned(sem);
        }
    }
    
    struct rw_semaphore {
        atomic_long_t count;
        /*
         * Write owner or one of the read owners as well flags regarding
         * the current state of the rwsem. Can be used as a speculative
         * check to see if the write owner is running on the cpu.
         */
        atomic_long_t owner;
    #ifdef CONFIG_RWSEM_SPIN_ON_OWNER
        struct optimistic_spin_queue osq; /* spinner MCS lock */
    #endif
        raw_spinlock_t wait_lock;
        struct list_head wait_list;
    #ifdef CONFIG_DEBUG_LOCK_ALLOC
        struct lockdep_map dep_map;
    #endif
    };
    
  • 根据上面的代码,可以看到 trylock 失败后会走 rwsem_down_read_slowpath
    。用 trace 抓取 rwsem_down_read_slowpath
    ,找到 sem 的 owner。

    luo@luo:/usr/share/bcc/tools$ sudo ./trace  'rwsem_down_read_slowpath(struct rw_semaphore *sem, int state) "count=0x%lx  owner=%s", sem->count.counter, ((struct task_struct *)((sem->owner.counter)&~0x7))->comm'
    /virtual/main.c:44:66: warning: comparison of array '((struct task_struct *)((sem->owner.counter) & ~7))->comm' not equal to a null pointer is
          always true [-Wtautological-pointer-compare]
            if (((struct task_struct *)((sem->owner.counter)&~0x7))->comm != 0) {
                ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~~    ~
    1 warning generated.
    PID     TID     COMM            FUNC             -
    10127   10127   sync            rwsem_down_read_slowpath count=0x103  owner=modprobe
  • 元凶终于找到了, modprobe !但是,modprobe 在加载哪个模块的时候出的事故呢?

5.2 sync 在同步哪个资源的时候卡死了?

  • down_read(&sb->s_umount)
    可以发现,sem 是 super_block
    的成员,可以通过 sem 获取 super_block
    相关的信息。

    luo@luo:/usr/share/bcc/tools$ sudo ./trace 'rwsem_down_read_slowpath(struct rw_semaphore *sem, int state) "count=0x%lx  fs name=%s", sem->count.counter, (((struct super_block*)((void *)sem-(void*)(&(((struct super_block*)0)->s_umount))))->s_id)'
    PID     TID     COMM            FUNC             -
    10144   10144   sync            rwsem_down_read_slowpath count=0x103  fs name=nfsd
    
  • 到此,已经找到了 sync 卡死和挂载 nfsd 失败的两个直接联系。

6 结论

  • 当 Linux >= v5.3 时,在 docker 镜像中加载 nfsd 模块失败,并且 modprobe 退出后 nfsd 模块的读写锁被写者 modprobe 持有,导致 sync 命令申请获取该锁时失败,一直等待。
  • 这个 bug 目前只有一个 workaround 的方案:

    针对 Linux >= 5.3 的,在 host 侧插入 nfsd 模块。
    针对 win 和 macosx,暂时没有比较好的策略,保留原有策略,后续需要确认 win 和 macosx docker 所用版本,如果不超过 5.3,应该是没问题。

  • 后续找到在 docker 中加载 nfsd 失败的原因了,会写一篇对应的文章。

7 工具安装

  • perf
sudo apt update -y && sudo apt upgrade -y
sudo apt install -y linux-tools-common linux-tools-`uname -r` linux-cloud-tools-`uname -r`
  • ebpf trace
docker pull zlim/bcc
docker run -it --rm \
  --privileged \
  -v /lib/modules:/lib/modules:ro \
  -v /usr/src:/usr/src:ro \
  -v /etc/localtime:/etc/localtime:ro \
  --workdir /usr/share/bcc/tools \
  zlim/bcc