Zephyr 的日志系统应该是很多同学从裸机或其它 RTOS 转过来时第一个要重新适应的模块。我见过不少工程,应用代码写得没问题,就是日志死活不出来,或者一开日志整个系统就被拖慢,最后排查半天发现都是 logging 的配置和用法没对上。这一篇就专门把这个模块从头到尾拆开讲清楚,从设计思路、配置选项、后端机制到实际排障,按着我平时调工程的经验顺序来写,看完基本能少踩一半的坑。
1. 日志系统整体设计:先弄懂级别、模块与后端这三件事
1.1 日志级别:从 ERR 到 DBG,数字越大越详细
Zephyr 日志系统沿用了一套嵌入式和 Linux 圈都比较熟悉的级别体系,但这里有一个特别容易记反的地方:数字越大,代表日志越详细,输出优先级反而越低。具体来说:
| 级别宏 | 数值 | 使用场景 |
|---|---|---|
| LOG_LEVEL_NONE | 0 | 关闭该模块的日志输出 |
| LOG_LEVEL_ERR | 1 | 不可恢复的错误、系统级故障 |
| LOG_LEVEL_WRN | 2 | 异常但不致命,可恢复的告警 |
| LOG_LEVEL_INF | 3 | 关键节点信息,比如启动流程、参数配置 |
| LOG_LEVEL_DBG | 4 | 调试信息,比如函数入口、中间变量、寄存器值 |
打个比方,ERR 级别是“必须有人来处理的紧急电话”,DBG 级别是“仅供内部查阅的流水账”。所以你在代码里看到LOG_INF和LOG_DBG,它们完全不是“一个高级一个低级”的差异,而是信息密度和重要程度不一样。实际调试的时候,把模块级别从 INF 调到 DBG,你会突然看到一大片平时被裁掉的信息,这也是刚上手时最直观的体验变化。
级别体系贯穿了 Zephyr 日志系统的三个作用位置:编译期裁剪、运行时过滤、输出端优先级。理解这一点,后面配置就不容易乱。
1.2 LOG_MODULE_REGISTER:给模块办一张日志身份证
Zephyr 里用日志,第一步几乎都是这两行:
#include <zephyr/logging/log.h> LOG_MODULE_REGISTER(app, LOG_LEVEL_DBG);这个宏做的事情远比看起来复杂。它不只是告诉编译器“我这段代码要打日志”,而是创建了一个日志源。每个日志源在系统里都有一个唯一的模块 ID、一个静态编译级别、一个可变的运行时级别,还会自动挂上模块名字。类似给每个功能模块办了张身份证,日志系统才能知道一条日志是谁发的、当前允许它发多详细的日志。
这里有一个很多文档没强调的点:LOG_MODULE_REGISTER 只能在一个编译单元中使用一次。如果一个模块由多个 .c 文件组成,其它文件要打日志,应该用LOG_MODULE_DECLARE声明引用同一个模块,而不是再次 REGISTER。我之前见过有人把 REGISTER 写在头文件里,结果只要有两个 .c 文件包含它,编译直接报错,因为重复注册了同一个日志源。
另外,REGISTER 的第二个参数是模块的默认编译期级别。这个参数的意思是:凡是级别高于这个值的日志调用,在编译阶段就直接被优化掉,连参数表达式都不会被求值。所以如果你把模块级别设成 LOG_LEVEL_INF,那么代码里所有 LOG_DBG 都不会进入二进制,相关字符串常量也不会占用 flash。这也是 Zephyr 日志系统比直接调 printf 更省资源的根本原因之一。
1.3 后端与消息流转:日志从调用点到串口之间发生了什么
日志级别解决的是“允许打什么”,那“日志最终去哪儿”就是后端的问题。Zephyr 里日志系统不直接做输出,而是把格式化后的消息转给后端。后端可以是 UART、RTT、网络、文件系统、内存缓冲区,甚至是你自己写的一个网络服务。
我画过一条流转链,基本是这样的:
日志调用宏 -> 过滤判断(编译期 + 运行时) -> 格式化(或仅打包参数) -> 消息队列(deferred 模式) -> 日志处理线程 -> 后端 API -> 实际输出设备这个设计的好处是解耦。你的应用代码只需要对着log.h里的宏喊一声“打条日志”,后面的事情一概不管。至于日志是进了串口还是进了网络协议栈,应用层完全无感知。这在做复杂系统时特别有用,比如产品量产阶段想把日志导向 RTT 方便产测,开发阶段想走 UART,只需要改配置,根本不用动业务代码。
理解这条链路,是排查日志问题的基本功。后面所有疑难杂症,几乎都是这条链路里某一段断了。
2. 配置项逐项拆解:用最少的开关把日志拉起来
2.1 最小可用配置:三行 prj.conf 起步
Zephyr 的日志系统不是开箱即用的,Kconfig 默认情况下CONFIG_LOG是关闭的。想跑起来,prj.conf 里至少要有这几项:
CONFIG_LOG=y CONFIG_LOG_MODE_IMMEDIATE=y CONFIG_LOG_BACKEND_UART=y这三行对应了三个最关键的关系:总开关开启、日志处理模式选择直接输出、串口后端使能。有这三行,你的LOG_INF就能从默认的串口控制台里出来了。
我见过不少人在这里漏掉CONFIG_LOG_BACKEND_UART=y,结果日志系统开了,但根本没有输出设备,所有日志全被丢弃,看起来就像日志没生效。实际上日志链路是通的,只是最后一段没接上。
还有一个容易混淆的点:CONFIG_LOG和CONFIG_PRINTK是两套独立的东西。printk 走的是内核自己的输出通道,虽然最终可能也在同一个串口上,但它不经过日志系统的过滤、格式化和后端机制。如果你把某个模块的日志级别调成 NONE,printk 照样会输出,别指望用日志过滤去管住业务代码里的 printk。
2.2 immediate 与 deferred:两条完全不同的性能路线
日志的模式选择是整个系统里最影响性能的一个决策。CONFIG_LOG_MODE_IMMEDIATE表示日志调用点在当前线程上下文里直接同步完成格式化并推给后端。好处是实时性好,日志和实际事件发生的时间点完全同步,排查时序问题很方便;坏处是日志处理会阻塞当前线程,如果在中断处理函数里打日志,串口写入这种耗时的操作会直接拉长中断响应时间。
CONFIG_LOG_MODE_DEFERRED则相反,日志调用点只把消息封装好丢进一个内核消息队列,真正格式化和输出由专门的日志处理线程在后台完成。好处是调用点开销极小,就算在传感器中断里频繁打日志,也不会长期占用中断上下文;坏处是消息是异步处理的,严重偶发故障时最后几条日志可能来不及刷出。
实际选型我有一个比较稳的经验:
- 开发调试阶段,能接受一点性能损失,优先用 immediate,排查逻辑问题最方便。
- 做性能测试、跑外设中断、处理高频采样数据,切到 deferred。
- 如果项目对日志的实时性有硬指标要求,比如必须证明某中断在某时确实被触发过,那只能 immediate,别想太多。
有一点要提醒:deferred 模式下,如果日志消息队列满了,新的日志会被丢弃。这意味着系统越接近崩溃、日志越关键的时候,越可能丢日志。所以我在正式版本里通常会把日志级别调低,只在调试版本里开全量日志。
2.3 运行时过滤:不重新编译也能调日志等级
编译期裁剪能省 flash 和 CPU,但缺点是改日志级别必须重新编译烧录。Zephyr 提供了运行时过滤机制,打开CONFIG_LOG_RUNTIME_FILTERING=y之后,每个日志源的动态级别可以和编译期级别不同,动态级别只要不高于编译期级别就能生效。
比如模块注册时静态级别是 DBG,意味着所有日志代码都被编进去了。运行时你可以把它动态降成 ERR,这样一来 DBG 和 INF 的调用在调用点会被快速跳过,不执行格式化。这种做法很适合产品现场:出厂固件保留完整日志代码,但默认运行时级别只显示 WRN,当现场出问题时通过后台命令把某模块提高到 DBG,抓到问题再降回来,整个过程不用重新烧固件。
代价也不是没有。运行时过滤需要内存存每个日志源的当前级别表,同时每个日志调用都会多一次表查询判断,带来的开销比纯编译期裁剪要大。所以追求极致性能的模块,还是老老实实靠编译期级别砍干净。
3. 实操复现:从最小工程到 Shell 动态调参
3.1 写一个可复现的最小示例工程
理论说了一堆,实际操作还是动手最直观。我通常用一个极简工程来验证日志系统是否正常。这里以 Zephyr 3.x 以上版本为例,应用目录结构就不展开了,直接看 prj.conf 和 main.c。
prj.conf:
CONFIG_LOG=y CONFIG_LOG_MODE_DEFERRED=y CONFIG_LOG_BACKEND_UART=y CONFIG_LOG_RUNTIME_FILTERING=y CONFIG_SHELL=ymain.c:
#include <zephyr/kernel.h> #include <zephyr/logging/log.h> #include <zephyr/shell/shell.h> LOG_MODULE_REGISTER(app, LOG_LEVEL_DBG); static int cmd_set_level(const struct shell *sh, size_t argc, char **argv) { int level = atoi(argv[1]); log_filter_set(0, 0, level); /* domain_id=0, src_id=0, 即 app 模块 */ return 0; } SHELL_CMD_ARG_REGISTER(set_level, NULL, "set log level", cmd_set_level, 2, 0); void main(void) { LOG_ERR("error-level message"); LOG_WRN("warn-level message"); LOG_INF("info-level message, %d", 42); LOG_DBG("debug-level message, %s", "can you see me?"); while (1) { k_sleep(K_MSEC(1000)); LOG_DBG("periodic debug tick"); } }构建运行就用标准的 west 命令:
west build -b native_sim -d build . west build -d build -t runnative_sim 不需要真实硬件,跑起来直接看控制台输出。你会看到这样几行:
[00:00:00.000,000] <err> app: error-level message [00:00:00.000,000] <wrn> app: warn-level message [00:00:00.000,000] <inf> app: info-level message, 42 [00:00:00.000,000] <dbg> app: debug-level message, can you see me?注意 LOG_ERR 第一行的时间戳是 0.000,因为它最先执行,系统时钟还没跑多少。如果你把模块注册级别改成LOG_LEVEL_INF,再编译一次,最后两行就不会出现,这就直观体验到了编译期裁剪。
3.2 日志后端切换:UART、RTT 与自定义后端
开发阶段最常用的是 UART 后端,也就是默认控制台输出,性能一般但够用。做低功耗调试或者不想打扰主串口时,RTT 后端是个好选择。RTT 通过调试探针的内存通道传输,不占用硬件 UART,也不影响实时性,速度比 UART 快得多。
打开 RTT 后端需要这样配置:
CONFIG_LOG_BACKEND_UART=n CONFIG_LOG_BACKEND_RTT=y CONFIG_USE_SEGGER_RTT=y这里有个坑:如果你同时开着 UART 和 RTT 两个后端,同一份日志会从两个口重复输出,调试端看到的就是一模一样的日志出现两遍,还容易混淆。所以我一般切换后端时会把另一个显式关掉,除非真有双路输出的需求。
自定义后端也没有想象中难。实现一组回调,注册进日志系统就行。核心是填充struct log_backend_api里的put函数,后端从data里拿到格式化后的字节流,把它转给你的目标设备。比如把日志转到一个自定义的加密通道,或者存进外部 SPI Flash,在这层都可以做。
#include <zephyr/logging/log_backend.h> static void my_put(const struct log_backend *backend, uint8_t *data, size_t len, size_t *processed) { /* 将 data 转发到自定义输出设备 */ my_output_write(data, len); *processed = len; } static const struct log_backend_api my_backend_api = { .put = my_put, }; LOG_BACKEND_DEFINE(my_backend, my_backend_api, false);这个自定义后端的注册是编译期静态完成的,不需要在 main 里手动初始化。这也是 Zephyr logging 设计得比较顺手的地方,新增一种输出设备,完全不改动已有业务模块。
3.3 进阶玩法:hexdump 和按实例独立过滤
普通文本日志适合看流程,但看协议帧、加密数据、传感器原始数据时,十六进制转储更方便。Zephyr 提供了LOG_HEXDUMP_*系列宏:
uint8_t packet[] = {0x01, 0xAA, 0x55, 0x00, 0xFF}; LOG_HEXDUMP_INF(packet, sizeof(packet), "rx packet");输出会自动按 16 字节一行排列,左侧是偏移量,中间是十六进制值,右侧是 ASCII 可见字符的对照。比起自己写一个 hex dump 函数,这行宏省了不少事,而且同样支持级别过滤。
还有一个容易被忽略的功能是按实例记录日志。普通模块是“一个源”,但有些场景下有多个同类型实例需要分别过滤。比如系统里有三个传感器,每个都要单独控制日志级别。这时候用LOG_INSTANCE_REGISTER可以给每个实例建一条日志源,再用LOG_INST_INF(instance, ...)打日志,每条实例可以独立设置运行时级别。这种需求在驱动开发里很常见,一套驱动代码管理多个同型号外设时,能单独打开某一个设备的调试信息极其有用。
4. 性能账本、坑点排查与排障速查
4.1 日志是怎么吃掉 CPU 和内存的
很多开发者低估了日志系统的开销,觉得“打几个字而已”。实际上日志的代价有两块:格式化开销和内存开销。
格式化开销主要体现在LOG_INF("%d %s", a, b)这类调用上。传入的参数类型、数量都会影响格式化函数的工作量。deferred 模式下虽然格式化的动作被挪到了日志线程,但如果日志线程的优先级比业务线程低,大量日志积压会让日志线程长期占满 CPU,反过来又耽误业务。日志线程的栈大小、消息池容量,都需要根据日志频率估算。
内存开销更容易被忽略。deferred 模式的核心数据结构是消息池,每条日志都要占用一块消息内存。假设你配置的消息池能容纳 64 条日志,每条消息又分配了 256 字节,那光日志系统就要吃掉 16KB RAM。小内存的 MCU 上,这个数字很可观。
所以我的习惯是:产品正式版把模块级别全部调到 WRN 或 ERR,同时把消息池调小,保证日志系统只在异常时使用。性能测试版本单独开一个配置片段,把 DBG 全打开,测完就关。不要企图一套配置走天下,日志配置应该是构建参数的一部分,跟着构建类型走。
4.2 高频问题排查速查表
我把平时遇到过的问题整理成了一张速查表,照方抓药基本都能解决:
| 现象 | 可能原因 | 处理方式 |
|---|---|---|
| 所有日志都不输出 | CONFIG_LOG 未开启 | 检查 prj.conf 是否包含 CONFIG_LOG=y |
| 日志有系统但看不到内容 | 后端未使能 | 确认 CONFIG_LOG_BACKEND_UART=y 或对应后端 |
| 部分模块没日志 | 静态级别低于调用级别 | 检查 LOG_MODULE_REGISTER 的第二个参数 |
| 之前有 DBG 突然没了 | 运行时级别被调低 | 用 log status / log level 恢复 |
| deferred 模式丢日志 | 消息池过小或处理线程优先级过低 | 调大消息池,或提高日志线程优先级 |
| 中断里打日志卡顿 | immediate 模式在 ISR 中同步写串口 | 改 deferred,或不在 ISR 高频打日志 |
| 日志重复输出 | 多个后端同时使能 | 只保留需要的后端,其它关掉 |
| 时间戳停在某个值 | 日志处理线程阻塞 | 检查是否有死锁或长任务占用日志线程 |
排查的时候我一般从上往下按链路走:先确认总开关,再确认后端,再确认模块级别,最后看运行时过滤。大多数问题出在中间两环,跟业务代码关系反而不大。
4.3 排障心得与建议
最后多写几句实践体会。
第一,日志不是越多越好。我见过有人把所有变量每个循环都打印一遍,日志系统跑起来后系统响应慢了 30%。这种问题的根源不是日志系统不够快,而是打日志的姿势太粗暴。高频路径上禁止打日志,尤其是函数的每层入口都打一遍,这种习惯要改掉。
第二,deferred 模式不等于零开销。虽然调用点开销很小,但日志处理线程本身要占 CPU,消息池要占内存。日志的最终代价永远存在,只是换了个地方和时间发生。
第三,shell 命令是调试日志问题的利器。打开 CONFIG_SHELL 后,在控制台输入log开头的命令可以查看当前所有日志源的状态、动态调整级别、开关后端。我之前遇到过生产环境不打印日志的问题,现场工程没法断点调试,就是在 shell 里把目标模块从 INF 调到 DBG,立刻定位到了问题模块。这块功能平时不用,但关键时刻能救命。
第四,多读源码胜过瞎猜。Zephyr logging 的核心代码在subsys/logging/目录下,文件不多,但注释和结构都很清晰。遇到奇怪的格式化输出或时序问题,直接翻源码比翻论坛帖子快得多。日志系统这种东西,一旦理解了消息流转链路,剩下的基本都是配置问题。
这一篇从设计到实操讲完了,配置文件、示例代码都是可以直接复制去跑的水平。下一篇如果接着写,我可能会聊聊 Zephyr 的 shell 子系统怎么和日志系统组合成一套完整的调试方案,或者讲讲日志网络后端在分布式场景里的玩法。具体写哪个,看到时候手上项目更缺哪块吧。