泰晓科技 -- 聚焦 Linux - 追本溯源，见微知著！
网站地址：https://tinylab.org

泰晓Linux知识星球：1300+知识点，520+用户
请稍侯

Linux 下的 Sync 卡死问题分析报告

Luo Xiaogang 创作于 2020/05/14
打赏

By rxd of TinyLab.org May 14, 2020

背景

最近陆续有 Linux Lab 用户报告偶发 firefox 跑不起来，偶发执行 sync 命令后不返回的情况，本文是这个 bug 的分析报告。

有部分 Linux Lab 开发者参与了现象收集和初步分析工作，最后由我汇总如下文。在此感谢他们的付出。

现象收集与汇总

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

异常环境信息

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

正常环境信息

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

问题初步分析

寻找必现路径

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

调用栈初步分析

  • 用下面的命令分别抓取了正常情况和异常情况下 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();

问题深入分析

获取第一现场

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

分析第一现场

  • 根据多年的嵌入式研发经验，简单的命令卡死，第一反应当然是看 cpu、mem、io、/proc/<pidof sync>/status、/proc/<pidof sync>/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 内核还是有一定关系的（毕竟卡死在内核了）。

排除干扰，寻找元凶

  • 我们逐个排查了 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$ lsmod | grep nsfd
luo@luo:~/linux/cloud-lab$ ./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$ sudo modprobe -d /m nfsd
ubuntu@linux-lab:/labs/linux-lab$ echo $?
137
ubuntu@linux-lab:/labs/linux-lab$
  • 执行 modprobe，返回值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 <49> 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 <48> 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 <49> 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 模块失败有关系。

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

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 在加载哪个模块的时候出的事故呢？

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 失败的两个直接联系。

结论

  • 当 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 失败的原因了，会写一篇对应的文章。

工具安装

  • 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

Read Album:

Read Related:

Read Latest: