容器因内存频繁OOM而引发的内核“血案”

2021-09-23 16:17:36 浏览数 (3)

腾讯云线上一个大客户上云过程中遇到在TKE环境中，出现node节点频繁夯死的现象，经过团队深入分析得知是触发了在ext4文件系统上内存频繁OOM而引发内核hung死，本文抱着学习vmcore的心态对该内核bug的原因做深入分析，如何复现，如何规避，以及在kubernetes容器环境下内核如何选型的最佳实践。

1. 勘查现场

客户上云过程中将原有在数据中心自建kubernetes集群迁移至腾讯云TKE集群，迁移过程中发现其中有一个容器沙箱环境频繁出现node节点夯死现象，目前已经出现5-6次，亟需定位原因。出现异常时节点无法登陆且需要手动重启才能恢复，"罪犯"逃离，异常后节点状态置为NotReady，无状态化pods会自动驱逐至其他节点，有状态化StatefullSets部署的pods无法驱逐成功。

出现异常时通过巴拉多观察监控，可以发现一个共同的现象：异常期间容器所在的cbs数据盘读IO瞬间打满，磁盘util利用率持续达到100%

磁盘读IO瞬间打满磁盘读IO瞬间打满

前两次出现异常时候客户直接重启机器恢复，“案发现场”已逃离，无法获知到异常时的蛛丝马迹。为了抓取案发现场，等待第三次复现，联系CVM计算专项同学手动触发“魔法键”生成vmcore。

2. 浮出水面

2.1 尝试破案

由于事先知道机器已夯死，调查组通过SysRq手动触发生成vmcore文件，安装crash和kernel-debuginfo工具包，调查组开始犯罪现场的调研工作：尝试分析coredump文件，先看下D进程的情况，可以看到有17w个进程，其中有2081个进程处于僵死状态，大部分是Java进程。

代码语言：txt复制
crash> sys
      KERNEL: /usr/lib/debug/lib/modules/3.10.0-1127.19.1.el7.x86_64/vmlinux
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 64
        DATE: Mon Aug 30 10:46:05 2021
      UPTIME: 53 days, 20:45:42
LOAD AVERAGE: 2142.96, 2141.13, 2126.04
       TASKS: 17585
    NODENAME: VM-8-17-centos
     RELEASE: 3.10.0-1127.19.1.el7.x86_64
     VERSION: #1 SMP Tue Aug 25 17:23:54 UTC 2020
     MACHINE: x86_64  (2595 Mhz)
      MEMORY: 128 GB
       PANIC: "SysRq : Trigger a crash"    //通过SysRq手动触发生成crash

crash> ps | wc -l    //一共有17586个进程
17586

crash> ps | grep UN | wc -l    //其中2081个进程处于僵死状态
2081

crash> ps | grep UN  //大部分僵死进程是Java进程，除此之外还有docker等进程
1459  2  24  ffff94d2fd95d230  UN   0.0       0      0  [jbd2/vdb-8]
4441  4192192  11  ffff94c9c7fa62a0  UN   0.5 36955132 679404  java
4444  4192192  12  ffff94c8a09941c0  UN   0.5 36955132 679404  java
4585  4192192  48  ffff94c8a09920e0  UN   0.5 36955132 679404  java
4586  4192192  14  ffff94c8a0993150  UN   0.5 36955132 679404  java

有这么多进程处于僵死状态，到底是什么进程导致系统hung死呢？先统计下所有hung住的进程都hung在哪里

代码语言：txt复制
crash> foreach UN bt | awk '/#2/ {print $3,$5}' |sort|uniq -c|sort -n
   1725 rwsem_down_read_failed ffffffffb3187795
    160 schedule_timeout ffffffffb31838b1
    119 wait_transaction_locked ffffffffc04f8085
     52 __mutex_lock_slowpath ffffffffb3184c57
     22 rwsem_down_write_failed ffffffffb31874e5
      1 trace_do_page_fault ffffffffb318da26
      1 __mutex_lock_killable_slowpath ffffffffb318450c
      1 jbd2_log_wait_commit ffffffffc0501875
      1 jbd2_journal_commit_transaction ffffffffc04fb30c
      1 handle_mm_fault ffffffffb2bf5d80
      1 __do_page_fault ffffffffb318d653
      1 do_async_page_fault ffffffffb318cfa2
      1 asyncpage_fault ffffffffb31897a8

可以看到有1725个进程在等待rwsem，推测进程卡住是因为rwsem本身卡住或者是其他原因卡住而导致，查看最早卡死的进程，可以看到有jbd2/vdb-8进程出现了僵死，查看log日志可以看到磁盘出现了"jbd2/vdb-8:1459 blocked for more than 120 seconds.",还有polkitd，kubelet等进程

代码语言：txt复制
crash> ps |grep UN | head    //jbd2/vdb进程出现卡死
 1459      2  24  ffff94d2fd95d230  UN   0.0       0    0 [jbd2/vdb-8]
 1534      1  52  ffff94d2e6f520e0  UN   0.0  614460   7176  polkitd
 1582      1   0  ffff94d2e6f55230  UN   0.0   65444  5528  dbus-daemon
 1607      1  42  ffff94d2faaed230  UN   0.1 4580440 160912  kubelet

 crash> log
[4453228.128056] INFO: task jbd2/vdb-8:1459 blocked for more than 120 seconds.    //vdb磁盘出现了卡死
[4453228.129706] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[4453228.131078] jbd2/vdb-8      D ffff94d2fd95d230     0  1459      2 0x00000000
[4453228.128056] INFO: task jbd2/vdb-8:1459 blocked for more than 120 seconds.        //vdb出现卡死，超过120s后即卡死
[4453228.129706] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[4453228.131078] jbd2/vdb-8      D ffff94d2fd95d230     0  1459      2 0x00000000
[4453228.131082] Call Trace:
[4453228.131807]  [<ffffffffb2ad3820>] ? task_rq_unlock 0x20/0x20
[4453228.132907]  [<ffffffffb3185da9>] schedule 0x29/0x70
[4453228.133942]  [<ffffffffc04fb30c>] jbd2_journal_commit_transaction 0x23c/0x19c0 [jbd2]
[4453228.135309]  [<ffffffffb2ae1bfe>] ? account_entity_dequeue 0xae/0xd0
[4453228.136500]  [<ffffffffb2ae539c>] ? dequeue_entity 0x11c/0x5c0
[4453228.137614]  [<ffffffffb2a6d3be>] ? kvm_sched_clock_read 0x1e/0x30
[4453228.138752]  [<ffffffffb2ae69a1>] ? put_prev_entity 0x31/0x400
[4453228.139849]  [<ffffffffb2a2b59e>] ? __switch_to 0xce/0x580
[4453228.140883]  [<ffffffffb2ad53fe>] ? finish_task_switch 0x4e/0x1c0
[4453228.141993]  [<ffffffffb2ac7780>] ? wake_up_atomic_t 0x30/0x30
[4453228.143063]  [<ffffffffb3185942>] ? __schedule 0x402/0x840
[4453228.144107]  [<ffffffffb2aae97e>] ? try_to_del_timer_sync 0x5e/0x90
[4453228.145239]  [<ffffffffc0501f39>] kjournald2 0xc9/0x260 [jbd2]
[4453228.146337]  [<ffffffffb2ac7780>] ? wake_up_atomic_t 0x30/0x30
[4453228.147429]  [<ffffffffc0501e70>] ? commit_timeout 0x10/0x10 [jbd2]
[4453228.148563]  [<ffffffffb2ac6691>] kthread 0xd1/0xe0
[4453228.149531]  [<ffffffffb2ac65c0>] ? insert_kthread_work 0x40/0x40
[4453228.150704]  [<ffffffffb3192d24>] ret_from_fork_nospec_begin 0xe/0x21
[4453228.151948]  [<ffffffffb2ac65c0>] ? insert_kthread_work 0x40/0x40

通过这里可以知道vdb的jbd2已经出现了卡死，是vdb卡死导致内核奔溃还是rwsem进程导致vdb奔溃呢？ 为什么jbd2会出现卡死呢？

什么是ext4/jbd2 ,参考 Linux: The Journaling Block Device（https://web.archive.org/web/20070926223043/http://kerneltrap.org/node/6741），ext4 文件系统基于 jbd2 以 WAL（write-ahead logging）形式更新元数据，防止系统 crash 时发生元数据损坏。每一个 ext4 文件系统实例对应一个 jbd2 Journal 实例。每个用户线程的一次数据更新称为一个 Handle，在时间上连续的多个 Handle（可能来自不同线程）组成一个 Transaction，以便实现批量提交。Transaction 提交满足原子性。

查看下jbd2进程的堆栈信息，可以看到jbd2/vdb-8在等待jbd2_journal_commit_transaction

代码语言：txt复制
crash> ps |grep vdb
 1459    2  24  ffff94d2fd95d230  UN   0.0       0      0  [jbd2/vdb-8]
 
crash> bt 1459    //查看jbd2/vdb-8的堆栈信息
PID: 1459   TASK: ffff94d2fd95d230  CPU: 24  COMMAND: "jbd2/vdb-8"
 #0 [ffff94d2fb68bc08] __schedule at ffffffffb31858fa 
 #1 [ffff94d2fb68bc98] schedule at ffffffffb3185da9 
 #2 [ffff94d2fb68bca8] jbd2_journal_commit_transaction at ffffffffc04fb30c  [jbd2]
 #3 [ffff94d2fb68be48] kjournald2 at ffffffffc0501f39  [jbd2]
 #4 [ffff94d2fb68bec8] kthread at ffffffffb2ac6691 
 #5 [ffff94d2fb68bf50] ret_from_fork_nospec_begin at ffffffffb3192d24

排行前面的进程卡死是什么导致的呢，通过查看polkitd进程和后面的kubelet进程，其堆栈信息均相同，因此怀疑是相同的原因导致后面的进程卡死，也就是说后面的进程是受害者，因为vdb卡死而导致进程陆续卡死

代码语言：txt复制
crash> bt 1534
PID: 1534   TASK: ffff94d2e6f520e0  CPU: 52  COMMAND: "polkitd"
 #0 [ffff94d2ee8ab9e8] __schedule at ffffffffb31858fa 
 #1 [ffff94d2ee8aba78] schedule at ffffffffb3185da9 
 #2 [ffff94d2ee8aba88] schedule_timeout at ffffffffb31838b1 
 #3 [ffff94d2ee8abb30] io_schedule_timeout at ffffffffb318549d 
 #4 [ffff94d2ee8abb60] io_schedule at ffffffffb3185538 
 #5 [ffff94d2ee8abb70] bit_wait_io at ffffffffb3183f01 
 #6 [ffff94d2ee8abb88] __wait_on_bit at ffffffffb3183a27 
 #7 [ffff94d2ee8abbc8] wait_on_page_bit_killable at ffffffffb2bc0c93 
 #8 [ffff94d2ee8abc20] __lock_page_or_retry at ffffffffb2bc0d62 
 #9 [ffff94d2ee8abc40] filemap_fault at ffffffffb2bc1157 //
#10 [ffff94d2ee8abcb0] ext4_filemap_fault at ffffffffc0651706  [ext4]
#11 [ffff94d2ee8abcd8] __do_fault at ffffffffb2bedf6a 
#12 [ffff94d2ee8abd58] do_read_fault at ffffffffb2bee51c 
#13 [ffff94d2ee8abdb8] handle_mm_fault at ffffffffb2bf5d80 
#14 [ffff94d2ee8abe80] __do_page_fault at ffffffffb318d653 
#15 [ffff94d2ee8abef0] trace_do_page_fault at ffffffffb318da26 
#16 [ffff94d2ee8abf30] do_async_page_fault at ffffffffb318cfa2 
#17 [ffff94d2ee8abf50] async_page_fault at ffffffffb31897a8 
    RIP: 00007f3604c3da9f  RSP: 00007ffd161cf660  RFLAGS: 00010207
    RAX: 0000000000000001  RBX: 0000000000000001  RCX: ffffffffffffffff
    RDX: 0000000000000001  RSI: 0000000000000081  RDI: 00007f3604e79658
    RBP: 0000558426397850   R8: 0000000000000000   R9: 000055842638bf60
    R10: 0000000000000000  R11: 0000000000000246  R12: 0000558426397858
    R13: 0000558426397860  R14: 00007f35f000f410  R15: 00007f3604c27940
    ORIG_RAX: ffffffffffffffff  CS: 0033  SS: 002b

至此，推测是vdb/jbd2卡死导致此次机器hung死的原因，而vdb卡死原因从监控上来看是读IO瞬间突增导致cbs云盘被打满。

至于磁盘读IO的来源，和客户了解业务模型中并为有读IO瞬间突增的请求，其容器只有常规的写日志操作，由于node节点并为部属atop或者iotop监控，无法抓取到磁盘IO突增时刻IO所属的进程，因此无法获知vdb卡死的来由。

经过评估，需要在node节点上部署atop和iotop监控，待复现抓取异常IO的来源，通过crontab部署iotop监控，其中iotop以每秒的粒度获取监控信息，通过crontab每天运行一次，内容如下:

代码语言：txt复制
01 10 * * * nohup /usr/sbin/iotop -botq --iter=86400 >> /data1/iotop/$(date " %Y%m%d")_iotop.log

部署完监控后，待“犯罪分子”再次光临。

2.2 陷入两难

经过两周的时间等待，犯罪分子于8月30日02:57分再次作案，警方希望通过已部署的“抓捕工具”（atop和iotop）能够抓到犯罪证据（磁盘读高IO来源）

磁盘util被打满磁盘util被打满

然而，通过分析atop和iotop发现，犯罪分子相当“狡猾”，案发之后所有的监控都失效了：iotop在02:57分后就无日志记录； atop最后一次日志时间为02:48:37 （10分钟采集一次）

https://km.woa.com/files/photos/pictures/202109/1631437802_47_w971_h261.png

iotop监控iotop监控

到2:57分之后系统就处于夯死状态，此时调查组陷入了进退两难的界面：怀疑内核hung死是由于磁盘读高IO导致，内核夯死导致监控无法抓到现场，犯罪分子逃之夭夭，此时陷入两难界面：到底是内核问题引起 or 磁盘高IO导致机器夯死？如若无法找到真凶，找出幕后罪魁祸首，客户切量上云将会受到极大的阻碍，调查组增派专家支援，试图从残留的犯罪现场中寻找蛛丝马迹。

2.3 拨开云雾

首先分析下为何atop和iotop监控无法采集到犯罪现场：通过查看atop和iotop的堆栈信息，可以看到：iotop和atop因获取rwsem量而卡住，导致卡死无法获取到当时的监控信息

代码语言：txt复制
crash> ps | grep iotop
  607982  607971  15  ffff94cc443b20e0  UN   0.1  275244  86412  iotop

crash> bt 607982    //iotop因获取rwsem而卡住
PID: 607982  TASK: ffff94cc443b20e0  CPU: 15  COMMAND: "iotop"
 #0 [ffff94c7ec177cb8] __schedule at ffffffffb31858fa 
 #1 [ffff94c7ec177d40] schedule at ffffffffb3185da9 
 #2 [ffff94c7ec177d50] rwsem_down_read_failed at ffffffffb3187795 #卡住
 #3 [ffff94c7ec177dd8] call_rwsem_down_read_failed at ffffffffb2d96748 
 #4 [ffff94c7ec177e28] down_read at ffffffffb31850b0 
 #5 [ffff94c7ec177e40] proc_pid_cmdline_read at ffffffffb2cc9b32 
 #6 [ffff94c7ec177ed8] vfs_read at ffffffffb2c4d06f 
 #7 [ffff94c7ec177f08] sys_read at ffffffffb2c4dedf 
 #8 [ffff94c7ec177f50] tracesys at ffffffffb3193166  (via system_call)
    RIP: 00007ff51452d9a0  RSP: 00007ffc4fac8f78  RFLAGS: 00000246
    RAX: ffffffffffffffda  RBX: 0000000002fc5570  RCX: ffffffffffffffff
    RDX: 0000000000001000  RSI: 0000000001cde844  RDI: 0000000000000006
    RBP: 00007ff514802380   R8: ffffffffffffffff   R9: 0000000000000000
    R10: 0000000000000022  R11: 0000000000000246  R12: 0000000000001000
    R13: 0000000000000d70  R14: 00007ff514801838  R15: 0000000001cde844
    ORIG_RAX: 0000000000000000  CS: 0033  SS: 002b

crash> ps |grep atop
  867919      1  13  ffff94c9e4e262a0  UN   0.1  142892 125964  atop

crash> bt 867919    //atop因为获取rwsem而卡住，同iotop一致
PID: 867919  TASK: ffff94c9e4e262a0  CPU: 13  COMMAND: "atop"
 #0 [ffff94ca23467cb8] __schedule at ffffffffb31858fa 
 #1 [ffff94ca23467d40] schedule at ffffffffb3185da9 
 #2 [ffff94ca23467d50] rwsem_down_read_failed at ffffffffb3187795 
 #3 [ffff94ca23467dd8] call_rwsem_down_read_failed at ffffffffb2d96748 
 #4 [ffff94ca23467e28] down_read at ffffffffb31850b0 
 #5 [ffff94ca23467e40] proc_pid_cmdline_read at ffffffffb2cc9b32 
 #6 [ffff94ca23467ed8] vfs_read at ffffffffb2c4d06f 
 #7 [ffff94ca23467f08] sys_read at ffffffffb2c4dedf 
 #8 [ffff94ca23467f50] tracesys at ffffffffb3193166  (via system_call)
    RIP: 00007f22cccd69a0  RSP: 00007ffedbfb2d58  RFLAGS: 00000246
    RAX: ffffffffffffffda  RBX: 000000000214f010  RCX: ffffffffffffffff
    RDX: 0000000000000400  RSI: 00007f22cdd56000  RDI: 0000000000000007
    RBP: 00007f22ccfab380   R8: ffffffffffffffff   R9: 0000000000000000
    R10: 0000000000000022  R11: 0000000000000246  R12: 00007f22ccfaa838
    R13: 00007f22ccfaa838  R14: 0000000000000d70  R15: 00007f22ccfab5a8
    ORIG_RAX: 0000000000000000  CS: 0033  SS: 002b

为什么会rwsem获取不到信号量呢？通过堆栈和反汇编，找到堆栈的值（获取方法比较复杂）

代码语言：txt复制
crash> bt 607982

PID: 607982  TASK: ffff94cc443b20e0  CPU: 15  COMMAND: "iotop"
 #0 [ffff94c7ec177cb8] __schedule at ffffffffb31858fa 
 #1 [ffff94c7ec177d40] schedule at ffffffffb3185da9 
 #2 [ffff94c7ec177d50] rwsem_down_read_failed at ffffffffb3187795 
 #3 [ffff94c7ec177dd8] call_rwsem_down_read_failed at ffffffffb2d96748 
 #4 [ffff94c7ec177e28] down_read at ffffffffb31850b0 
 #5 [ffff94c7ec177e40] proc_pid_cmdline_read at ffffffffb2cc9b32 
 #6 [ffff94c7ec177ed8] vfs_read at ffffffffb2c4d06f 
 #7 [ffff94c7ec177f08] sys_read at ffffffffb2c4dedf 
 #8 [ffff94c7ec177f50] tracesys at ffffffffb3193166  (via system_call)
    RIP: 00007ff51452d9a0  RSP: 00007ffc4fac8f78  RFLAGS: 00000246
    RAX: ffffffffffffffda  RBX: 0000000002fc5570  RCX: ffffffffffffffff
    RDX: 0000000000001000  RSI: 0000000001cde844  RDI: 0000000000000006
    RBP: 00007ff514802380   R8: ffffffffffffffff   R9: 0000000000000000
    R10: 0000000000000022  R11: 0000000000000246  R12: 0000000000001000
    R13: 0000000000000d70  R14: 00007ff514801838  R15: 0000000001cde844
    ORIG_RAX: 0000000000000000  CS: 0033  SS: 002b

crash> 
crash> whatis down_read
void down_read(struct rw_semaphore *);
crash> 
crash> rd ffff94c7ec177dd8 -e ffff94c7ec177e28
ffff94c7ec177dd8:  ffffffffb2d96748 0000000000000000   Hg..............
ffff94c7ec177de8:  0000000000000246 00000000000050ad   F........P......
ffff94c7ec177df8:  ffffe885c50fed40 ffffffffb348d58f   @.........H.....
ffff94c7ec177e08:  ffff94c7ec177fd8 0000000000000000   ................
ffff94c7ec177e18:  ffff94c362f225f8 ffff94c7ec177e38   .%.b....8~......//ffff94c362f225f值
crash> 

crash> struct rw_semaphore ffff94c362f225f8
struct rw_semaphore {
  {
    count = {
      counter = -4294967295
    }, 
    __UNIQUE_ID_rh_kabi_hide1 = {
      count = -4294967295
    },
    {<No data fields>}
  }, 
  wait_lock = {
    raw_lock = {
      val = {
        counter = 0
      }
    }
  }, 
  osq = {
    tail = {
      counter = 0
    }
  },
  wait_list = {
    next = 0xffff94cd30223d90
  }, 
  owner = 0xffff94cb018d5233    //owner所属值
}

得到该值后,该owner所属的进程是一个PID为1387203的Java进程，该进程可以看到是jbd2处理transaction的过程中出现了异常：进程在等待Journal Transaction Commit

代码语言：txt复制
crash> bt 0xffff94cb018d5230

PID: 1387203  TASK: ffff94cb018d5230  CPU: 30  COMMAND: "java"
 #0 [ffff94cb018cb8f8] __schedule at ffffffffb31858fa 
 #1 [ffff94cb018cb988] schedule at ffffffffb3185da9 
 #2 [ffff94cb018cb998] wait_transaction_locked at ffffffffc04f8085  [jbd2]
 #3 [ffff94cb018cb9f0] add_transaction_credits at ffffffffc04f8368  [jbd2]
 #4 [ffff94cb018cba50] start_this_handle at ffffffffc04f85e1  [jbd2]
 #5 [ffff94cb018cbae8] jbd2__journal_start at ffffffffc04f8a93  [jbd2]
 #6 [ffff94cb018cbb30] __ext4_journal_start_sb at ffffffffc067d679  [ext4]
 #7 [ffff94cb018cbb70] ext4_dirty_inode at ffffffffc065106a  [ext4]
 #8 [ffff94cb018cbb90] __mark_inode_dirty at ffffffffb2c7e55d 
 #9 [ffff94cb018cbbc8] update_time at ffffffffb2c6aec9 
#10 [ffff94cb018cbbf8] file_update_time at ffffffffb2c6afb0 
#11 [ffff94cb018cbc38] ext4_page_mkwrite at ffffffffc06512bd  [ext4]
#12 [ffff94cb018cbc90] do_page_mkwrite at ffffffffb2bee06a 
#13 [ffff94cb018cbd10] do_wp_page at ffffffffb2bf1b27 
#14 [ffff94cb018cbdb8] handle_mm_fault at ffffffffb2bf5e82 
#15 [ffff94cb018cbe80] __do_page_fault at ffffffffb318d653 
#16 [ffff94cb018cbef0] trace_do_page_fault at ffffffffb318da26 
#17 [ffff94cb018cbf30] do_async_page_fault at ffffffffb318cfa2 
#18 [ffff94cb018cbf50] async_page_fault at ffffffffb31897a8 
    RIP: 00007fba56cf230e  RSP: 00007fba29de7da0  RFLAGS: 00010216
    RAX: 0000000002b94888  RBX: 00007fba57e98420  RCX: 0000000000000002
    RDX: 00007fba566540e0  RSI: 00007fba5735ffec  RDI: 00007fba5001eb90
    RBP: 00007fba29de7db0   R8: 0000000000000003   R9: 0000000000000032
    R10: 00000000000073b2  R11: 000b1a759ff75bcd  R12: 0000000000000008
    R13: 00007fba50020d90  R14: 0000000000000002  R15: 0000000000000001
    ORIG RAX: ffffffffffffffff  CS: 0033  SS: 002b

crash> 
crash> task_struct.sched_info 0xffff94cb018d5230
  sched_info = {
    pcount = 59975484, 
    run_delay = 1415791995, 
    last_arrival = 4453057373285825, 
    last_queued = 0
  }

crash> log |grep sysrq
[4653942.472357] IP: [<ffffffffb2e738f6>] sysrq_handle_crash 0x16/0x20
[4653942.472357] RIP: 0010:[<ffffffffb2e738f6>]  [<ffffffffb2e738f6>] sysrq_handle_crash 0x16/0x20
[4653942.472357]  [<ffffffffb2e7411d>] __handle_sysrq 0x10d/0x170
[4653942.472357]  [<ffffffffb2e74533>] sysrq_filter 0x363/0x390
[4653942.472357] RIP  [<ffffffffb2e738f6>] sysrq_handle_crash 0x16/0x20

正在处理Transaction Commit的容器进程788315因为pod cgroup内存耗尽导致分配不到内存卡住，之所以卡住而不是触发oom kill的原因是进程788315触发了oom，但是__getblk这里因为满足不了退出死循环条件导致进程无法退出到handle_mm_fault调用oom kill：

堆栈分析堆栈分析
block函数block函数

其所在的容器pod id为：pod2e7583c6-a4bc-4b24-8b2b-5bd1d86c576b

容器所属容器所属

至此，触发机器hung死的原因是pod mobile-mfanxing-home-6747c88777-hl7vj内存使用超过mem limit触发了centos7内核bug。社区上游有看到类似的case：https://bugs.centos.org/view.php?id=17982。

社区bug说明社区bug说明

该bug当前为被修复，其触发的根因是在ext4文件系统下，因为cgroup oom而导致内核journnal模块调用时触发死锁，导致内核文件系统卡死。读IO高的原因是什么呢？至今依旧是个谜，由于内核hung死之后，系统内部无法检测到IO的来由。

3. 案发重现

该问题能否通过复现方式验证呢？带着这个疑问，我们在云加社区找到了一篇相同的文章，由 OOM 引发的 ext4 文件系统卡死 ,并且提供了验证复现的方法，不过ext4-repro-with-write二进制文件有点问题，需要重新编译。通过复现的方法验证内核bug，采用3个场景进行测试验证：

  • 使用3.10内核，文件系统为ext4，验证bug是否能复现
  • 使用3.10内核，文件系统为xfs，验证xfs能否修复此bug
  • 使用4.16内核，文件系统为ext4，验证高版本内核是否修复

3.1 准备复现环境

环境说明：准备好测试环境

|环境 |腾讯云CVM |

|:--|

|配置信息 |16核32G，SA3.4XLARGE3 |

|磁盘信息 |高性能云盘100G，vdb |

|操作系统 |CentOS Linux release 7.7.1908 (Core) |

|内核版本 |3.10.0-1062.18.1.el7.x86_64 |

此次环境复现一共包含有3个文件：

  • ext4-repro-with-multiple-cgroup.sh，总入口调用fio和触发cgroup oom
  • ext4-repro-with-write,打开 ext4 文件系统上的文件，并不断地对该文件做写操作，过程中会涉及到 ext4 inode 内部的一些内存分配操作
  • ext4-repro-with-write.go,源码程序文件，不需要使用，其定义了/usr/share/fxck路径，需要把数据盘挂载至该路径测试

脚本的功能如下：

  • 准备一个测试程序 ext4-repro-with-write，打开 ext4 文件系统上的文件，并不断地对该文件做写操作，过程中会涉及到 ext4 inode 内部的一些内存分配操作；测试的 cgroup 中只有这一类进程，OOM Kill 的只可能是这类进程；
  • 创建 10 个 cgroup，每个的内存限制为 100 MB；
  • 对于每个 cgroup，创建 30 个 ext4-repro-with-write 进程；

ext4-repro-with-multiple-cgroup.sh脚本内容如下：

代码语言：txt复制
cat ext4-repro-with-multiple-cgroup.sh 

#!/usr/bin/bash


echo "clean up"
systemctl stop ext4-repro-cgroup*-*

mkdir /usr/share/fxck/ -p
cp ext4-repro-with-write /usr/share/fxck/ext4-repro-with-write
chmod  x /usr/share/fxck/ext4-repro-with-write

for i in `seq 1 10`;do
    echo "prepare cgroup"
    cat << EOF > /etc/systemd/system/system-fio${i}.slice
[Unit]
Description=zbs Slice
Before=slices.target
Wants=system.slice
After=system.slice
EOF

    mkdir  /etc/systemd/system/system-fio${i}.slice.d -p
    cat << EOF >  /etc/systemd/system/system-fio${i}.slice.d/50-MemoryLimit.conf
[Slice]
MemoryLimit=104857600
EOF

    systemctl daemon-reload
    systemctl restart system-fio${i}.slice
    systemctl status system-fio${i}.slice

echo "prepare fio data path"
TEST_PATH="/usr/share/ext4-repro"

mkdir $TEST_PATH


for j in `seq 1 30`;do
    mkdir /etc/systemd/system/ext4-repro-cgroup${i}-${j}.service.d/ -p 
    cat << EOF > /etc/systemd/system/ext4-repro-cgroup${i}-${j}.service.d/cgroup.conf
    [Service]
    Slice=system-fio${i}.slice
EOF



    cat << EOF > /usr/lib/systemd/system/ext4-repro-cgroup${i}-${j}.service
    [Unit]
    After=network.target、
    
    [Service]
    ExecStart=/usr/share/fxck/ext4-repro-with-write
    Restart=always
    RestartSec=3s
    
    [Install]
    WantedBy=multi-user.target

EOF

done

pushd /usr/lib/systemd/system

systemctl restart ext4-repro-cgroup${i}*.service

popd
done

ext4-repro-with-write.go内容如下：

代码语言：txt复制
cat ext4-repro-with-write.go 

package main


import (

"flag"
"fmt"
"math/rand"
"os"
"strconv"
"time"
)



const letterBytes = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ"

const path = "/usr/share/fxck/"



func RandStringBytes(n int) string {
b := make([]byte, n)
for i := range b {
b[i] = letterBytes[rand.Intn(len(letterBytes))]
}

return string(b)

}



func createFileName(path string) string {
name, _ := os.Hostname()
fn := path   name   strconv.Itoa(int(time.Now().Unix()))   RandStringBytes(8)
return fn
}



func w(path string) {
fn := createFileName(path)
fmt.Println(fn)
f, _ := os.OpenFile(fn, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
fmt.Println(f)
defer os.Remove(fn)

defer f.Close()

for {
s := RandStringBytes(10)
_, _ = f.WriteString(s)
f.Sync()

}

}


func main() {
path := flag.String("path", "/usr/share/ext4-repo/", "a string")
flag.Parse()

fmt.Println("path:", *path)
go w(*path)

for {
time.Sleep(time.Duration(1) * time.Second)

}
}

将数据盘/dev/vdb格式化为ext4文件系统，并将其挂载至/usr/share/fxck目录

代码语言：txt复制
mkfs.ext4 -f /dev/vdb 
[root@VM-7-9-centos ~]# mount /dev/vdb /usr/share/fxck/
[root@VM-7-9-centos ~]# df -T /dev/vdb 

文件系统       类型     1K-块  已用     可用 已用% 挂载点
/dev/vdb       ext4 103080888 83420 97738204    1% /usr/share/fxck

3.2 复现案发现场

运行脚本ext4-repro-with-multiple-cgroup.sh开始执行测试

代码语言：txt复制
bash ext4-repro-with-multiple-cgroup.sh

运行脚本后，此时可以看到系统已经开了若干个ext4-repro-with进程，并且CPU负载会瞬间飙升

复现进程复现进程

查看/var/log/message日志可以看到有频繁的OOM现象

复现OOM复现OOM

观察进程此时可以看到jbd2/vdb-8进程处于僵死状态（D）

jbd2进程僵死jbd2进程僵死
出现夯死现象出现夯死现象

此时查看系统盘的监控，可以发现磁盘只读出现瞬间突增的现象，与案发现场现象完全吻合 ，由此可以进一步确认该bug是ext4文件系统在内核频繁oom而触发的内核bug。

IO读被打满IO读被打满

出现异常后，操作系统处于hung死状态，机器无法登陆，只能通过强制重启的方式回复系统，如果如上脚本测试，约10-30min左右即可复现，复现频次高。

3.3 更换文件系统

导致系统hung死的原因是内核在提交Journal Transaction Commit时卡住，Journal模块是Linux kernel中同个通用模块，为ext4等文件系统所用，客户IDC环境采用xfs文件系统，并为出现过因OOM而引发的内核bug。

如果文件系统是xfs会出现相同的问题么，带着这个问题，我们继续进行验证，采用相同的测试脚本，将文件系统更换为xfs之后，看是否还会出现异常现象，更换数据盘的文件系统格式

代码语言：txt复制
# systemctl stop ext4-repro-cgroup*-*

# umount  /dev/vdb 

# mount /dev/vdb /usr/share/fxck/

# df -T /usr/share/fxck/

文件系统       类型     1K-块  已用      可用 已用% 挂载点

/dev/vdb     xfs  104806400 32992 104773408    1% /usr/share/fxck

准备好文件系统系统之后，重新运行测试脚本

代码语言：txt复制
# bash ext4-repro-with-multiple-cgroup.sh

重新运行脚本会提示部分报错，由于之前已经存在systemd服务，可以忽略报错，通过ps可以看到ext4-repro-with相关的进程已经在系统中运行，同时vdb相关的进程状态也未出现僵死状态

https://km.woa.com/files/photos/pictures/202109/1631942107_84_w3078_h990.png

更换xfs情况更换xfs情况

环境经过1周的时间测试，更换xfs文件系统之后测试发现，频繁OOM场景下不会触发内核bug导致系统夯死。相比于ext4 10min左右即可复现问题，效果显著，进一步可以说明该bug触发的场景。

3.4 更换内核版本

该内核bug是在3.10内核触发，因此更换内核也是一种解决方案，cgroup容器推广之后大范围开始使用，因此相较于更新版本的内核，3.10内核在处理cgroup oom的场景下相对没有那么健壮。根据线上客户实际运营经验来看，出现过不少因为cgroup oom而引发的bug，对于此类问题，根本的解决方案是升级至更新的内核版本，强烈推荐使用TencentOS内核。

将上述的操作系统更换为TencentOS内核，将文件系统重新更换为ext4进行测试,本文采用TencentOS Server 2.4系统，其内核为4.14.105版本，可以通过重装的方式更换：

https://km.woa.com/files/photos/pictures/202109/1631942216_13_w1568_h1624.png

更换tencentos内核更换tencentos内核

重新将磁盘格式更换为ext4文件系统并挂载，重新运行测试脚本

代码语言：txt复制
mkfs.ext4 /dev/vdb
mkdir /usr/share/fxck/
mount /dev/vdb /usr/share/fxck/
# df -T /dev/vdb 
文件系统       类型     1K-块  已用     可用 已用% 挂载点
/dev/vdb       ext4 103080888 80300 97741324    1% /usr/share/fxck

bash ext4-repro-with-multiple-cgroup.sh

更换TencentOS内核之后，测试一周后均无法复现内核bug，4.x的内核相比于3.10的内核，处理OOM场景更加健壮，可以说明在4.x之后的内核版本均已经修复该问题。

4. 真相大白

经过内核层面的分析以及环境复现和验证，真相终于浮出水面，可以得出如下结论：

  • 3.10内核使用ext4文件系统，频繁oom触发内核bug；
  • 3.10内核使用xfs文件系统，频发oom不会触发内核bug；
  • TencentOS内核使用ext4文件系统，不会触发内核bug。

同时通过复现验证，可以知道：磁盘读高IO是由于内核夯死而引起，复现现象与实际故障一致！

5. 最佳实践

通过上面的分析和验证可知，客户当前该问题可以通过两种方法解决：

  • 将ext4文件系统更换为xfs；
  • 将操作系统内核升级至4.x版本

Cgroup自动docker出现之后逐步发扬光大，容器主要在3.10内核中开始大规模使用，相比于高版本的内核，cgroup内核代码处理并不太健壮。与之同时，容器环境设置了cgroup内存limits后，容器超过内存限制后OOM往往是常见的现象，因此出现OOM的概率相比于非容器环境会更加频繁。根据腾讯云线上的容器环境的运维，3.10内核出现内核问题较多，如下是一些同学整理的文章：

  • cgroup OOM引发内核死锁问题分析
  • cgroup oom引发容器重建问题分析
  • 由 OOM 引发的 ext4 文件系统卡死
  • 容器cgroup引发的内存泄漏问题分析
  • iptables内核bug引发节点偶发宕机（文章暂未记录），目前已在等多个大客户环境中遇到，如有兴趣可以联系我获取资料。

当下是一个云原生的时代，kubernetes是当下不二的选择，越来越多的应用会选择运行在kubernetes环境上，容器的底层实现深度依赖于内核的众多特性。例如，overlay 文件系统、namespace 及 cgroup 等。因此内核的功能和稳定性，在很大程度上决定了整个容器 PaaS 平台的功能和稳定性。对于腾讯云上如何选择master和node节点的内核呢？强烈推荐TencentOS内核。

Tencent Linux 是腾讯官方运营的 Linux 版本，参考官网说明 。由腾讯专门的内核维护，专门针对云环境下优化的内核，且遇到问题会有专门的团队维护，相比于社区的修复速度可以大大提高，其优化的一些性能：

  • 解决 IPVS 模式高并发场景下，连接复用引发连接异常的问题（#81775）。
  • 解决 IPVS 模式在高配节点（核数多）下 IPVS 规则过多引发网络毛刺的问题。
  • 解决在容器密集场景下（单节点上容器数量较多），cAdvisor 读取 memcg 陷入内核态过久引发网络毛刺的问题。
  • 解决大 Pod（占用核数多，单核占用高）在高配节点（核数多）场景下，CPU 负载均衡引发网络毛刺的问题。
  • 解决高并发场景下的 TCP 连接监控（例如单独部署 cAdvisor 配置监控 TCP 连接）引发网络周期性抖动问题。
  • 优化网络收包软中断，提升网络性能。

相比于Linux内核上游社区，TencentOS内核具有以下优势：

  • 提供热补丁更新，避免更换内核造成业务损伤；
  • TKE集群中已经大量部署及验证；
  • 针对不同容器客户进行性能优化沉淀，规避大部分已知问题；
  • 基于开源代码进行功能、性能优化，代码本身也对外开源：https://github.com/Tencent/TencentOS-kernel。

写在最后

内核问题分析是个复杂而艰难的问题，作者全程参与了该问题的排查，抱着学习vmcore的心态，整理和分享处理该问题的过程，从内核问题分析到问题验证，给予容器内核选型参考和建议。

容器服务 kubernetes 云服务器 容器内核 vmcore crash

0 人点赞