跳转至

RT-Thread ulog 日志组件应用笔记 - 进阶篇

摘要

本应用笔记在《RT-Thread ulog 日志组件应用笔记 - 基础篇》的基础之上,讲解 RT-Thread ulog 组件的高级用法和使用技巧。帮助开发者更加深入的了解 ulog ,并提升日志调试效率。

本文的目的和结构

本文的目的和背景

在了解了《RT-Thread ulog 日志组件应用笔记 - 基础篇》之后,ulog 的基本功能都可以掌握了。为了让大家更好的玩转 ulog ,这篇应用笔记会重点跟大家介绍 ulog 的高级功能及一些日志调试的经验和技巧。学会这些高级用法以后,开发者也能很大程度上提升日志调试的效率。

同时还会介绍 ulog 的高级模式: syslog 模式,这个模式能做到从前端 API 到日志格式对于 Linux syslog 的完全兼容,极大的方便从 Linux 上的迁移过来的软件。

本文的结构

本应用笔记将从以下几个方面来介绍 RT-Thread ulog 的高级应用:

  • ulog 的后端
  • ulog 的异步模式
  • ulog 的日志过滤器
  • ulog 的 syslog 模式
  • 日志调试的一些技巧

问题阐述

本应用笔记将围绕下面几个问题来介绍 RT-Thread ulog 组件。

  • ulog 支持的后端有哪些?
  • 异步模式、日志过滤器及 syslog 模式如何使用?
  • 系统异常(例如:hardfault)时,ulog 该如何处理?
  • 如何输出更加直观的日志?
  • 如何从 rt_dbg.h 或者 elog 迁移过来?

想要解决这些问题,就需要对 RT-Thread ulog 组件的高级功能有一定的认识与了解,同时结合实际例程动手实验,各种功能也将会在 qemu 平台上进行演示。

问题的解决

日志后端

ulog 框架

讲到后端,我们来回顾下 ulog 的框架图。通过上图可以看出, ulog 是采用 前后端分离 的设计,前后端无依赖。并且支持的后端多样化,无论什么样后端,只要实现出来,都可以注册上去。

目前 ulog 已集成控制台后端,即传统的输出 rt_kprintf 打印日志的设备。ulog 还支持 Flash 后端,与 EasyFlash 无缝结合,详见其软件包(点击查看)。后期 ulog 还会增加文件后端、网络后端等后端的实现。当然,如果有特殊需求,用户也可以自己来实现后端。

下面以控制台后端为例,简单介绍后端的实现方法及注册方法。

打开 rt-thread/components/utilities/ulog/backend/console_be.c 文件,可以看到大致有如下内容:

#include <rthw.h>
#include <ulog.h>

/* 定义控制台后端设备 */
static struct ulog_backend console;
/* 控制台后端输出函数 */
void ulog_console_backend_output(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, size_t len)
{
    ...
    /* 输出日志到控制台 */
    ...
}
/* 控制台后端初始化 */
int ulog_console_backend_init(void)
{
    /* 设定输出函数 */
    console.output = ulog_console_backend_output;
    /* 注册后端 */
    ulog_backend_register(&console, "console", RT_TRUE);

    return 0;
}
INIT_COMPONENT_EXPORT(ulog_console_backend_init);

通过上面的代码可以看出控制台后端的实现非常简单,这里实现了后端设备的 output 函数,并将该后端注册到 ulog 里,之后 ulog 的日志都会输出到控制台上。

如果要实现一个比较复杂的后端设备,此时就需要了解后端设备结构体,具体如下:

struct ulog_backend
{
    char name[RT_NAME_MAX];
    rt_bool_t support_color;
    void (*init)  (struct ulog_backend *backend);
    void (*output)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, size_t len);
    void (*flush) (struct ulog_backend *backend);
    void (*deinit)(struct ulog_backend *backend);
    rt_slist_t list;
};

从这个结构体的角度可以看出,实现后端设备的要求如下:

  • name 以及 support_color 属性可以通过 ulog_backend_register 函数在注册时传入;
  • output 为后端具体的输出函数,所有后端都必须实现接口;
  • init/deinit 可选择性实现,init 会在 register 时调用,deinit 会在 ulog_deinit 时调用;
  • flush 也是可选择性实现,一些内部输出带缓存的后端需要必须实现该接口 。比如一些带 RAM 缓存的文件系统。后端的 flush 一般会在断言、hardfault 等异常情况下由 ulog_flush 完成调用。

异步日志

在 ulog 中,默认的输出模式是同步模式,在很多场景下用户可能还需要异步模式。用户在调用日志输出 API 时,会将日志缓存到缓冲区中,会有专门负责日志输出的线程取出日志,然后输出到后端。

异步模式 VS 同步模式

两个模式针对用户而言,在日志 API 使用上是没有差异的,因为 ulog 在底层处理上会有区分。两者的工作原理区别大致如下图所示:

ulog 异步VS同步

再来看下异步模式的优缺点

  • 优点
    • 首先日志输出时不会阻塞住当前线程,再加上有些后端输出速率低,所以使用同步输出模式可能影响当前线程的时序,异步模式不存在该问题。
    • 其次,由于每个使用日志的线程省略了后端输出的动作,所以这些线程的堆栈开销可能也会减少,从这个角度也可以降低整个系统的资源占用。
    • 同步模式下的中断日志只能输出到控制台后端,而异步模式下中断日志可以输出到所有后端去。
  • 缺点 :首先异步模式需要日志缓冲区。再者异步日志的输出还需要有专门线程来完成,比如:idle 线程或者用户自定义的线程,用法上略显复杂。整体感觉异步模式资源占用会比同步模式要高。

异步模式的配置

打开 env,进入 rt-thread\bsp\qemu-vexpress-a9 文件夹,打开 menuconfig 找到 ulog 的异步输出模式选项,打开的效果如下:

ulog 异步配置

针对于异步模式,这里有几个选项

  • The async output buffer size. :异步缓冲区大小,默认为 2048
  • Enable async output by thread. :是否启用 ulog 里异步日志输出线程,该线程运行时将会等待日志通知,然后输出日志到所有的后端。该选项默认开启,如果想要修改为其他线程,例如:idle 线程,可关闭此选项。
    • The async output thread stack size. :异步输出线程的堆栈大小,默认为 1024 ;
    • The async output thread stack priority. :异步输出线程的优先级,默认为 30;

注意:使用 idle 线程输出时,实现虽然很简单,只需在应用层调用 rt_thread_idle_sethook(ulog_async_output) 即可,但也会存在一些限制:

  • idle 线程堆栈大小需要根据实际的后端使用情况进行调整;
  • 由于在 idle 线程内部 不允许 执行线程挂起操作,所以 Flash 、网络等后端可能无法基于 idle 线程使用

异步模式例程

  • 保存异步输出选项配置
  • rt-thread\examples\ulog_example.c 拷贝至 rt-thread\bsp\qemu-vexpress-a9\applications 文件夹下
  • 执行 scons 命令并等待编译完成
  • 运行 qemu.bat 来打开 RT-Thread 的 qemu 模拟器
  • 输入 ulog_example 命令,即可看到 ulog 例程运行结果,大致效果如下图

ulog 异步例程

大家如果细心观察可以发现,开启异步模式后,这一些在代码上离得非常近的日志的时间信息几乎是相同的。但在同步模式下,日志使用用户线程来输出,由于日志输出要花一定时间,所以每条日志的时间会有一定的间隔。这里也充分说明了异步日志的输出效率很高,几乎不占用调用者的时间。

日志过滤器(动态过滤)

在 ulog 应用笔记的基础篇中有介绍过一些日志的静态过滤功能,静态过滤有其优点比如:节省资源,但很多时候,用户需要在软件运行时动态调整日志的过滤方式,这就可以使用到 ulog 的动态过滤器功能。使用动态过滤器功能需在 menuconfig 中开启 Enable runtime log filter. 选项,该选项 默认关闭

ulog 支持的动态过滤方式有以下 4 种,并且都有对应的 API 函数及 Finsh/MSH 命令,下面将会逐一介绍。

按模块的级别过滤

  • 函数:int ulog_tag_lvl_filter_set(const char *tag, rt_uint32_t level)
  • 命令格式: ulog_tag_lvl <tag> <level>

这里指的的 模块 在应用笔记的基础篇中有介绍过,代表一类具有相同标签属性的日志代码。有些时候需要在运行时动态的修改某一个模块的日志输出级别。常见功能对应的函数调用与命令示例如下:

功能 函数调用 执行命令
关闭 wifi 模块全部日志 ulog_tag_lvl_filter_set("wifi", LOG_FILTER_LVL_SILENT); ulog_tag_lvl wifi 0
开启 wifi 模块全部日志 ulog_tag_lvl_filter_set("wifi", LOG_FILTER_LVL_ALL); ulog_tag_lvl wifi 7
设置 wifi 模块日志级别为警告 ulog_tag_lvl_filter_set("wifi", LOG_LVL_WARNING); ulog_tag_lvl wifi 4

按级别进行全局过滤

  • 函数:void ulog_global_filter_lvl_set(rt_uint32_t level)
  • 命令格式: ulog_lvl <level> ,level 分别为
  • 0: Assert
  • 3: Error
  • 4: Warning
  • 6: Info
  • 7: Debug

通过 函数 或者命令设定好全局的过滤级别以后,低于设定级别 的日志都将停止输出。常见功能对应的函数调用与命令示例如下:

功能 函数调用 执行命令
关闭全部日志 ulog_global_filter_lvl_set(LOG_FILTER_LVL_SILENT); ulog_lvl 0
开启全部日志 ulog_global_filter_lvl_set(LOG_FILTER_LVL_ALL); ulog_lvl 7
设置日志级别为警告 ulog_global_filter_lvl_set(LOG_LVL_WARNING); ulog_lvl 4

按标签进行全局过滤

  • 函数:void ulog_global_filter_tag_set(const char *tag)
  • 命令格式: ulog_tag [tag] ,tag 为空时,则取消标签过滤

该过滤方式可以对所有日志执行按标签过滤,只有 包含标签信息 的日志才允许输出。

例如:有 wifi.driverwifi.mgntaudio.driver 3 种标签的日志,当设定过滤标签为 wifi 时,只有标签为 wifi.driverwifi.mgnt 的日志会输出。同理,当设置过滤标签为 driver 时,只有标签为 wifi.driveraudio.driver 的日志会输出。常见功能对应的函数调用与命令示例如下:

功能 函数调用 执行命令
设置过滤标签为 wifi ulog_global_filter_tag_set("wifi"); ulog_tag wifi
设置过滤标签为 driver ulog_global_filter_tag_set("driver"); ulog_tag dirver
设置日志级别为警告 ulog_global_filter_tag_set(""); ulog_tag

按关键词进行全局过滤

  • 函数:void ulog_global_filter_kw_set(const char *keyword)
  • 命令格式: ulog_kw [keyword] ,keyword 为空时,则取消关键词过滤

该过滤方式可以对所有日志执行按关键词过滤,包含关键词信息的日志才允许输出。常见功能对应的函数调用与命令示例如下:

功能 函数调用 执行命令
设置过滤关键词为 wifi ulog_global_filter_kw_set("wifi"); ulog_kw wifi
清空过滤关键词 ulog_global_filter_kw_set(""); ulog_kw

查看过滤器信息

在设定完过滤器参数后,如果想要查看当前过滤器信息,可以输入 ulog_filter 命令,大致效果如下:

msh />ulog_filter
--------------------------------------
ulog global filter:
level   : Debug  
tag     : NULL
keyword : NULL
--------------------------------------
ulog tag's level filter:
wifi                   : Warning
audio.driver           : Error  
msh />

提示:过滤参数也支持保存在 Flash 中,也支持开机自动装载配置。如果需要该功能,请查看 ulog_easyflash 软件包的使用说明。(点击查看

运行例程

依然是在 qemu BSP 中执行,首先在 menuconfig 开启动态过滤,然后保存配置并编译、运行例程,在日志输出约 20 次后,会执行 ulog_example.c 里对应的如下过滤代码:

if (count == 20)
{
    /* Set the global filer level is INFO. All of DEBUG log will stop output */
    ulog_global_filter_lvl_set(LOG_LVL_INFO);
    /* Set the test tag's level filter's level is ERROR. The DEBUG, INFO, WARNING log will stop output. */
    ulog_tag_lvl_filter_set("test", LOG_LVL_ERROR);
}
...

此时全局的过滤级别由于被设定到了 INFO 级别,所以无法再看到比 INFO 级别低的日志。同时,又将 test 标签的日志输出级别设定为 ERROR ,此时 test 标签里比 ERROR 低的日志也都停止输出了。在每条日志里都有当前日志输出次数的计数值,对比的效果如下:

ulog 过滤器例程20

在日志输出约 30 次后,会执行 ulog_example.c 里对应的如下过滤代码:

...
else if (count == 30)
{
    /* Set the example tag's level filter's level is LOG_FILTER_LVL_SILENT, the log enter silent mode. */
    ulog_tag_lvl_filter_set("example", LOG_FILTER_LVL_SILENT);
    /* Set the test tag's level filter's level is WARNING. The DEBUG, INFO log will stop output. */
    ulog_tag_lvl_filter_set("test", LOG_LVL_WARNING);
}
...

此时又新增了 example 模块的过滤器,并且是将这个模块的所有日志都停止输出,所以接下来将看不到该模块日志。同时,又将 test 标签的日志输出级别降低为 WARING ,此时就只能看到 test 标签的 WARING 与 ERROR 级别日志 。效果如下:

ulog 过滤器例程30

在日志输出约 40 次后,会执行 ulog_example.c 里对应的如下过滤代码:

...
else if (count == 40)
{
    /* Set the test tag's level filter's level is LOG_FILTER_LVL_ALL. All level log will resume output. */
    ulog_tag_lvl_filter_set("test", LOG_FILTER_LVL_ALL);
    /* Set the global filer level is LOG_FILTER_LVL_ALL. All level log will resume output */
    ulog_global_filter_lvl_set(LOG_FILTER_LVL_ALL);
}

此时将 test 模块的日志输出级别调整为 LOG_FILTER_LVL_ALL ,即不再过滤该模块任何级别的日志。同时,又将全局过滤级别设定为 LOG_FILTER_LVL_ALL ,所以接下来 test 模块的全部日志将恢复输出。效果如下:

ulog 过滤器例程40

系统异常时的使用

由于 ulog 的异步模式具有缓存机制,注册进来的后端内部也可能具有缓存。如果系统出现了 hardfault 、断言等错误情况,但缓存中还有日志没有输出出来,这可能会导致日志丢失的问题,对于查找异常的原因会无从入手。

针对这种场景,ulog 提供了统一的日志 flush 函数: void ulog_flush(void) ,当出现异常时,输出异常信息日志时,同时再调用该函数,即可保证缓存中剩余的日志也能够输出到后端中去。

下面以 RT-Thread 的断言及 CmBacktrace 进行举例:

断言

RT-Thread 的断言支持断言回调(hook),我们定义一个类似如下的断言 hook 函数,然后通过 rt_assert_set_hook(rtt_user_assert_hook); 函数将其设置到系统中即可。

static void rtt_user_assert_hook(const char* ex, const char* func, rt_size_t line)
{
    rt_enter_critical();

    ulog_output(LOG_LVL_ASSERT, "rtt", RT_TRUE, "(%s) has assert failed at %s:%ld.", ex, func, line);
    /* flush all log */
    ulog_flush();
    while(1);
}

CmBacktrace

CmBacktrace 是一个 ARM Cortex-M 系列 MCU 的错误诊断库,它也有对应 RT-Thread 软件包,并且最新版的软件包已经做好了针对于 ulog 的适配。里面适配代码位于 cmb_cfg.h

...
/* print line, must config by user */
#include <rtthread.h>
#ifndef RT_USING_ULOG
#define cmb_println(...)               rt_kprintf(__VA_ARGS__);rt_kprintf("\r\n")
#else
#include <ulog.h>
#define cmb_println(...)               ulog_e("cmb", __VA_ARGS__);ulog_flush()
#endif /* RT_USING_ULOG */
...

由此可以看出,当启用了 ulog 以后,CmBacktrace 的每一条日志输出时都会使用错误级别,并且会同时执行 ulog_flush ,用户无需再做任何修改。

syslog 模式

在 Unix 类操作系统上,syslog 广泛应用于系统日志。syslog 常见的后端有文件和网络,syslog 日志可以记录在本地文件中,也可以通过网络发送到接收 syslog 的服务器 。

ulog 提供了 syslog 模式的支持,不仅仅前端 API 与 syslog API 完全一致,日志的格式也符合 RFC 标准。但需要注意的是,在开启 syslog 模式后,不管使用哪一种日志输出 API ,整个 ulog 的日志输出格式都会采用 syslog 格式。

syslog 配置

只需要开启 Enable syslog format log and API. 选项即可。

日志的格式

ulog syslog 格式

如上图所示,ulog syslog 日志格式分为下面 4 个部分:

  • PRI :PRI 部分由尖括号包含的一个数字构成,这个数字包含了程序模块(Facility)、严重性(Severity)信息,是由 Facility 乘以 8,然后加上 Severity 得来。 Facility 和 Severity 由 syslog 函数的入参传入,具体数值详见 syslog.h;
  • Header :Header 部分主要是时间戳,指示当前日志的时间;
  • TAG :当前日志的标签,可以通过 openlog 函数入参传入,如果不指定将会使用 rtt 作为默认标签;
  • Content :日志的具体内容。

使用方法

使用前需要在 menuconfig 中开启 syslog 选项,主要常用的 API 有:

  • 打开 syslog:void openlog(const char *ident, int option, int facility)

  • 输出 syslog 日志:void syslog(int priority, const char *format, ...)

提示:调用 openlog 是可选择的。如果不调用 openlog ,则在第一次调用 syslog 时,自动调用 openlog

syslog() 函数的使用方法也非常简单,其入参格式与 printf 函数一致。在 ulog_example.c 中也有 syslog 的例程,在 qemu 中的运行效果大致如下:

ulog syslog 例程

如何输出更加直观的日志

有了日志工具后,如果使用不当,也会造成日志被滥用、日志信息无法突出重点等问题。这里重点与大家分享下日志组件在使用时的一些技巧,让日志信息更加直观。主要关注点有:

日志标签分类

合理利用标签功能,每个模块代码在使用日志前,先明确好模块、子模块名称。这样也能让日志在最开始阶段就做好分类,为后期日志过滤也做好了准备。

合理利用日志级别

刚开始使用日志库时,大家会经常遇到 警告与错误 日志无法区分,信息与调试 日志无法区分,导致日志级别选择不合适。一些重要日志可能看不到,不重要的日志满天飞等问题。所以,在使用前务必仔细阅读《RT-Thread ulog 日志组件应用笔记 - 基础篇》的日志级别章节,针对各个级别划分,里面有明确的标准。

避免重复性冗余日志

在一些情况下会出现代码的重复调用或者循环执行,多次输出相同、相似的日志问题。这样的日志不仅会占用很大的系统资源,还会影响开发人员对于问题的定位。所以,在遇到这种情况时,建议增加对于重复性日志特殊处理,比如:让上层来输出一些业务有关的日志,底层只返回具体结果状态;同一个时间点下相同的日志,是否可以增加去重处理,在错误状态没有变化时,只输出一次等等。

开启更多的日志格式

ulog 默认的日志格式中没有开启时间戳及线程信息。这两个日志信息,在 RTOS 上挺实用。它们能帮助开发者直观的了解各个日志的运行时间点、时间差,还能清晰的看到是在哪个线程执行当前代码。所以如果条件允许,还是建议开启。

关闭不重要的日志

ulog 提供了多种维度的日志开关、过滤的功能,完全能够做到精细化控制,所以如果在调试某个功能模块时,可以适当关闭其他无关模块的日志输出,这样就可以聚焦在当前调试的模块上,更多关于日志过滤功能请阅读 《RT-Thread ulog 日志组件应用笔记 - 基础篇》设定级别的分类 章节及本应用笔记的 日志过滤器 章节 。

使用 rt_dbg.h 或 elog 的项目如何迁移

如果项目中以前使用的是这两类日志组件,当要使用 ulog 时,就会牵扯到如何让以前代码也支持 ulog ,下面将会重点介绍迁移过程。

从 rt_dbg.h 迁移

当前 rtdbg 已完成 无缝对接 ulog ,开启 ulog 后,旧项目中使用 rtdbg 的代码无需做任何修改,即可使用 ulog 完成日志输出。

从 elog(EasyLogger)迁移

如果无法确认某个源代码文件运行的目标平台上一定会使用 ulog ,那么还是建议在该文件中增加下面的改动:

#ifdef RT_USING_ULOG
#include <ulog.h>
#else
#include <elog.h>
#endif /* RT_USING_ULOG */

如果明确只会使用 ulog 组件后,那么只需将头文件引用从 elog.h 更换为 ulog .h,其他任何代码都无需改动。

常见问题

  • 1、运行出现警告提示:Warning: There is no enough buffer for saving async log, please increase the ULOG_ASYNC_OUTPUT_BUF_SIZE option.

当遇到该提示时,说明了在异步模式下的缓冲区出现了溢出的情况,这会导致一部分日志丢失,增大 ULOG_ASYNC_OUTPUT_BUF_SIZE 选项可以解决该问题。

  • 2、编译时提示:The idle thread stack size must more than 384 when using async output by idle (ULOG_ASYNC_OUTPUT_BY_IDLE)

在使用 idle 线程作为输出线程时,idle 线程的堆栈大小需要提高,这也取决于具体的后端设备,例如:控制台后端时,idle 线程至少得 384 字节。

参考

本文所有相关的 API

API 列表

API 位置
rt_err_t ulog_backend_register(ulog_backend_t backend, const char *name, rt_bool_t support_color) ulog.c
void ulog_async_output(void) ulog.c
int ulog_tag_lvl_filter_set(const char *tag, rt_uint32_t level) ulog.c
void ulog_global_filter_lvl_set(rt_uint32_t level) ulog.c
void ulog_global_filter_tag_set(const char *tag) ulog.c
void ulog_global_filter_kw_set(const char *keyword) ulog.c
void openlog(const char *ident, int option, int facility) syslog.c
void syslog(int priority, const char *format, ...) syslog.c
int setlogmask(int mask) syslog.c

核心 API 详解

注册后端设备
rt_err_t ulog_backend_register(ulog_backend_t backend, const char *name, rt_bool_t support_color)

将后端设备注册到 ulog 中,注册前确保后端设备结构体中的函数成员已设置。

参数 描述
backend AT 客户端使用设备名称
name 后端设备名称
support_color 是否支持彩色日志
返回 描述
>=0 成功
异步模式下输出全部日志
void ulog_async_output(void)

在异步模式下,如果想要使用其他非 idle 线程作为日志输出线程时,则需要在输出线程中循环调用该 API ,输出缓冲区中日志至所有的后端设备

按模块/标签的级别过滤日志
int ulog_tag_lvl_filter_set(const char *tag, rt_uint32_t level)

通过这个 API 可以按照标签的级别来过滤日志,例如:

/* 停止输出 wifi.driver 模块的日志 */
ulog_tag_lvl_filter_set("wifi.driver", LOG_FILTER_LVL_SILENT);
/* 停止 wifi.mgnt 模块 INFO 级别以下日志的输出 */
ulog_tag_lvl_filter_set("wifi.mgnt", LOG_LVL_INFO);
参数 描述
tag 日志的标签
level 设定的日志级别,详见 ulog_def.h
返回 描述
>=0 成功
-5 失败,没有足够的内存
按级别过滤日志(全局)
void ulog_global_filter_lvl_set(rt_uint32_t level)

设定全局的日志过滤器级别,低于这个级别的日志都将停止输出。可设定的级别包括:

级别 名称
LOG_LVL_ASSERT 断言
LOG_LVL_ERROR 错误
LOG_LVL_WARNING 警告
LOG_LVL_INFO 信息
LOG_LVL_DBG 调试
LOG_FILTER_LVL_SILENT 静默(停止输出)
LOG_FILTER_LVL_ALL 全部
参数 描述
level 设定的级别,详见上面的表格,也可见 ulog_def.h
按标签过滤日志(全局)
void ulog_global_filter_tag_set(const char *tag)

设定全局的日志过滤器标签,只有日志的标签内容中 包含 该设定字符串时,才会允许输出。

参数 描述
tag 设定的过滤标签
按关键词过滤日志(全局)
void ulog_global_filter_kw_set(const char *keyword)

设定全局的日志过滤器关键词,只有内容中包含该关键词的日志才会允许输出。

参数 描述
keyword 设定的过滤关键词

评论