1. 程式人生 > >【Linux】【Kernel】BUG: scheduling while atomic問題分析

【Linux】【Kernel】BUG: scheduling while atomic問題分析

核心模組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)