RT-Thread-已开启线程打印安全，多线程输出日志感觉还是会互相抢占打断RT-Thread问答社区

问题分析

在各个文件中定义打印标签和打印等级，使用LOG_D、LOG_I、LOG_W或LOG_E打印：

#define DBG_TAG "main"
#define DBG_LVL DBG_LOG
#include <rtdbg.h>
int main(void)
{
    LOG_D("This is a debug message");
    LOG_I("This is an information message");
    LOG_W("This is a warning message");
    LOG_E("This is an error message");
    return RT_EOK;
}

相关文件是rtdbg.h，其中指定文件的DBG_LVL决定了是否打印对应等级即以上的日志。其中关键的宏定义是：

#define dbg_log_line(lvl, color_n, fmt, ...)                \
    do                                                      \
    {                                                       \
        _DBG_LOG_HDR(lvl, color_n);                         \
        rt_kprintf(fmt, ##__VA_ARGS__);                     \
        _DBG_LOG_X_END;                                     \
    }                                                       \
    while (0)

以LOG_I、启用颜色打印为例，依次展开LOG_I：

根据对应的等级，启用LOG_I打印：

 #define LOG_I(fmt, ...)      dbg_log_line("I", 32, fmt, ##__VA_ARGS__)

展开dbg_log_line：

 #define LOG_I(fmt, ...)
     do                                                      \
     {                                                       \
         _DBG_LOG_HDR("I", 32);                              \
         rt_kprintf(fmt, ##__VA_ARGS__);                     \
         _DBG_LOG_X_END;                                     \
     }                                                       \
     while (0)

分别展开_DBG_LOG_HDR和_DBG_LOG_X_END：

 #define LOG_I(fmt, ...)
     do                                                      \
     {                                                       \
         rt_kprintf("\033[32m[I/" DBG_SECTION_NAME "] ")     \
         rt_kprintf(fmt, ##__VA_ARGS__);                     \
         rt_kprintf("\033[0m\n");                            \
     }                                                       \
     while (0)

其中：

两个带常量字符串会被合并，例如DBG_SECTION_NAME如果是"main"，rt_kprintf("\033[32m[I/" DBG_SECTION_NAME "] ")最终为rt_kprintf("\033[32m[I/main] ")；
##__VA_ARGS__表示展开LOG_I(fmt, ...)中的...；
\033[数值m表示设置字体的前景色。_DBG_LOG_HDR的32表示绿色，_DBG_LOG_X_END的0表示重置颜色；
#define xxx do{xxx}while (0)是一个宏定义展开为多条语句的方法。

可见，语句LOG_X语言被分成了三部分：设置颜色和标签头；打印实体；重置颜色并换行。

因此，rt_kprintf函数线程安全也会导致日志输出的顺序不一致。

例如你的：

[W/bms rtu][w/dsp rtu] receive timeout.
receive timeout

第一行有颜色，第二行没有颜色，且有些错位。可以猜出它的顺序是：

颜色+标签头[W/bms rtu]；
颜色+标签头[W/bms rtu]；
receive timeout.
重置颜色+换行；
receive timeout.
重置颜色+换行；

解决方案

从上面的分析可知，对于一行原始语句的打印，它本身是线程安全的，但加上颜色标头和换行以后就有点乱了。无伤大雅，如果要整体线程安全，可以把dbg_log_line宏定义展开的语句合并为一行：

#define dbg_log_line(lvl, color_n, fmt, ...)                \
    rt_kprintf(_DBG_HDR(lvl, color_n) fmt _DBG_X_END, ##__VA_ARGS__)

其中，_DBG_HDR(lvl, color_n)和_DBG_X_END定义如下：

#ifdef DBG_COLOR
#define _DBG_COLOR(n)        rt_kprintf("\033["#n"m")
#define _DBG_HDR(lvl_name, color_n)                        \
    "\033["#color_n"m[" lvl_name "/" DBG_SECTION_NAME "] "
#define _DBG_X_END                                         \
    "\033[0m\n"
#else
#define _DBG_COLOR(n)
#define _DBG_HDR(lvl_name, color_n)                        \
    "[" lvl_name "/" DBG_SECTION_NAME "] "
#define _DBG_X_END                                         \
    "\n"
#endif /* DBG_COLOR */

修改后的rtdbg.h如下：

/*
 * Copyright (c) 2006-2021, RT-Thread Development Team
 *
 * SPDX-License-Identifier: Apache-2.0
 *
 * Change Logs:
 * Date           Author       Notes
 * 2016-11-12     Bernard      The first version
 * 2018-05-25     armink       Add simple API, such as LOG_D, LOG_E
 */
/*
 * The macro definitions for debug
 *
 * These macros are defined in static. If you want to use debug macro, you can
 * use as following code:
 *
 * In your C/C++ file, enable/disable DEBUG_ENABLE macro, and then include this
 * header file.
 *
 * #define DBG_TAG           "MOD_TAG"
 * #define DBG_LVL           DBG_INFO
 * #include <rtdbg.h>          // must after of DBG_LVL, DBG_TAG or other options
 *
 * Then in your C/C++ file, you can use LOG_X macro to print out logs:
 * LOG_D("this is a debug log!");
 * LOG_E("this is a error log!");
 */
#ifndef RT_DBG_H__
#define RT_DBG_H__
#include <rtconfig.h>
#ifdef __cplusplus
extern "C" {
#endif
/* the debug log will force enable when RT_DEBUG macro is defined */
#if defined(RT_DEBUG) && !defined(DBG_ENABLE)
#define DBG_ENABLE
#endif
/* it will force output color log when RT_DEBUG_COLOR macro is defined */
#if defined(RT_DEBUG_COLOR) && !defined(DBG_COLOR)
#define DBG_COLOR
#endif
#if defined(RT_USING_ULOG)
/* using ulog compatible with rtdbg  */
#include <ulog.h>
#else
/* DEBUG level */
#define DBG_ERROR           0
#define DBG_WARNING         1
#define DBG_INFO            2
#define DBG_LOG             3
#ifdef DBG_TAG
#ifndef DBG_SECTION_NAME
#define DBG_SECTION_NAME    DBG_TAG
#endif
#else
/* compatible with old version */
#ifndef DBG_SECTION_NAME
#define DBG_SECTION_NAME    "DBG"
#endif
#endif /* DBG_TAG */
#ifdef DBG_ENABLE
#ifdef DBG_LVL
#ifndef DBG_LEVEL
#define DBG_LEVEL         DBG_LVL
#endif
#else
/* compatible with old version */
#ifndef DBG_LEVEL
#define DBG_LEVEL         DBG_WARNING
#endif
#endif /* DBG_LVL */
/*
 * The color for terminal (foreground)
 * BLACK    30
 * RED      31
 * GREEN    32
 * YELLOW   33
 * BLUE     34
 * PURPLE   35
 * CYAN     36
 * WHITE    37
 */
#ifdef DBG_COLOR
#define _DBG_COLOR(n)        rt_kprintf("\033["#n"m")
#define _DBG_HDR(lvl_name, color_n)                        \
    "\033["#color_n"m[" lvl_name "/" DBG_SECTION_NAME "] "
#define _DBG_LOG_HDR(lvl_name, color_n)                    \
    rt_kprintf("\033["#color_n"m[" lvl_name "/" DBG_SECTION_NAME "] ")
#define _DBG_X_END                                         \
    "\033[0m\n"
#define _DBG_LOG_X_END                                     \
    rt_kprintf("\033[0m\n")
#else
#define _DBG_COLOR(n)
#define _DBG_HDR(lvl_name, color_n)                        \
    "[" lvl_name "/" DBG_SECTION_NAME "] "
#define _DBG_LOG_HDR(lvl_name, color_n)                    \
    rt_kprintf("[" lvl_name "/" DBG_SECTION_NAME "] ")
#define _DBG_X_END                                         \
    "\n"
#define _DBG_LOG_X_END                                     \
    rt_kprintf("\n")
#endif /* DBG_COLOR */
/*
 * static debug routine
 * NOTE: This is a NOT RECOMMENDED API. Please using LOG_X API.
 *       It will be DISCARDED later. Because it will take up more resources.
 */
#define dbg_log(level, fmt, ...)                            \
    if ((level) <= DBG_LEVEL)                               \
    {                                                       \
        switch(level)                                       \
        {                                                   \
            case DBG_ERROR:   _DBG_LOG_HDR("E", 31); break; \
            case DBG_WARNING: _DBG_LOG_HDR("W", 33); break; \
            case DBG_INFO:    _DBG_LOG_HDR("I", 32); break; \
            case DBG_LOG:     _DBG_LOG_HDR("D", 0); break;  \
            default: break;                                 \
        }                                                   \
        rt_kprintf(fmt, ##__VA_ARGS__);                     \
        _DBG_COLOR(0);                                      \
    }
#define dbg_here                                            \
    if ((DBG_LEVEL) <= DBG_LOG){                            \
        rt_kprintf(DBG_SECTION_NAME " Here %s:%d\n",        \
            __FUNCTION__, __LINE__);                        \
    }
#define dbg_log_line(lvl, color_n, fmt, ...)                \
    rt_kprintf(_DBG_HDR(lvl, color_n) fmt _DBG_X_END, ##__VA_ARGS__)
#define dbg_raw(...)         rt_kprintf(__VA_ARGS__);
#else
#define dbg_log(level, fmt, ...)
#define dbg_here
#define dbg_enter
#define dbg_exit
#define dbg_log_line(lvl, color_n, fmt, ...)
#define dbg_raw(...)
#endif /* DBG_ENABLE */
#if (DBG_LEVEL >= DBG_LOG)
#define LOG_D(fmt, ...)      dbg_log_line("D", 0, fmt, ##__VA_ARGS__)
#else
#define LOG_D(...)
#endif
#if (DBG_LEVEL >= DBG_INFO)
#define LOG_I(fmt, ...)      dbg_log_line("I", 32, fmt, ##__VA_ARGS__)
#else
#define LOG_I(...)
#endif
#if (DBG_LEVEL >= DBG_WARNING)
#define LOG_W(fmt, ...)      dbg_log_line("W", 33, fmt, ##__VA_ARGS__)
#else
#define LOG_W(...)
#endif
#if (DBG_LEVEL >= DBG_ERROR)
#define LOG_E(fmt, ...)      dbg_log_line("E", 31, fmt, ##__VA_ARGS__)
#else
#define LOG_E(...)
#endif
#define LOG_RAW(...)         dbg_raw(__VA_ARGS__)
#endif /* defined(RT_USING_ULOG) && define(DBG_ENABLE) */
#ifdef __cplusplus
}
#endif
#endif /* RT_DBG_H__ */