即日起在codingBlog上分享您的技术经验即可获得积分,积分可兑换现金哦。

【Linux】【Kernel】BUG: scheduling while atomic相关疑难问题解析

编程语言 vickytong1018 11℃ 0评论

内核模块local_clients用于监听DHCP包,并把主机名字,IP,MAC等信息写到文件/proc/local_clients/local_clients_info,然后webserver解析这个问题,达到显示当前连接到AP的无线客户端主机名称的功能


/tmp # cat /proc/local_clients/local_clients_info


58-7F-57-8B-BC-0D 192.168.0.100 myPhone


现在需要对这个模块进行改进,增加监听DNS报文,确定连接到AP的主机的IP和MAC,结果写入/proc/local_clients/local_clients_info,在用户空间解析这个问题,如果发现存在主机名是未知(UNKNOWN)的条目,则通过用户态程序client_mgmt发NBNS或者MDNS获取主机名。


/tmp # cat /proc/local_clients/local_clients_info


14-CC-20-16-FB-DA 192.168.0.110 UNKNOWN

问题:解析主机名功能实现了,但是跑了大概2个多小时,串口出现异常打印如下:


[ 3419.912000] BUG: scheduling while atomic:client_mgmt/1051/0x00000100


[ 3419.916000] Modules linked in: umac ath_dev(P)ath_rate_atheros(P) ath_hal(P) asf(P) adf(P) athrs_gmac local_clients


[ 3419.928000] Cpu 0


[ 3419.932000] 0:00000000000000010000000000000000[3419.936000] 4 :00000041 832e4500 000000fe 23c637bb


[ 3419.944000] 8:3b9aca00129b0ea4c4ec4e0cfffffff8[3419.948000]12 :fffffffe 592f6656 00000000 004031a4


[ 3419.952000] 16:00000d5b832d0000000010000041a1a8[3419.960000]20 :825c3e98 00000000 0041a1a8 00001000


[ 3419.964000] 24:0000000f800b22c8[3419.972000]28 :825c2000 825c3e50 825c3f10 832d42c0


[ 3419.976000] Hi :000fd669


[ 3419.980000] Lo :2c3458d0


[ 3419.980000] epc :832d42d8 remove_timeout_stas+0x4c/0x8c [local_clients]


[ 3419.988000] Tainted: P


[ 3419.992000] ra :832d42c0 remove_timeout_stas+0x34/0x8c [local_clients]


[ 3420.000000] Status: 1000ff03 KERNEL EXL IE


[ 3420.004000] Cause : 10800400


[ 3420.008000] PrId :00019374 (MIPS 24Kc)

~ #


~ # ps


PID USER VSZ STAT COMMAND


1 root 1512 S init


2 root 0 SW< [kthreadd]


3 root 0 SW< [ksoftirqd/0]


4 root 0 SW< [events/0]


5 root 0 SW< [khelper]


6 root 0 SW< [async/mgr]


7 root 0 SW< [kblockd/0]


8 root 0 SW [pdflush]


9 root 0 SW [pdflush]


10 root 0 SW< [kswapd0]


13 root 0 SW< [mtdblockd]


1059 root 1512 S sh -c cat /proc/local_clients/local_clients_info > /tmp/log.txt


1060 root 1504 D cat /proc/local_clients/local_clients_info


1071 root 3716 S /usr/bin/httpserver


1072 root 1512 S sh -c client_mgmt -s 192.168.0.101


1073 root 1196 D client_mgmt -s 192.168.0.101


1074 root 1512 S sh -c cat /proc/local_clients/local_clients_info > /tmp/log.txt


1075 root 1504 D cat /proc/local_clients/local_clients_info


1164 root 3716 S /usr/bin/httpserver


1165 root 1512 S sh -c client_mgmt -s 192.168.0.101


1166 root 1196 D client_mgmt -s 192.168.0.101


1167 root 1512 S sh -c cat /proc/local_clients/local_clients_info > /tmp/log.txt


1168 root 1504 D cat /proc/local_clients/local_clients_info


1225 root 3716 S /usr/bin/httpserver


1226 root 1512 S sh -c client_mgmt -s 192.168.0.101


1227 root 1196 D client_mgmt -s 192.168.0.101


1228 root 1512 S sh -c cat /proc/local_clients/local_clients_info > /tmp/log.txt


1229 root 1504 D cat /proc/local_clients/local_clients_info


1441 root 3716 S /usr/bin/httpserver


1442 root 1512 S sh -c client_mgmt -s 192.168.0.101


1443 root 1196 D client_mgmt -s 192.168.0.101


1444 root 1512 S sh -c cat /proc/local_clients/local_clients_info > /tmp/log.txt


1445 root 1504 D cat /proc/local_clients/local_clients_info

分析:通过日志可以看到异常出在函数remove_timeout_stas中,查看这个函数,发现是对全局变量l_clients_info_list进行老化操作,整个过程通过mutex进行保护,怀疑是mutex的死锁,但是检查代码,没有发现lock之后没有unlock就返回的地方。在日志中还发现一个特别的提示:scheduling whileatomic; 网上搜索这个关键字,发现有篇文章介绍:http://blog.csdn.net/cfy_phonex/article/details/12090943


其中结论是:Linux内核打印”BUG: scheduling whileatomic”和”bad: scheduling from the idlethread”错误的时候,通常是在中断处理函数中调用了可以休眠的函数,如semaphore,mutex,sleep之类的可休眠的函数。和mutex相关。但是疑惑的是处理中断的时候。哪里来的中断?


在看看日志,发现cat进程都卡死了,难道是cat产生的中断?查了一下cat的使用说明,cat将一个文件打印到标准输出设备上。既然cat会产生中断,那么中断处理就是打开文件并输出到终端设备,重点看读proc文件的处理函数。


内核模块local_clients注册了一个操作proc文件的方法/这里又是一个可以发掘的知识点/:


static structseq_operations clients_seq_ops = {


.start = clients_seq_start,


.next = clients_seq_next,


.stop = clients_seq_stop,


.show = clients_seq_show


};


其中调用cat/proc/local_clients/local_clients_info时,会先执行 clients_seq_start然后再执行clients_seq_show,clients_seq_start函数:


static void*clients_seq_start(struct seq_file *s, loff_t *pos)


{


printk(“pos = %lld\n”, *pos);


remove_timeout_stas(); /该函数中调用了mutex_lock(&local_clients_mutex); /


//mutex_lock(&local_clients_mutex);


if (*pos >= MAX_WIRELESS_CLIENTS_NUM)


{


return NULL;


}


printk(“return addr: %p, pos = %lld\n”,l_clients_info_list + *pos, *pos);

return l_clients_info_list + *pos;

}


问题引起的原因应该是:两个操作调用了mutex_lock;


一个是页面的定时刷新请求webserver调用cat 命令读/proc/local_clients/local_clients_info,cat触发的中断调用了proc文件系统中该文件的读处理函数clients_seq_start,最后引起问题的是调用了mutex_lock(&local_clients_mutex)。


另外一个是当有WLAN中的主机发出DNS报文,local_clients监听到DNS报文时,将发送该报文的主机IP,MAC,HOST信息添加到文件local_clients_info前,也会调用mutex_lock(&local_clients_mutex);


就是说,存在两种顺序,一是在cat中断处理函数被调用时,local_clients添加条目的行为引起了对cat中断处理函数的调度,于是报错。 或者另一种情况,local_clients在添加条目时调用了mutex_lock,而这时cat中断触发也调用了mutex_lock,这时中断中的mutex_lock要等待,所以中断处理函数要进入睡眠,这个也是违背中断处理机制的宗旨的。

解决方法:使用自旋锁spin_lock而不是互斥量mutex_lock,两者的差异在于:自旋锁,重复检查是否可以取得锁,但是不会进入睡眠状态(忙等待,所以spin_lock保护的代码要短小精干,不能耗费太多cpu时间);信号量在等待信号释放的时候,进入睡眠状态,直到被唤醒;中断处理函数不能进入睡眠状态(就是说不能调用sleep,或者等待一个信号量资源)。

测试:


测试1)


测试修改前使用mutex_lock和修改后的spin_lock两种情况,使用shell脚本循环cat /proc/local_clients/local_clients_info文件,在WLAN端pc使用一个bat脚本进行nslookup 操作令PC不断发送DNS报文,测试发现,使用mutex_lock很快出现错误提示:


/tmp # tftp -g 192.168.0.104 -r test.sh;chmod 777 test.sh


test.sh 100% |*********************| 78 0:00:00 ETA


/tmp # tftp -g 192.168.0.104 -r test.sh;chmod 777 test.sh


test.sh 100% |*********************| 78 0:00:00 ETA


/tmp # ./test.sh


[ 193.176000] BUG: scheduling while atomic: cat/1835/0x00000100


[ 193.184000] Modules linked in: umac ath_dev(P) ath_rate_atheros(P) ath_hal(P) asf(P) adf(P) athrs_gmac local_clients tp_domain parentCtrl


[ 193.196000] Cpu 0


[ 193.200000] 0:00000000000000010000000100000000[193.204000] 4 : 00000030 832e32ac 00000080 c4653600


[ 193.208000] 8:3b9aca00364c598bc4ec4d38fffffff8[193.216000]12 : 0000002d 592f59ba 0000003f 00455924


[ 193.220000] 16:000000c1832d0000000010007fc7fc70[193.224000]20 : 825cde98 00000000 7fc7fc70 00001000


[ 193.232000] 24:000000a9800b22c8[193.236000]28 : 825cc000 825cde50 825cdf10 832d42c0


[ 193.240000] Hi : 001a99e2


[ 193.244000] Lo : 8f4e21b0


[ 193.248000] epc : 832d42d8 remove_timeout_stas+0x4c/0x8c [local_clients]


[ 193.256000] Tainted: P


[ 193.260000] ra : 832d42c0 remove_timeout_stas+0x34/0x8c [local_clients]


[ 193.264000] Status: 1000ff03 KERNEL EXL IE


[ 193.268000] Cause : 10800400


[ 193.272000] PrId : 00019374 (MIPS 24Kc)


测试2)


是否可能是由多个cat 引起的mutex_lock调用导致问题产生


在shell中执行多个调用cat的脚本,跑了很长一段时间,没有出现问题;cat是用户态进程,那么kernel是否会同时执行两个打开文件的操作呢?


答案是不会,这里涉及到进程调度,cat是用户态进程,而打卡文件属于内核态操作,从用户态到核心态有两种方法,1是系统调用,2是中断,这里明显是使用系统调用。如果系统处于核心态并正在处理系统调用,那么系统中的其他进程是无法夺取启cpu时间,调度器必须等待系统调用完成,才能选择另一个进程执行,但是中断可以终止系统调用。所以该问题应该是mutex_lock引起的。

续:


在AP(MTK7628),当小米6连接时,也出现类似的问题,导致其他无线设备连接不上AP,不过在最新版的MIUI V8.2.23.0 该问题已经修复。


[06-07 12:03:49]BUG: scheduling while atomic: RtmpMlmeTask/154/0x00000100


[06-07 12:03:49]Modules linked in: mt_wifi


[06-07 12:03:49]Cpu 0


[06-07 12:03:49]0:0000000000000000c03582ec00000002[060712:03:49] 4 : c0503000 c05e2728 00000000 c050a6ef


[06-07 12:03:49]8:c050a6fc80f53d3e0000000480f53d44[060712:03:49]12 : 00044000 00000004 00000002 00000000


[06-07 12:03:49]16:00000002c05e2728c0503000c0360000[060712:03:49]20 : c04844bc c03e0000 c048436c c043fdac


[06-07 12:03:49]24:00000000c0358e28[060712:03:49]28 : 80f52000 80f53db8 c0484284 c03e334c


[06-07 12:03:49]Hi : 00000000


[06-07 12:03:49]Lo : 00000040


[06-07 12:03:49]epc : c03582ec RTMPCheckEntryEnableAutoRateSwitch+0x0/0x90 [mt_wifi]


[06-07 12:03:49] Not tainted


[06-07 12:03:49]ra : c03e334c APMlmeDynamicTxRateSwitching+0x130/0x9a8 [mt_wifi]


[06-07 12:03:49]Status: 1100ff03 KERNEL EXL IE


[06-07 12:03:49]Cause : 50808000


[06-07 12:03:49]PrId : 00019655 (MIPS 24Kc)

转载请注明:CodingBlog » 【Linux】【Kernel】BUG: scheduling while atomic相关疑难问题解析

喜欢 (0)or分享 (0)
发表我的评论
取消评论

*

表情