Zephyr 的日志系统应该是很多同学从裸机或其它 RTOS 转过来时第一个要重新适应的模块。我见过不少工程应用代码写得没问题就是日志死活不出来或者一开日志整个系统就被拖慢最后排查半天发现都是 logging 的配置和用法没对上。这一篇就专门把这个模块从头到尾拆开讲清楚从设计思路、配置选项、后端机制到实际排障按着我平时调工程的经验顺序来写看完基本能少踩一半的坑。1. 日志系统整体设计先弄懂级别、模块与后端这三件事1.1 日志级别从 ERR 到 DBG数字越大越详细Zephyr 日志系统沿用了一套嵌入式和 Linux 圈都比较熟悉的级别体系但这里有一个特别容易记反的地方数字越大代表日志越详细输出优先级反而越低。具体来说级别宏数值使用场景LOG_LEVEL_NONE0关闭该模块的日志输出LOG_LEVEL_ERR1不可恢复的错误、系统级故障LOG_LEVEL_WRN2异常但不致命可恢复的告警LOG_LEVEL_INF3关键节点信息比如启动流程、参数配置LOG_LEVEL_DBG4调试信息比如函数入口、中间变量、寄存器值打个比方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_LOGy CONFIG_LOG_MODE_IMMEDIATEy CONFIG_LOG_BACKEND_UARTy这三行对应了三个最关键的关系总开关开启、日志处理模式选择直接输出、串口后端使能。有这三行你的LOG_INF就能从默认的串口控制台里出来了。我见过不少人在这里漏掉CONFIG_LOG_BACKEND_UARTy结果日志系统开了但根本没有输出设备所有日志全被丢弃看起来就像日志没生效。实际上日志链路是通的只是最后一段没接上。还有一个容易混淆的点CONFIG_LOG和CONFIG_PRINTK是两套独立的东西。printk 走的是内核自己的输出通道虽然最终可能也在同一个串口上但它不经过日志系统的过滤、格式化和后端机制。如果你把某个模块的日志级别调成 NONEprintk 照样会输出别指望用日志过滤去管住业务代码里的 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_FILTERINGy之后每个日志源的动态级别可以和编译期级别不同动态级别只要不高于编译期级别就能生效。比如模块注册时静态级别是 DBG意味着所有日志代码都被编进去了。运行时你可以把它动态降成 ERR这样一来 DBG 和 INF 的调用在调用点会被快速跳过不执行格式化。这种做法很适合产品现场出厂固件保留完整日志代码但默认运行时级别只显示 WRN当现场出问题时通过后台命令把某模块提高到 DBG抓到问题再降回来整个过程不用重新烧固件。代价也不是没有。运行时过滤需要内存存每个日志源的当前级别表同时每个日志调用都会多一次表查询判断带来的开销比纯编译期裁剪要大。所以追求极致性能的模块还是老老实实靠编译期级别砍干净。3. 实操复现从最小工程到 Shell 动态调参3.1 写一个可复现的最小示例工程理论说了一堆实际操作还是动手最直观。我通常用一个极简工程来验证日志系统是否正常。这里以 Zephyr 3.x 以上版本为例应用目录结构就不展开了直接看 prj.conf 和 main.c。prj.confCONFIG_LOGy CONFIG_LOG_MODE_DEFERREDy CONFIG_LOG_BACKEND_UARTy CONFIG_LOG_RUNTIME_FILTERINGy CONFIG_SHELLymain.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_id0, src_id0, 即 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_UARTn CONFIG_LOG_BACKEND_RTTy CONFIG_USE_SEGGER_RTTy这里有个坑如果你同时开着 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_LOGy日志有系统但看不到内容后端未使能确认 CONFIG_LOG_BACKEND_UARTy 或对应后端部分模块没日志静态级别低于调用级别检查 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 子系统怎么和日志系统组合成一套完整的调试方案或者讲讲日志网络后端在分布式场景里的玩法。具体写哪个看到时候手上项目更缺哪块吧。
