背景

最近在做一個(gè)OTA的功能時(shí)，遇到一個(gè)hard fault on handler的問(wèn)題，前前后后排查了將近2天，才將此問(wèn)題解決，因此做一個(gè)記錄，方便其它工程師，遇到此類問(wèn)題的時(shí)候有個(gè)參考。

環(huán)境

rt-thread v4.1.0
lwip2.1.2
cJSON-lastest
使能了posix的select和poll
CmBacktrace v1.3.0
使能了ulog組件

問(wèn)題和排查過(guò)程
最開始遇到問(wèn)題的時(shí)候，報(bào)以下錯(cuò)誤

psr: 0xa100000f
r00: 0xffffffff
r01: 0x2000def4
r02: 0xffffffff
r03: 0x7fffffff
r04: 0x00000000
r05: 0x20017f18
r06: 0x20000358
r07: 0xdeadbeef
r08: 0x00000000
r09: 0x00000001
r10: 0xdeadbeef
r11: 0xdeadbeef
r12: 0x00000000
lr: 0x08042ed9
pc: 0x08042ef8
hard fault on handler
bus fault:
SCB_CFSR_BFSR:0x82 PRECISERR SCB->BFAR:FFFFFFFF

使用CmBacktrace軟件包定位問(wèn)題

后來(lái)在論壇搜索相關(guān)的關(guān)鍵詞，有人推薦使用CmBacktrace軟件包，于是去安裝此軟件包，但是安裝了以后，報(bào)如下錯(cuò)誤

thread pri status sp stack size max used left tick error

rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000009 000
rf_read 10 suspend 0x000000c0 0x00000200 39% 0x00000003 000
可以看到，CmBacktrace沒(méi)有打印完全，這時(shí)候我又去CmBacktrace的github倉(cāng)庫(kù)，看有沒(méi)有人提相關(guān)的issue,發(fā)現(xiàn)是因?yàn)槲掖蜷_了ulog組件導(dǎo)致的，具體可以參考這個(gè)issue

Usage fault下沒(méi)輸出關(guān)鍵的call_stack信息

然后我按照鏈接，手動(dòng)修改CmBacktrace的打印宏定義為rt_kprintf，使用CmBacktrace的cmb_test的除零測(cè)試命令測(cè)試以后，可以正常打印了,這時(shí)候我太開心了，以為問(wèn)題基本上可以定位了，然而我發(fā)現(xiàn)我高興的還是太早了。

在cmb_test正常以后，當(dāng)我把問(wèn)題再次復(fù)現(xiàn)時(shí)，CmBacktrace打印的信息，還是不全，和之前完全沒(méi)有變化！！！如下所示。

thread pri status sp stack size max used left tick error

rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000009 000
rf_read 10 suspend 0x000000c0 0x00000200 39% 0x00000003 000

這就非常奇怪了，明明使用CmBacktrace的除零測(cè)試是OK的，為什么還是打印不正常呢？

使用PC和LR反推

看樣子是不能用CmBacktrace了，也許是我使用的姿勢(shì)不對(duì)，也許是其他問(wèn)題，那就只能靠自己了。

我試著按照文章的方法去排查，結(jié)果發(fā)現(xiàn)復(fù)現(xiàn)問(wèn)題的時(shí)候，是在rtthread的timer里面，如下圖所示

這就讓我犯難了，這不會(huì)是rt-thread的問(wèn)題吧，rt-thread這么多年了，難道我一用就出問(wèn)題？

不破不立

不可能，絕對(duì)不可能，一定是我用的姿勢(shì)不對(duì)，再換一個(gè)姿勢(shì)吧，不破不立，由于我的代碼是分模塊的，于是我就將自己感覺(jué)有問(wèn)題的模塊，一個(gè)一個(gè)注釋掉，如下圖所示，從后面往前面一個(gè)一個(gè)注釋，每注釋一個(gè)模塊，我就看看是否還會(huì)發(fā)生hardfualt

當(dāng)我把ota_init模塊注釋掉的時(shí)候，發(fā)現(xiàn)hardfualt沒(méi)了，這…這怎么可能呢，這個(gè)模塊我之前測(cè)試過(guò)的呀，跑了兩天都是正常的。

然后我發(fā)現(xiàn)，設(shè)備每次出現(xiàn)hardfault的時(shí)候，系統(tǒng)的tick都是553600ms左右,如下所示，換算成分鐘也就是9分鐘這樣，9分鐘，9分鐘，9分鐘，9分鐘的時(shí)候還沒(méi)有出現(xiàn)hardfualt，我的ota模塊，是每10分鐘去服務(wù)器拉取一次做版本檢測(cè)，這么說(shuō)，是這里的問(wèn)題了？

| /

RT - Thread Operating System
/ | 4.1.0 build Jan 6 2023 17:42:12
2006 - 2022 Copyright by RT-Thread team
lwIP-2.1.2 initialized!
[4416] I/sal.skt: Socket Abstraction Layer initialize success.
[4574] I/rfid_config: reader.id : 4403061904001
[4579] I/rfid_config: reader.beep : 0
[4584] I/rfid_config: report.interval : 60
[4588] I/rfid_config: reader.power : 10
[4594] D/ota_module: ota_flag == ERASE_IAP_FLAG
msh />[4715] D/rfid_module: rfid_report tag
[65630] D/rfid_module: rfid_report tag
[126649] D/rfid_module: rfid_report tag
[187613] D/rfid_module: rfid_report tag
[248612] D/rfid_module: rfid_report tag
[309611] D/rfid_module: rfid_report tag
[370595] D/rfid_module: rfid_report tag
[430629] D/rfid_module: rfid_report tag
[491631] D/rfid_module: rfid_report tag
[552598] D/rfid_module: rfid_report tag
thread pri status sp stack size max used left tick error

tcp_ser 10 suspend 0x000001d8 0x00000800 25% 0x0000000a 000
udp_ser 10 suspend 0x00000228 0x00000400 53% 0x0000000a 000
rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000003 000
rf_read 10 suspend 0x000000c0 0x00000200 37% 0x00000004 000
| /

RT - Thread Operating System
/ | 4.1.0 build Jan 6 2023 17:42:12
2006 - 2022 Copyright by RT-Thread team
lwIP-2.1.2 initialized!
[4416] I/sal.skt: Socket Abstraction Layer initialize success.
[4574] I/rfid_config: reader.id : 4403061904001
[4579] I/rfid_config: reader.beep : 0
[4584] I/rfid_config: report.interval : 60
[4588] I/rfid_config: reader.power : 10
[4594] D/ota_module: ota_flag == ERASE_IAP_FLAG
msh />[4716] D/rfid_module: rfid_report tag
[65642] D/rfid_module: rfid_report tag
[126601] D/rfid_module: rfid_report tag
[151604] D/rfid_module: rfid_report tag
[187619] D/rfid_module: rfid_report tag
[248596] D/rfid_module: rfid_report tag
[309616] D/rfid_module: rfid_report tag
[370621] D/rfid_module: rfid_report tag
[431620] D/rfid_module: rfid_report tag
[492616] D/rfid_module: rfid_report tag
[553600] D/rfid_module: rfid_report tag
thread pri status sp stack size max used left tick error

rf_led 10 suspend 0x00000080 0x00000100 50% 0x0000000a 000
rf_send 10 suspend 0x000000a0 0x00000800 16% 0x00000009 000
rf_read 10 suspend 0x000000c0 0x00000200 39% 0x00000003 000

于是我把OTA的時(shí)間改成每10秒一次，果然10秒以后，就出現(xiàn)了hardfault

峰回路轉(zhuǎn)

那么問(wèn)題很明確了，就是這個(gè)OTA模塊的問(wèn)題，于是我在OTA模塊里面打斷點(diǎn)排查，發(fā)現(xiàn)在socket里面，發(fā)送UDP數(shù)據(jù)包的時(shí)候，就出現(xiàn)了hardfault，如下所示

這會(huì)是數(shù)組越界導(dǎo)致的嗎？于是我開始排查在這個(gè)udp發(fā)送函數(shù)前面的代碼，仔細(xì)排查以后，沒(méi)發(fā)現(xiàn)有數(shù)組越界的現(xiàn)象。線索又?jǐn)嗔恕?怎么辦呢？我左思右想，問(wèn)題就出現(xiàn)在這，到底是什么原因？

柳暗花明

udp發(fā)送，udp發(fā)送，會(huì)不會(huì)是這個(gè)線程爆棧了，于是我瞟了一眼這個(gè)線程的棧大小，哎喲我去，512字節(jié)。

thread = rt_thread_create("ota", ota_thread, RT_NULL, 512, 10, 10);
那我就改一下吧，改1024試試，果然，正常了….松了一口氣…

原來(lái)這個(gè)線程的棧是1024字節(jié)的，后面我使用ps命令看了這個(gè)線程棧的利用率還很低，于是我改成了512字節(jié)，這也就是說(shuō)，為什么我之前測(cè)試了2天這個(gè)模塊都是正常的，現(xiàn)在卻不行了。因?yàn)槲沂褂胮s命令的時(shí)候，那會(huì)才運(yùn)行了幾分鐘，看到的線程棧利用率是沒(méi)有調(diào)用udp發(fā)送函數(shù)的，也就是說(shuō)，那會(huì)看到的棧利用率，是不準(zhǔn)的，那時(shí)候我去減小它，肯定就容易出問(wèn)題了

當(dāng)系統(tǒng)正常以后，我再次去ps，發(fā)現(xiàn)線程實(shí)際的棧利用率是92%，如下所示（前面的ps是沒(méi)有調(diào)用udp函數(shù)之前的，后面的ps是調(diào)用udp函數(shù)以后的，這時(shí)候的棧我設(shè)置的大小是1024），也就是說(shuō)，512字節(jié)，肯定是不夠的，甚至1024都快爆了，還得增大。

thread pri status sp stack size max used left tick error

ota 10 suspend 0x0000007c 0x00000400 32% 0x00000005 000
sys_led 10 suspend 0x0000007c 0x00000100 48% 0x0000000a 000
tshell 20 running 0x00000094 0x00001000 13% 0x00000003 000
tcpip 10 suspend 0x000000d0 0x00002000 07% 0x00000014 000
etx 12 suspend 0x00000094 0x00000400 14% 0x00000010 000
erx 12 suspend 0x00000094 0x00000400 56% 0x00000010 000
sys work 23 suspend 0x00000060 0x00000800 53% 0x0000000a 000
tidle0 31 ready 0x00000048 0x00000100 45% 0x00000009 000
timer 4 suspend 0x00000064 0x00000200 24% 0x00000009 000
main 10 suspend 0x00000084 0x00000800 33% 0x0000000e 000
msh />
msh />
msh />
msh />
msh />[14598] D/udp_module: send success
[14628] D/ota_module: ota_flag == ERASE_IAP_FLAG
ps
thread pri status sp stack size max used left tick error

ota 10 suspend 0x0000007c 0x00000400 92% 0x00000001 000
sys_led 10 suspend 0x0000007c 0x00000100 48% 0x0000000a 000
tshell 20 running 0x0000020c 0x00001000 13% 0x00000007 000
tcpip 10 suspend 0x000000d0 0x00002000 07% 0x00000014 000
etx 12 suspend 0x00000094 0x00000400 14% 0x00000010 000
erx 12 suspend 0x00000094 0x00000400 56% 0x00000010 000
sys work 23 suspend 0x00000060 0x00000800 53% 0x0000000a 000
tidle0 31 ready 0x00000058 0x00000100 45% 0x00000018 000
timer 4 suspend 0x00000064 0x00000200 24% 0x00000009 000
main 10 suspend 0x00000084 0x00000800 33% 0x0000000e 000

總結(jié)

使用了網(wǎng)絡(luò)的線程，一定要將線程棧開大一點(diǎn)，512字節(jié)肯定是不夠的，最少1536字節(jié)以上
使用ps命令打印出來(lái)的線程棧最大使用率，是在代碼運(yùn)行過(guò)一段時(shí)間以后，才準(zhǔn)的，比如我的代碼中，udp發(fā)送數(shù)據(jù)是在系統(tǒng)啟動(dòng)10分鐘以后才運(yùn)行到，所以我在前面幾分鐘的時(shí)候使用的ps命令看，ota線程是沒(méi)有爆棧的，只有在運(yùn)行到這個(gè)網(wǎng)絡(luò)發(fā)送數(shù)據(jù)的代碼，這個(gè)棧才會(huì)溢出。

因此如果有一些代碼不是立即運(yùn)行的，在調(diào)試的時(shí)候，可以把這個(gè)時(shí)間提前，盡量讓系統(tǒng)上電以后，把所有的代碼都能跑一遍，這樣對(duì)于一些跑了一段時(shí)間才出現(xiàn)棧溢出的問(wèn)題，比較容易復(fù)現(xiàn)，容易復(fù)現(xiàn)也就容易解決。

或者可以在調(diào)試代碼的時(shí)候，可以把線程棧設(shè)置大一些，讓代碼先能夠正常跑起來(lái)，然后跑個(gè)幾天，再去ps一下看看棧的最大利用率，幾天以后所有的代碼、流程應(yīng)該基本上都跑過(guò)一遍了，這時(shí)候的棧利用率才是比較準(zhǔn)的，這時(shí)候才去優(yōu)化這個(gè)棧大小，會(huì)比較合適。

在遇到hardfault的時(shí)候，不要怕，用工具不行，我們就手動(dòng)一個(gè)一個(gè)模塊去排查，把問(wèn)題的范圍縮小，盡管耗費(fèi)的時(shí)間會(huì)長(zhǎng)一點(diǎn)，但是總會(huì)定位到問(wèn)題的。

最后我想，如果rt-thread可以在棧溢出的時(shí)候，自動(dòng)檢測(cè)并且定位出來(lái)就好了，比如我這個(gè)ota的線程棧溢出了，rt-thread就告訴我，xxxx線程棧溢出啦，你得開辟大一點(diǎn)，就好了。