记一个藏得很深的bug
看了别人写的内核bug修复历程，心血来潮也想写点什么，最近一直在开发公司的四代机的项目，修了不少bug但大都是关于dpdk与vdpa的。还好找到了一个存货，两个月前修了一个内核bug并且做了记录。其实我修bug从来不做记录，因为修得多了也没啥兴趣了，就是枯燥的半体力劳动，啥体力劳动？手指运动呗：）。但，这个bug是个例外，我做了笔记还记得很详细，为啥呢？哈哈，因为它让我推翻了我自己的结论，就像一个法官断错了案，那个耿耿于怀啊。下面故事开始了：
---------------------------------------------------------------------------------------------------------------------------
公有云线上环境的一个节点踏踏实实勤勤恳恳工作一年多以后突然宕机了！coredump显示处于UN状态的进程有385个。对这385个进程按执行顺序做个排序，有6个进程hang了6天多的时间。
[ 0 19:06:45.856] [UN] PID: 142120 TASK: ffff883990f1dee0 CPU: 3 COMMAND: "worker"
[ 0 19:06:45.859] [UN] PID: 122914 TASK: ffff880884a03f40 CPU: 34 COMMAND: "worker"
[ 0 19:06:45.855] [UN] PID: 63190 TASK: ffff885f6d139fa0 CPU: 1 COMMAND: "worker"
[ 0 19:06:46.009] [UN] PID: 1226 TASK: ffff88069aa3cf10 CPU: 16 COMMAND: "mn_agent_app"
[ 0 19:06:46.090] [UN] PID: 132079 TASK: ffff885f7db38000 CPU: 12 COMMAND: "xcgroup"
[ 6 08:16:45.871] [UN] PID: 120034 TASK: ffff882f64f9bf40 CPU: 44 COMMAND: "worker"
[ 6 08:16:45.866] [UN] PID: 120033 TASK: ffff883a91e93f40 CPU: 42 COMMAND: "worker"
[ 6 08:32:10.598] [UN] PID: 62675 TASK: ffff885f64e4eeb0 CPU: 0 COMMAND: "worker"
[ 6 08:32:11.765] [UN] PID: 84468 TASK: ffff88048f3b4f10 CPU: 3 COMMAND: "worker"
[ 6 08:32:13.288] [UN] PID: 62674 TASK: ffff8839f1b03f40 CPU: 0 COMMAND: "worker"
[ 6 08:32:13.290] [UN] PID: 78947 TASK: ffff885f6e570fd0 CPU: 20 COMMAND: "worker"
先看等待最长进程78947的堆栈，它在等待一个rw_semaphore等了6天！
crash> bt 78947
PID: 78947 TASK: ffff885f6e570fd0 CPU: 20 COMMAND: "worker"
#0 [ffff88393e4837f8] __schedule at ffffffff816b3ac4
#1 [ffff88393e483880] schedule at ffffffff816b40e9
#2 [ffff88393e483890] rwsem_down_read_failed at ffffffff816b571d
#3 [ffff88393e483918] call_rwsem_down_read_failed at ffffffff81338088
#4 [ffff88393e483968] down_read at ffffffff816b3200
#5 [ffff88393e483980] xfs_ilock at ffffffffc048adac [xfs]
#6 [ffff88393e4839b0] xfs_ilock_data_map_shared at ffffffffc048ae20 [xfs]
#7 [ffff88393e4839c8] __xfs_get_blocks at ffffffffc0472a4e [xfs]
#8 [ffff88393e483a60] xfs_get_blocks_direct at ffffffffc04734a7 [xfs]
#9 [ffff88393e483a70] do_blockdev_direct_IO at ffffffff812465b6
#10 [ffff88393e483ca8] __blockdev_direct_IO at ffffffff812476e5
#11 [ffff88393e483ce0] xfs_file_dio_aio_write at ffffffffc047f318 [xfs]
#12 [ffff88393e483d90] xfs_file_aio_write at ffffffffc047f8e2 [xfs]
#13 [ffff88393e483de8] do_sync_write at ffffffff81204c43
#14 [ffff88393e483ec0] vfs_write at ffffffff81205720
#15 [ffff88393e483f00] sys_pwrite64 at ffffffff812066f2
#16 [ffff88393e483f50] system_call_fastpath at ffffffff816c0715
RIP: 00007f6c02cbdfd3 RSP: 00007f6be79b4860 RFLAGS: 00000282
RAX: 0000000000000012 RBX: 0000000000000000 RCX: ffffffffffffffff
RDX: 0000000000001000 RSI: 00007f69adc9d000 RDI: 0000000000000016
RBP: 0000557b5b6fbf40 R8: 0000000000000000 R9: 0000000000000001
R10: 0000000236581000 R11: 0000000000000293 R12: 00007f69adc9d000
R13: 0000557b593d87b8 R14: 00007f6be79b5700 R15: 0000000000000032
ORIG_RAX: 0000000000000012 CS: 0033 SS: 002b
等待的位置在rwsem_down_read_failed，rwsem_down_read_failed代码片段：
257 /* wait to be given the lock */
258 while (true) {
259 set_task_state(tsk, TASK_UNINTERRUPTIBLE);
260 if (!waiter.task)
261 break;
262 schedule();
263 }
264
265 __set_task_state(tsk, TASK_RUNNING);
可以看到78947在不可中断的睡眠状态等待被唤醒，并且唤醒函数要清空其waiter.task才能使78947获得锁并退出等待状态。
从堆栈上获取到此信号量的信息如下：
xfs_inode.i_lock ffff885f6c260f00 -x
i_lock = {
mr_lock = {
{
count = {
counter = 0xffffffff00000001
},
__UNIQUE_ID_rh_kabi_hide4 = {
count = 0xffffffff00000001
},
{<No data fields>}
},
wait_lock = {
raw_lock = {
val = {
counter = 0x0
}
}
},
osq = {
tail = {
counter = 0x0
}
},
wait_list = {
next = 0xffff8838cc837a00
},
owner = 0x1
}
}
上面的信息告诉我们此信号量上目前是读者持有锁的状态，并且有进程在等待。osq.tail=0表明等待的进程已经进入等待队列，非自旋状态。
crash> list 0xffff8838cc837a00 rwsem_waiter.list -s rwsem_waiter
ffff8838cc837a00
struct rwsem_waiter {
list = {
next = 0xffff8802cd8c3a00,
prev = 0xffff8833a684fa00
},
task = 0xffff8839f1b03f40,
type = RWSEM_WAITING_FOR_WRITE
}
ffff8802cd8c3a00
struct rwsem_waiter {
list = {
next = 0xffff8839bfe03ac0,
prev = 0xffff8838cc837a00
},
task = 0xffff88048f3b4f10,
type = RWSEM_WAITING_FOR_WRITE
}
ffff8839bfe03ac0
struct rwsem_waiter {
list = {
next = 0xffff880a8bbab910,
prev = 0xffff8802cd8c3a00
},
task = 0xffff885f64e4eeb0,
type = RWSEM_WAITING_FOR_WRITE
}
ffff880a8bbab910
struct rwsem_waiter {
list = {
next = 0xffff8833a684fa00,
prev = 0xffff8839bfe03ac0
},
task = 0xffff882f64f9bf40,
type = RWSEM_WAITING_FOR_READ
}
ffff8833a684fa00
struct rwsem_waiter {
list = {
next = 0xffff8838cc837a00,
prev = 0xffff880a8bbab910
},
task = 0xffff883a91e93f40,
type = RWSEM_WAITING_FOR_WRITE
}
打印wait_list等待队列证实了上面的分析，4个写者1个读者。但是这个等待队列一共有5个，分别对应之前等了6天的6个进程中的5个，唯独没有78947号进程。按理说78947号进程等待时间最长应该在等待队列中的第一项。
crash> rwsem_waiter ffff88393e4838b0 -x
struct rwsem_waiter {
list = {
next = 0xdead000000000100,
prev = 0xdead000000000200
},
task = 0x0,
type = RWSEM_WAITING_FOR_READ
}
从78947的堆栈上找到它的链表结构rwsem_waiter。可以看到0xdead这个特殊标记，这种标记只在slist_del中设置，表明78947已经从等待队列中被释放，释放的流程在rwsem_wake-> __rwsem_mark_wake。
rwsem_wake代码片段：
588 if (!slist_empty(&sem->wait_list))
589 __rwsem_mark_wake(sem, RWSEM_WAKE_ANY, &wake_q);
590
591 raw_spin_unlock_irqrestore(&sem->wait_lock, flags);
592 wake_up_q(&wake_q);
__rwsem_mark_wake代码片段：
188 while (!slist_empty(&sem->wait_list)) {
189 struct task_struct *tsk;
190
191 waiter = list_entry(sem->wait_list.next, typeof(*waiter), list);
192
193 if (waiter->type == RWSEM_WAITING_FOR_WRITE)
194 break;
195
196 woken++;
197 tsk = waiter->task;
198
199 wake_q_add(wake_q, tsk);
200 slist_del(&waiter->list, &sem->wait_list);
201 /*
202 * Ensure that the last operation is setting the reader
203 * waiter to nil such that rwsem_down_read_failed() cannot
204 * race with do_exit() by always holding a reference count
205 * to the task to wakeup.
206 */
207 smp_store_release(&waiter->task, NULL);
208 }
由此我们可以推断如下场景，一个写者完成工作释放读写锁并唤醒等待的读者，78947是其中之一。78947先在第200行被摘链，然后在207行被清掉waiter->task，最后在592行被唤醒。然后回到rwsem_down_read_failed的代码，while循环检查waiter->task==0于是退出循环，从c语言级别看这个逻辑没有问题。从指令级别看虽然清0发生在唤醒之前，但是在处理器级别因为乱序执行这个顺序是不能保证的。对此在wake_up_q里有一段评论专门描述这个情况：
/*
* wake_up_process() implies a wmb() to pair with the queueing
* in wake_q_add() so as not to miss wakeups.
*/
wake_up_process(task);
在wake_up_process里能找到smp_mb__before_spinlock()，这样这个漏洞被堵上。
综上从软件层面看上面的bug不应该发生，但是从现实场景看，78947被曾经被唤醒，然后又阻塞在循环里，那只有一个可能waiter->task在当时判断为非0状态。对此我怀疑是处理器硬件的一次偶发性的不稳定问题，比如cache一致性在极端情况下没有得到保证，或者寄存器存在bit flip的情况。
另外这个节点在2019-08-09报过一次cpu的硬件问题，可能此节点本身有一定的不稳定性。
[7954068.969548] mce: [Hardware Error]: CPU 7: Machine Check Exception: 5 Bank 10: be200000000a0405
[7954068.970278] mce: [Hardware Error]: RIP !INEXACT! 10:<ffffffff816b6347> {intel_idle+0xf7/0x1d5}
[7954068.970973] mce: [Hardware Error]: TSC 47592635ce47e0 ADDR 4e831e90c0 MISC a44aa08059c086
[7954068.971674] mce: [Hardware Error]: PROCESSOR 0:50654 TIME 1565363513 SOCKET 1 APIC 46 microcode 2000050
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
以上是我当时整个分析过程，没过两星期，打脸了！
后续进展（2020.8.3）：
最近ls /export死锁问题在不同的主机上报了若干次，说明这个bug不是硬件问题导致，以上分析没有正确定位bug的根因。总结之前的分析并进一步分析所有新coredump，确认本bug与链接https://lore.kernel.org/lkml/1543495830-2644-1-git-send-email-xieyongji@baidu.com/ 中描述的问题几乎一样，基本可以确定是同一个问题。以上链接中的描述有个不对的地方在下面更正，细心的你发现是哪里了吗？
Imaging this:Thread 1 Thread 2down_write();
rwsem_down_read_failed()raw_spin_lock_irq(&sem->wait_lock);list_add_tail(&waiter.list, &wait_list);raw_spin_unlock_irq(&sem->wait_lock);__up_write();rwsem_wake();__rwsem_mark_wake();wake_q_add();list_del(&waiter->list);waiter->task = NULL;while (true) {set_current_state(TASK_UNINTERRUPTIBLE);if (!waiter.task) // truebreak;}__set_current_state(TASK_RUNNING);Now Thread 1 is queued in Thread 2's wake_q without sleeping. Then
Thread 1 call rwsem_down_read_failed() again because Thread 3
hold the lock, if Thread 3 tries to queue Thread 1 before Thread 2
do wakeup, it will fail and miss wakeup:Thread 1 Thread 2 Thread 3down_write();
rwsem_down_read_failed()raw_spin_lock_irq(&sem->wait_lock);list_add_tail(&waiter.list, &wait_list);raw_spin_unlock_irq(&sem->wait_lock);__rwsem_mark_wake();wake_q_add();wake_up_q();while (true) {set_current_state(TASK_UNINTERRUPTIBLE);if (!waiter.task) // falsebreak;schedule();} waiter->task = NULL; wake_up_q(&wake_q);
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
故事讲完了，很意外，表面上的xfs的bug结果是semaphore的bug，找到根因的方式也很意外，我更惊讶于patch作者是怎么推理出这么一个极端中的极端场景，要知道这个bug重现是偶发性的，三个线程中的代码片段要满足特定的时序，只能送上两字：佩服！
因为线上环境的特殊性，kpatch不能打到lib库上，导致这个修复还没有上线，所以后续我又开发了解锁方案，即针对这个bug的特殊性，把死锁解开恢复正常运行状态，我在内部文档中称其为手术式的修复，而kpatch就叫预防针式的修复。
------
然而。。这一切目前还没有得到验证，bug兄是不是还有“惊喜”给我，让我们拭目以待吧
记一个藏得很深的bug相关推荐
- 消格子时一个很深的bug的修复纪录
环境: cocos2d-x 2.2.2 jsb 条件:当快速在格子中来回拖拽选取时,会一直在计算指尖和格子的真实区域是否碰撞, 报错:touchMOve时由于不停的调用BOxItem的getVali ...
- 如何在自己开发的日程管理页面插入提醒功能_微信中6个藏得很深但却很有用的功能...
我们每天都会用微信,但是有些功能却不知道它的存在,究其原因是因为这些功能的使用频率不高,所以产品设计者把他们放到了比较深的层级中,但是在一些特定的情况下,这些功能又好用到爆,今天作者就来分享几个这样的 ...
- 记一个SwipeMenuListView侧滑删除错乱的Bug
做侧滑删除网上有很多方案,比如重写Listview实现滑动的监听,今天说下一个SwipeListView,这个是之前一个朋友在网上开源的一个封装组件,能够适用于多种情况,项目地址:https://gi ...
- 藏得很深！三分钟扫盲SD卡
SD SD卡(secure digital card)是SD卡协会开发的低成本,非易失性存储卡格式(相比较于RAM,SD卡掉电数据不丢失): 随着本世纪电子技术的高速发展,对于这种中等型号,节能.节省 ...
- 抓到Netty一个隐藏很深的内存泄露Bug | 详解Recycler对象池的精妙设计与实现
本系列Netty源码解析文章基于 4.1.56.Final版本 最近在 Review Netty 代码的时候,不小心用我的肉眼抓到了一个隐藏很深很深的内存泄露 Bug. 于是笔者将这个故事-哦不 -事 ...
- nvd3使用(1)——多线图中的一个很隐蔽的bug
d3是一个非常强大的以数据驱动的基础图形库,其中封装了一系列的图形转化变形处理操作,欲知其强大在哪里,强大到什么地步,请参考 http://d3js.org 和 https://github.com/ ...
- 遇到一个macOS下malware中毒很深的网友，安装的恶意软件MyCouponsmart、SearchMine.AnySearch、Advanced Mac Cleaner等真多！
前言: Foreword: 最近一段时间很久没有收到网友的求助了,不知道是因为觉得寻求帮助麻烦,还是因为最近疫情的原因,恶意软件活动的少了.我还是希望是后者导致的吧,如果是前者,那我只能说自己加个好友 ...
- Dahua Lin是香港中文大学汤晓鸥教授的高徒，在计算机视觉/机器学习方面有很深的造诣。他在自己的主页上有一个推荐书表，值得大家作为参考。 全英文版的，感觉到与国际接轨的压力了！！！
Dahua Lin是香港中文大学汤晓鸥教授的高徒,在计算机视觉/机器学习方面有很深的造诣.他在自己的主页上有一个推荐书表,值得大家作为参考. 全英文版的,感觉到与国际接轨的压力了!!! Recomme ...
- 一个由服务器时区引发的Bug
太阳照常升起,在每个需要挤公交车上班的日子里,即使窗外早已大雨如注.想来只有在周末,太阳会陪着我一起起床,所谓睡觉睡到自然醒,在雨天里保持晴天的心情,相当大的程度上,是因为今天不必上班.因此,一周 ...
- 我是一个硬盘（很感人）
我是一个硬盘. 在一个普普通通的台式机里工作.别人总认为我们是高科技白领,工作又干净又体面,似乎风光得很.也许他们是因为看到洁白漂亮的机箱才有这样的错觉吧.其实象我们这样的小台式机,工作环境狭迫,里面 ...
最新文章
- Uva 11396 爪分解
- 【安全漏洞】Emissary 的SSRF漏洞(CVE-2021-32639)发现过程
- Executor框架、ThreadPoolExecutor、3种常见的线程池
- 八十五、再探希尔排序，桶排序，计数排序和基数排序
- ORACLE TEXT LEXER PREFERENCE（二）
- C语言学习之企业发放的奖金根据利润提成。利润I低于或等于100000元的,奖金可提成10%;
- 我的Python成长之路---第六天---Python基础（18）---2016年2月20日（晴）
- uniapptabbar的高度是多少_【报Bug】uniapp页面底部空出了tabBar的高度
- LSGO软件技术团队与信息1402班开展真人CS活动
- CCD摄像头视场角计算公式
- Linux shell基础（四）正则表达式与grep命令 beta
- Android Studio右下角显示当前branch名称不一致
- CentOS 6.2配置NIS主/从服务器
- 什么是jsp，什么是Servlet？jsp 和Servlet 有什么区别
- 基于javaweb,springboot银行管理系统
- 支付宝-支付API(电脑网站支付)
- VUE连接MQTT即时通讯
- 智能宠物喂食器语音芯片应用设计方案（基于唯创语音芯片WT588E02-8S（C001）功能拓展）
- 有关汽车仪表的LED与LCD识别
- 华为路由器：配置禁止P2P软件下载的示例