Ulog使用硬件RTC時間戳信號量鎖死分析

一、現(xiàn)象描述
在使能硬件RTC，初始化階段未設(shè)置時間的情況下【測試環(huán)境為4.1.0版本Env創(chuàng)建的Keil工程】
如果開啟Ulog時間戳，打印日志導(dǎo)致線程鎖死

根本原因為打印時間戳日志的過程中由于未設(shè)置時間，導(dǎo)致再次調(diào)用日志打印，在以下函數(shù)中掛起線程

/* drv_rtc.c 文件 /
if (HAL_RTCEx_BKUPRead(&RTC_Handler, RTC_BKP_DR1) != BKUP_REG_DATA)
{
LOG_I("RTC hasn't been configured, please use command to config.");
/ 其他代碼省略 */
}
在LOG_I()中再次運行LOG_I()導(dǎo)致output_lock上鎖兩次
output_lock上鎖本質(zhì)為接收信號量ulog.output_locker
ulog初始化的信號量為1
第一次上鎖信號量減一
再次調(diào)用LOG_I導(dǎo)致第二次上鎖
第一次的鎖還沒有解開
第二次上鎖導(dǎo)致鎖死現(xiàn)象，直接掛起線程
Ulog無法輸出任何信息

二、對比分析
由于之前使用RT-Studio的4.0.3版本可以正常輸出提示

所以將4.1.0與4.0.3對比分析并排查問題

硬件平臺：STM32F407 正點原子探索者開發(fā)板

以下表格是在進入主線程之前為未設(shè)置時間的RTC初始化流程對比

三、臨時解決方案
方案一：避開初始化未設(shè)置時間的提示，增加RTC初始化函數(shù)，在進入主線程之前設(shè)置時間

缺點：如果真的忘記設(shè)置時間，導(dǎo)致死鎖又要踩坑，花時間排查原因，影響開發(fā)進度

方案二：保留始化未設(shè)置時間的提示，避開第二次上鎖，將 LOG_I 修改為 rt_kprintf

缺點：無論是否開啟Ulog，依舊會有提示，其實影響不是很大，甚至在未開啟Ulog也會有提示

? 【前提條件是開啟了串口或者其他控制臺輸出，如果沒開啟控制臺輸出不知道會發(fā)生什么】

方案三：直接將未設(shè)置時間的提示注釋掉，由于不會第二次上鎖，所以日志打印正常

缺點：未設(shè)置時間不會提示

方案四：使用4.0.3版本

方案五：Ulog不使用時間戳格式

四、場景復(fù)現(xiàn)
理論上只要是STM32的單片機都會有這個問題，其他廠家的未測試過

以下測試平臺以正點原子的探索者開發(fā)板為參考，場景復(fù)現(xiàn)大同小異

據(jù)說該開發(fā)板的啟動電路的串口設(shè)置為控制臺打印會有一些沖突

如果發(fā)現(xiàn)不能正常打印最好換一個串口或者使用RTT作為控制臺輸出

（1）鎖死環(huán)境復(fù)現(xiàn)
打開 ···rt-threadbspstm32stm32f407-atk-explorer

右鍵打開Env 輸入scons —dist

打開dist文件夾中新生成的bsp工程

右鍵打開Env 輸入menuconfig

進入 RT-Thread Kernel -> Kernel Device Object 修改可以使用的控制臺設(shè)備【如：uart1，jlinkRtt】

RT-Thread Comonents -> Device Drivers Using RTC device drivers

RT-Thread Comonents -> Utilities Enable ulog

log format -> Enbale timestamp format for time

Hardware Drivers Config -> On-chip Peripheral Drivers EnableRTC RTC_USING_LSE

Esc 然后選擇Yes保存配置

打開 ···boardCubeMX_Config文件夾，配置CubeMX

打開Keil，復(fù)制生成的時鐘配置，注釋掉msp文件的Error_Handler()已防止后續(xù)編譯錯誤

復(fù)制一下內(nèi)容到 main.c 僅供參考

#include
#include
#include
#define DBG_TAG "main"
#define DBG_LVL DBG_LOG
#include
/* defined the LED0 pin: PF9 /
#define LED0_PIN GET_PIN(F, 9)
int main(void)
{
/ set LED0 pin mode to output */
rt_pin_mode(LED0_PIN, PIN_MODE_OUTPUT);
while (1)
{
rt_pin_write(LED0_PIN, PIN_HIGH);
rt_thread_mdelay(500);
rt_pin_write(LED0_PIN, PIN_LOW);
rt_thread_mdelay(500);
LOG_D("Hello RT-Thread!");
}
}
編譯代碼并下載到芯片，發(fā)現(xiàn)日志打印失敗，燈不閃爍，此時 main線程已經(jīng)掛起

（2）對比環(huán)境復(fù)現(xiàn)
測試平臺為RT-Studio 2.2.1【其實和Studio版本關(guān)系不大】

基于芯片創(chuàng)建的RT-Thread工程

本文就不詳細說明Studio的配置步驟了

以下圖片為Ulog配置

復(fù)制上面的main函數(shù)，一切運行正常，并有未設(shè)置時間的提示

五、Ulog及RTC其它問題的吐槽
（1）部分設(shè)備注冊的日志信息無法打印
主要原因是初始化順序不可控，使用 INIT_BOARD_EXPORT(ulog_init);

不能保證在設(shè)備注冊之前初始化

使初始化階段部分打印之間 return

void ulog_voutput(······)
{
/* ······ /
if (!ulog.init_ok)
{
return;
}
/ ······ */
}
例如以下打印在我的測試環(huán)境下就是直接 return

LOG_I("I2C bus [%s] registered", bus_name);
（2）STM32的LSE和LSI不能同時開啟
為什么需要同時開啟？

因為獨立看門狗的時鐘源是LSI

當使用LSE作為RTC的時鐘源

如果關(guān)閉LSI是否會導(dǎo)致獨立看門狗工作異常？【實際情況未測試，可能和初始化順序有關(guān)】

具體看以下代碼

/* drv_rtc.c */
static rt_err_t stm32_rtc_init(void)
{
__HAL_RCC_PWR_CLK_ENABLE();
RCC_OscInitTypeDef RCC_OscInitStruct = {0};
#ifdef BSP_RTC_USING_LSI
RCC_OscInitStruct.OscillatorType = RCC_OSCILLATORTYPE_LSI;
RCC_OscInitStruct.PLL.PLLState = RCC_PLL_NONE;
RCC_OscInitStruct.LSEState = RCC_LSE_OFF;
RCC_OscInitStruct.LSIState = RCC_LSI_ON;
#else
RCC_OscInitStruct.OscillatorType = RCC_OSCILLATORTYPE_LSE;
RCC_OscInitStruct.PLL.PLLState = RCC_PLL_NONE;
RCC_OscInitStruct.LSEState = RCC_LSE_ON;
RCC_OscInitStruct.LSIState = RCC_LSI_OFF;
#endif
HAL_RCC_OscConfig(&RCC_OscInitStruct);
if (rt_rtc_config() != RT_EOK)
{
LOG_E("rtc init failed.");
return -RT_ERROR;
}
return RT_EOK;
}