前阵子调一个基于芯科 EFR32BG22 的 BLE 主机项目,功能本身不算复杂:扫描外设、发起连接、读特征值、接收通知。真正让我头疼的不是协议栈,而是调试过程——每次插上调试器打开 LOG,设备就像被下了咒一样乱套;关掉 LOG 又完全是摸着黑走路,出问题根本不知道发生在哪一环。后来我花了不少时间,把“能打印”和“在正确的时间、用正确的方式打印”这两件事彻底想明白了。这篇文章就把这段从踩坑到理清思路的完整过程记录下来,希望能帮到同样在做 BLE 主机开发、尤其是用芯科芯片的朋友。
1. BLE 主机调试,为什么偏偏绕不开 LOG 打印
1.1 BLE 主机的黑盒特性:断点会骗人,LOG 才是照妖镜
做 MCU 开发的人有个习惯,遇到 bug 先挂调试器、下断点、单步看变量。但这个套路在 BLE 主机场景下很容易失灵。BLE 主机要同时维护扫描、建链、加密、MTU 协商、GATT 发现、通知接收等多条逻辑链路,每一条链路都依赖严格的时序。你用断点把程序停住,整个射频协议栈也被一起冻住了,等你单步走完,外设早就因为超时把连接断掉了。你会看到极其诡异的现场:明明寄存器状态都对,变量值都合理,但设备就是连不上、收不到数据。这不是代码出了鬼,而是断点本身破坏了蓝牙协议的时间约束。
所以搞 BLE 主机开发,LOG 打印几乎是必备的调测手段。它得在不打断协议栈正常运行的前提下,把内部状态实时输出出来。比如连接参数更新失败、MTU 协商超时、GATT 服务发现顺序错乱、加密失败返回的错误码,这些信息只有通过 LOG 才能快速看到。我的习惯是:先把 LOG 通道调通,再开始写业务代码。谁先谁后,直接决定后续调试效率。
1.2 芯科 EFR32 平台上 LOG 输出路径的选型分析
芯科的 EFR32 系列(比如我用的 BG22)支持几种常见的 LOG 输出路径:UART、USB CDC、SEGGER RTT、SWO。每种方案都有适用场景,选错了后面全是坑。
UART 是最经典的方案。一根杜邦线接串口助手,115200 波特率,简单直接。它的优势是量产设备也能保留日志接口,只要引出 TX/RX/GND 三根线即可。缺点是打印本身要占用 CPU 时间,如果直接轮询发送,波特率又不够快,就会拖累协议栈时序。
USB CDC 的打印速度比 UART 快,不需要额外接 TX 线,插上 USB 就能看日志。但它的问题在于 USB 协议栈自身也有中断和调度开销,而且 EFR32BG22 这类芯片的 USB 资源有限,很多小封装型号根本没有 USB。如果你手头是 BG22 的 QFN32 封装,基本可以直接放弃 USB CDC。
SEGGER RTT 是我很推荐在开发阶段用的方案。它通过 J-Link 调试器的 SWD 接口传输数据,速度可以跑到 1MB/s 以上,比 UART 快一个数量级,而且不额外占用 UART 外设。缺点是必须挂 J-Link,量产现场没法用;另外 RTT 会占用一小块 RAM 作为缓冲区,在内存紧张的工程里也是成本。
SWO 是 ARM CoreSight 调试接口提供的一条单线跟踪输出,速度高、CPU 开销极小,但需要占用 SWO 引脚,而且部分芯片封装没有引出这个引脚,还要调试器支持 SWO 捕获。我在 BG22 上试过,波形倒是能出来,但配置调试器比较麻烦,后来就没再用。
综合来看,我的最终选择是 UART + DMA,理由很朴素:量产阶段可以保留同样的日志接口,开发阶段和现场阶段的行为一致,不容易出现“开发环境正常、量产环境翻车”的情况。这也是后面所有踩坑的主战场。
2. 芯科芯片 LOG 打印路上的三个隐藏坑
2.1 printf 重定向后乱码和丢字符,问题不在波特率
第一次在 EFR32 工程里调 UART 打印,我信心满满地配置好 GPIO、UART、时钟,然后在 main 函数里加了一句 printf,结果串口助手显示的是乱码。第一反应是波特率不对,重新确认了 115200、8N1,没问题;又怀疑时钟源没配好,检查 HFXO 也正常。后来发现真正的原因有两层。
第一层是 printf 的底层 retarget 实现问题。芯科 SDK 默认把 printf 重定向到某个底层字符发送函数,如果这个函数用的是阻塞轮询方式,发送每个字节前要等 TXE 标志。问题是 BLE 协议栈的中断优先级往往高于普通外设中断,在打印过程中如果有蓝牙事件进来,当前字节发送会被打断,等中断处理完再回来继续发,接收端看到的就是字节错乱。解决办法是把底层发送改成等待 TC 标志而不是 TXE,或者干脆用 DMA 搬运。
第二层是发送缓冲区溢出。printf 格式化出来的字符串先进入一个内部缓冲区,如果缓冲区只有几十字节,而你在一个循环里连续打印几百字节,底层发送速度跟不上,缓冲区就会溢出丢数据。我后来把发送缓冲区加大到 512 字节,并搭配 DMA 发送,这个问题才彻底解决。
2.2 日志级别配置的陷阱:不是所有日志都该打
Simplicity Studio 生成的工程默认带一套日志框架,有 error、warning、info、debug、verbose 几个级别。刚开始做项目时,我把全局日志级别拉到了 verbose,想着日志越详细越好。结果协议栈系统事件和底层驱动日志也跟着全部涌出来,一秒钟几百行,有用的业务日志被淹没在海量信息里,而且整个系统的实时性肉眼可见地下降。
这类问题属于“日志放大效应”:你以为自己在看有用的调试信息,实际是在给系统制造额外的负载。BLE SDK 自己有一套协议栈事件日志,比如连接事件、断开原因、加密状态变化,它和应用层的业务日志是两回事。正确的做法是把它们分开配置。应用层日志用 app_log 那一套,按模块拆分开关;协议栈层日志用 SDK 自带的 ILogger 配置,默认只开 error 级别,只有在需要排查链路层问题时才临时打开 verbose。
我在实际工程里定义了三个独立的日志开关:APP_LOG_ENABLE、STACK_LOG_ENABLE、RAW_LOG_ENABLE,分别控制应用日志、协议栈日志、原始数据日志。平时只开 APP_LOG,遇到链路问题才开 STACK,抓底层疑难问题才开 RAW。这样既不会淹没关键信息,也不会拖慢系统。
2.3 在 BLE 回调里直接打印的代价,比你想的严重得多
这个坑是我踩得最狠的。芯科的蓝牙协议栈采用事件驱动模型,所有蓝牙相关的事件都会汇聚到sl_bt_on_event这个回调函数里。我当时为了调试方便,直接在回调里加了一堆打印,打印扫描结果、打印连接状态、打印通知数据。刚开始低速运行还好,等到设备进入高频收发状态,系统开始频繁死机,有时候甚至直接触发看门狗复位。
原因是这个回调跑在协议栈任务上下文里,优先级相当高。如果你在回调里执行阻塞式 UART 打印,整个协议栈的事件处理就会被卡住。蓝牙连接事件间隔通常是 30 毫秒甚至更短,而打印 100 字节在 115200 波特率下需要约 8.7 毫秒,打印 200 字节就要 17 毫秒。如果协议栈还没来得及处理完连接事件,下一个事件又到了,就会出现事件堆积,轻则连接超时,重则协议栈任务崩溃。
正确的做法是在回调里只做数据拷贝,把需要打印的信息塞进一个内存队列,然后由一个独立的低优先级任务去消费这个队列并执行打印。这样回调函数只花几微秒,不阻塞协议栈事件处理。这也是很多商用方案常用的“异步日志”思路。
3. 一次实战排查:设备连上就断,日志一开就死
3.1 现象描述:看似稳定的工程,行为却反复无常
我当时的项目状态是:外设端用的是另一个芯科模块,广播一切正常;主机端能扫描到设备,也能发出连接请求,但连接建立后不到一秒就断开,抓到的断开原因是connection timeout。更奇怪的是,只要我把日志级别调低、减少打印量,连接就能维持久一点;把日志全关掉,连接偶尔能正常。这种“日志越详细,系统越不稳定”的反常现象,本身就说明问题出在日志系统与协议栈的配合上。
最先怀疑的是硬件:天线匹配、供电纹波、晶振精度。我用官方评估板替换了自己的主板,问题依旧,说明不是硬件问题。接着怀疑是射频参数配置不对,但换成官方的 empty sample 工程后,同样可以正常连接。于是锁定范围:问题在我自己写的应用代码里,具体来说是日志相关的那部分。
3.2 排查链路:从“全开”到“全关”的二分定位
排查过程我用的是经典的二分法。先把所有业务功能注释掉,只保留最基本的扫描和建链流程,不打印任何业务日志,连接稳定。然后逐步打开功能模块,每打开一个就测试一轮连接稳定性。当我打开“每 500 毫秒打印一次对端设备的全部特征值内容”这个调试代码时,连接立刻开始不稳定。
顺着这条线继续缩小范围,我把打印内容缩短为固定字符串“alive”,每 500 毫秒打印一次,连接也是稳定的。再恢复打印全部特征值内容,又不稳定了。对比两种情况的差异,区别只在于单次日志的数据量。我测了一下二进制特征值数据,一次打印大约 400 字节,在 115200 波特率下需要约 35 毫秒才能发完。而当时的连接事件间隔是 30 毫秒。一次日志打印占用的时间就超过了一个连接事件周期。
3.3 根因分析:用数据解释“日志挤压协议栈事件”
芯科的 BLE 协议栈在后台维护着一套事件调度机制,它的核心要求是:每个事件必须在下一个事件到来之前处理完。我算了一笔账:115200 波特率下,每发送 1 个字节需要约 86.8 微秒;400 字节就要约 34.7 毫秒。而我的连接事件间隔是 30 毫秒。也就是说,每次打印日志时,UART 发送这一个动作就直接占掉了超过一个连接周期的时间。在这个时间内,协议栈处理连接事件的窗口被严重挤压,堆栈事件越积越多,最终触发看门狗复位或者连接超时。
这里还有一个容易被忽略的细节:即便你不主动在回调里打印,只要应用任务里有一个高频率、大数据的日志输出,同样可能抢占 CPU。因为 UART 发送是外设操作,它在 DMA 模式下不占 CPU 时间,但如果你用阻塞轮询模式,每发一个字节 CPU 都要死等。而 BLE 协议栈对 CPU 的占用是突发性的,几个小时内可能都没事,一旦出现高频收发,日志就会成为压垮时序的最后一根稻草。
3.4 修复方案与验证:把日志“异步化”之后的世界
修复方案就是前文提到的异步日志。我在工程里加了一个环形缓冲区,容量设为 2048 字节,业务代码只负责把日志写入缓冲区,写入操作是纯内存操作,几微秒就完成。真正执行 UART 发送的是一个低优先级任务,它每隔一小段时间检查一次缓冲区,如果有数据就用 DMA 发送出去。由于发送任务优先级低于协议栈任务,蓝牙事件来临时会被优先处理,日志发送自然让路。
改完之后我连续跑了 12 个小时,连接稳定,没有一次掉线,日志内容也完整无丢失。为了验证极端情况,我把打印频率提到每 100 毫秒打印一次 400 字节内容,连续运行 2 小时,依然稳定。这里的关键是把“与协议栈共享 CPU 的阻塞打印”换成了“与协议栈抢占 CPU 的异步打印”,前者会堵车,后者只是排队。
3.5 顺带解决的日志丢帧问题
异步化之后还出现了一个小毛病:日志内容偶发丢帧,两行日志之间会有几个字符拼在一起。排查后发现是 DMA 发送和下次写入缓冲区之间的衔接问题。我在 DMA 发送完成中断里重置发送指针,但下一次写入可能在中断标志清掉之前就开始了,导致数据被覆盖。对策是用双缓冲,一个缓冲区在发送时,另一个缓冲区可以继续写入,交替使用。这个方案在串口打印里非常常用,改完之后日志输出再也没有丢过帧。
4. 把日志做成真正能用的调试系统:我的最终方案
4.1 分级日志 + 条件编译,让调试代码只属于调试构建
经历了前面这一轮折腾,我终于意识到日志打印不是“加个 printf”那么简单,它本质上是一个需要设计的数据通路。我最终的方案从五个维度来保证日志的可用性。
第一是分级。定义LOG_ERROR、LOG_WARN、LOG_INFO、LOG_DEBUG四类宏,每个宏内部带有文件名和行号信息。编译时通过一个全局宏控制当前编译版本允许的最低级别,比如发布版只保留 ERROR 和 WARN,开发版开 INFO,排查链路问题才开 DEBUG。这样日志代码在发布版本里几乎不占什么空间,也不会带来任何性能损耗。
第二是模块开关。工程里有扫描模块、连接管理模块、GATT 模块、外设任务模块,每个模块都有自己的打印宏,可以单独打开或关闭。比如只排查扫描问题时就只开SCAN_LOG,其他模块全部关闭,避免日志干扰。
4.2 时间戳和任务 ID,日志信息里最容易忽略的两件事
日志光有内容是不够的,还必须包含足够多的上下文。我在每条日志前自动加上 32 位递增计数的时间戳,单位是毫秒。这样就能精确知道两个事件之间隔了多久,判断是不是有异常延迟。还加了一个任务 ID 字段,用 1 到 3 个字符表示当前日志是哪个任务发出的,比如“APP”“STK”“SYS”。这两条信息联合起来,能快速分辨一条日志是协议栈任务产生的,还是应用任务产生的,排查并发问题的时候特别好用。
我举个例子:如果看到 “APP|12345|connection established”,后面紧跟 “STK|12349|connection timeout”,相隔 4 毫秒,那说明连接建立后立即发生了超时,问题大概率出在链路层参数配置。如果日志里没有任务 ID 和时间戳,两条日志混在一起是完全没法推导的。
4.3 环形缓冲区 + DMA,日志异步化的具体实现
以下是我最终采用的异步日志核心代码框架,实际项目中可以按需裁剪。我用一个环形缓冲区作为生产者队列,DMA 中断作为消费者,实现双缓冲发送。
#define LOG_BUFFER_SIZE 2048 static volatile uint16_t log_head = 0; static volatile uint16_t log_tail = 0; static uint8_t log_buffer[LOG_BUFFER_SIZE]; static uint8_t dma_tx_buffer[LOG_BUFFER_SIZE]; void log_write(const uint8_t *data, uint16_t len) { uint16_t i; for (i = 0; i < len; i++) { log_buffer[log_tail] = data[i]; log_tail = (log_tail + 1) % LOG_BUFFER_SIZE; } } void log_task(void) { uint16_t copy_len = 0; while (1) { if (log_head != log_tail) { copy_len = 0; while (log_head != log_tail && copy_len < LOG_BUFFER_SIZE) { dma_tx_buffer[copy_len] = log_buffer[log_head]; log_head = (log_head + 1) % LOG_BUFFER_SIZE; copy_len++; } uart_dma_send(dma_tx_buffer, copy_len); } os_delay(5); } }这段代码的好处是:业务代码写日志只花内存拷贝的时间,基本是微秒级;DMA 发送由外设自动完成,不占用 CPU;log_task是低优先级任务,协议栈事件可以被优先抢占。os_delay(5)的意思是每 5 毫秒检查一次缓冲区,如果日志量大,这个时间可以调小,代价是 CPU 占用升高。
4.4 协议级日志:Network Analyzer 才是深水区的杀手锏
应用层 LOG 再完善,也只能看到协议栈抛出的结果事件,看不到底层射频链路上的内容。真要排查疑难杂症,还得靠芯科的 Network Analyzer 工具。它本质上是一套集成的抓包方案,可以在 Simplicity Studio 里直接启动,配合 Wireshark 解析蓝牙协议包。它能抓取空中的数据包、连接参数更新请求、加密流程、ATT 错误码,甚至能还原出连接事件间隔和从机延迟参数。应用层 LOG 负责回答“协议栈告诉我什么错误”,Network Analyzer 负责回答“射频链路上实际发生了什么”。两个配合起来,绝大部分 BLE 问题都能快速定位。
举个例子,我之前遇到过 GATT 服务发现错乱,应用层 LOG 显示服务发现完成后没有拿到期望的 UUID。用 Network Analyzer 抓包后发现,对端在 ATT Read By Group Type Request 阶段返回了一个超长响应,分包逻辑在主机侧没有处理好。这种问题单纯看应用日志是看不出来的,必须看协议包。
4.5 自动化日志解析:让打印出的数据反哺调试效率
这是最后一个小技巧。UART 日志输出是一串文本,靠肉眼去扫效率太低。我写了一个简单的 Python 脚本,读取串口日志,按时间戳和任务 ID 做分类统计,能自动输出每个任务在单位时间内的日志条数、平均耗时、最大耗时。脚本还能按关键字过滤,比如过滤包含“error”或“timeout”的行。排查一段时间内的性能问题时,这个脚本能直接告诉我哪个任务打印最频繁、哪个任务卡顿最严重,省去了大量人工翻日志的时间。
5. 踩坑之后,我对 BLE 日志打印的几点最终心得
5.1 日志不是辅助功能,是系统的一部分
经过这一轮项目考验,我最大的体会是:在 BLE 主机这种对时序高度敏感的工程里,日志打印必须和业务代码一起设计,而不是事后随手加。从一开始就规划好日志通道、日志级别、异步发送机制,后续调试会顺畅很多。反过来,等出问题再回头补日志,往往已经错过了最佳排查时机。
5.2 打印不是越多越好,关键是带上上下文
在关键路径上打印时,不要只打印“connected”或“disconnected”这种孤零零的状态词,要把连接句柄、地址类型、错误码、当前状态机都带上。比如:
LOG_INFO("conn[%d] opened, addr_type=%d, err=0x%02x", handle, addr_type, result);这样一条日志提供的信息量,抵得上十条只有状态词的日志。排查问题时,错误码能直接指向协议栈定义的具体失败原因,省去对照手册的功夫。
5.3 特殊复用:把日志接口留到量产阶段
量产的设备不一定需要持续输出日志,但给它留一个日志接口,关键时刻能救命。我设计硬件时特意引出 TX/RX/GND 三个测试点,配合 4MB 的 flash 存储日志缓存区。产品在现场出问题时,可以直接读回缓存区的日志,配合时间戳重现现场流程,定位是不是链路异常导致的偶发故障。这个习惯已经帮我解决过不止一次远程问题。
做 BLE 主机开发,调试手段决定了你能走多快。LOG 打印看似基础,背后却是对协议栈时序、CPU 占用、外设特性的综合理解。希望这篇记录能让你少走点弯路。