log

已开启线程打印安全，多线程输出日志感觉还是会互相抢占打断

发布于 2024-03-18 15:51:35 浏览：551 订阅该版

2 个回答

聚散无由 2024-03-19

https://jswyll.com

## 问题分析

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

```c
#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决定了是否打印对应等级即以上的日志。其中关键的宏定义是：

```c
#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：

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

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

2. 展开dbg_log_line：

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

3. 分别展开`_DBG_LOG_HDR`和`_DBG_LOG_X_END`：

```c
    #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函数线程安全也会导致日志输出的顺序不一致。**

例如你的：

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

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

1. 颜色+标签头`[W/bms rtu]`；
2. 颜色+标签头`[W/bms rtu]`；
3. receive timeout.
4. 重置颜色+换行；
5. receive timeout.
6. 重置颜色+换行；

### 解决方案

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

```c
#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`定义如下：

```c
#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如下：

```c
/*
 * 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__ */
```

改动了两处：

![screenshot_image.png](https://oss-club.rt-thread.org/uploads/20240319/77a5c2721d02e01420302161ddd09de6.png.webp)

![screenshot_image.png](https://oss-club.rt-thread.org/uploads/20240319/29cc002462d4e23826a40dbd8ed0337c.png.webp)