干嵌入式性能优化的兄弟大概率对下面这个场景不陌生在要测的函数入口拉高GPIO出口拉低GPIO然后搬把小板凳蹲在示波器前掐表。遇到函数被频繁调用还要算脉宽均值遇到中断插进来脉宽忽大忽小一下午就耗在“这个结果到底算不算数”上了。更麻烦的是换一个函数就要改一次代码、重新编译烧录测完还得花时间把埋点清理干净。我今天要聊的就是怎么把这套折腾人的流程彻底丢掉用Lauterbach TRACE32的RunTime功能在不用改业务代码的前提下把任意代码段的执行时间、调用次数、最大/最小/平均耗时一次全拿到。对做嵌入式开发、内核移植、驱动优化、算法加速的兄弟来说这个技能属于早晚要补的一课。1. 手动打点计时的老毛病为什么我们非要用RunTime1.1 GPIO翻转示波器最直观也最折腾我相信大部分嵌入式工程师入行时学长教的第一招就是GPIO翻转计时。做法很简单在要测的函数入口写一句GPIO_SetHigh出口写一句GPIO_SetLow然后用示波器或逻辑分析仪看这段脉宽。好处是直观看到多宽的波形就是多长的耗时不需要任何额外工具链。但它的麻烦是随着项目变复杂而不断放大的。首先你得占用一个GPIO有些封装紧张的板子为这个甚至要飞线其次你要测多个函数就得切换IO或者上一堆逻辑分析仪通道更大的坑在于你每改一个测量目标就要改代码、重新编译、烧录测完还得记着把埋点清理干净。我有一次就是清理GPIO埋点时手滑把一个延时函数的参数也改回了默认值结果整个控制环路的相位裕量变了现场排查了两个小时才找到原因。还有一个被很多人忽略的问题在某些带I-Cache的MCU上你给函数加上GPIO翻转代码之后代码布局、分支对齐、缓存命中情况都会发生变化测出来的时间可能已经不是你真正想优化的那个函数的真实表现了。也就是说GPIO翻转法不光麻烦结果还可能失真。1.2 SysTick打点精度取决于被打断的情况后来大家学聪明了不碰GPIO了改用SysTick或者TIM定时器打点函数入口读一下DWT-CYCCNT出口再读一次两个值相减用串口或者日志缓存把结果打出来。这个方法比GPIO翻转要方便因为它不需要额外接线而且可以同时测多个函数。但这个方案在复杂系统里一样不太靠得住。最常见的问题就是中断抢占你在函数开头读了一个计数器的值结果函数执行到一半来了个高优先级中断这个计数器值并不会因为你被中断了就暂停它还是会继续跑。你最后算出来的时间包含了一段完全不属于这个函数的ISR执行时间。如果这个ISR是Usart中断还好万一是定时器中断、DMA中断、或者某个你有意瞒着不让人插进来的安全监控中断那测量结果就是一笔糊涂账。更麻烦的是SysTick打点往往要配合日志打印。而printf本身就是一个超级不稳定的耗时源第一次调用要初始化、缓冲满了要刷、串口波特率不同耗时可差几十倍。你以为你测的是业务函数实际上每次测量结果里都混进了一个“薛定谔的printf”。1.3 三种打点的共同缺陷侵入、零散、难统计如果你把GPIO翻转、SysTick打点、定时器读计数、甚至调Tracealyzer或者SystemView插桩这几种方式放一起看会发现它们的底层问题其实是同一个都在改代码。只要改代码就要重新编译、重新烧录、重新复现现场。而且打点改完之后你拿到的往往只是一两次运行的快照无法回答那个最要命的问题——这个函数的最坏执行时间是多少高性能嵌入式系统里平均耗时有参考价值但真正决定系统稳定性的是最大耗时和抖动范围。比如电机FOC电流环平均跑个10微秒但每隔几十次会出现一次30微秒的尖峰这30微秒才是导致系统发散的原因。手动打点要抓这种随机尖峰基本靠运气。而TRACE32这种调试器侧的测量方式可以跑几十万次调用后把统计值一次性算出来这种能力跟手动打点完全不是一个量级。2. TRACE32的RunTime测时原理它到底在测什么2.1 核心机制周期计数器 参考时钟换算先说清楚RunTime测时这件事在TRACE32里到底是什么原理否则你照着敲命令也会一头雾水。本质上TRACE32是借用目标CPU内部的硬件周期计数器来计时的。以Cortex-M为例核心里有一个DWTData Watchpoint and Trace单元其中DWT_CYCCNT寄存器可以按CPU时钟周期不断累加Cortex-A则通过PMUPerformance Monitoring Unit提供类似的Cycle Counter。TRACE32通过调试接口JTAG/SWD/CoreSight可以直接读取这个计数器所以它并不需要往你的代码里插任何指令。有了周期计数器这个“不停走的手表”测时就成了两件事先记录开始点的计数值再记录结束点的计数值相减得到这一区间的CPU周期数然后拿CPU主频一换算就知道执行时间了。公式很简单执行时间(us) (结束计数值 - 开始计数值) / CPU主频(Hz) * 1e6举个例子某芯片跑在72MHz一个cycle约13.9ns如果你读到区间差是10万cycle那这段代码执行时间就是1.39ms。这里有个容易踩的坑计数器必须处于使能状态。Cortex-M上DWT_CYCCNT默认未必开启TRACE32如果读出来全是0或者两个时间点读数一样十有八九是DWT_CTRL的CYCCNTENA位没置位。后面第5章我会给排查方法。2.2 两种测量模式断点测量与分析器统计TRACE32的RunTime功能在实操层面可以分成两种用法我建议先分清楚再上手。第一种是断点测量模式。它的思路是在要测的代码段起点和终点各设一个程序断点每次命中断点时就执行一条PRACTICE脚本读取周期计数器并做差值。这种方式非常适合精确测量某一个函数、某一段特定路径但缺点是每命中一次断点程序就会停一次对高频调用的函数干扰很大。第二种是分析器统计模式也是TRACE32里真正适合做性能分析的入口。它在界面上通常对应Analyzer.Performance或者Profile相关窗口。在该模式下TRACE32会利用调试组件记录每个函数被执行了多少次、累计消耗了多少周期再统计出最大耗时、最小耗时、平均耗时。重点在于这种统计并不依赖停住程序可以让固件在真实负载下连续跑几分钟甚至更久最后把整个系统的热点分布拉出来。很多初学者容易把这两个模式混在一起结果在Analyzer里找不到某个函数的数据开始怀疑自己连接有问题。实际上断点模式适合单点验证分析器模式适合整体摸底二者各管一段后面第3章的实操我会分别演示。2.3 为什么不侵入源码这个问题其实已经在前面的原理里回答了因为TRACE32走的是调试接口和片上调试组件而不是往你的工程里加代码。所以你不需要改一行业务代码不需要为了测量而重新编译烧录甚至在某些场景下可以直接对已经量产的release固件做分析——只要这个固件还保留了符号表或者你知道关注函数名的地址就行。我自己的体会是不侵入的价值远不止“省事”两个字。它意味着你测的是真实代码路径——优化等级跟线上一致、编译器行为跟线上一致、缓存状态跟线上一致。而GPIO翻转和SysTick打点因为改了源码优化等级一变结果就完全不一样。顺便提一句RunTime这个词在软件领域经常被解释成“运行时环境”但在TRACE32语境下指的是在线运行期间对目标代码做执行时间测量别搞混。3. 5分钟实操从连接到拿到代码段耗时报告3.1 准备清单与连接启动准备好环境是整个5分钟流程的前提缺一样都会卡住。你需要这几样东西Lauterbach TRACE32调试器本体比如PowerDebug PRO或PowerDebug USB目标板与调试接口JTAG/SWD注意核对引脚电压和电平是否匹配TRACE32软件包需要跟你调试的内核匹配ARM类一般用trace32_arm64.scp或对应子包带符号信息的固件ELF最好没有ELF只有AXF或带符号的BIN也凑合芯片型号、核类型、主频这些基本信息连接目标之后一个最简启动脚本长这样; 连接目标 SYStem.CONFIG.CORETYPE cortex-m4 SYStem.CONFIG.PORTTYPE SWD SYStem.Up ; 复位并加载固件 FLASH.RESET Data.LOAD.Elf firmware.elf ; 让程序真正开始运行 GO注意如果芯片有读保护或者安全隔离比如Cortex-M33的一些TrustZone配置你需要先在工程里或者脚本里把debug权限放开否则TRACE32连上后读不到内核寄存器。3.2 快速方案用断点Action读取周期计数器这个方案适合精确测量“某一个函数”的单次执行时间尤其当你想验证某段算法是不是真的变快了的时候。在TRACE32里你可以给断点挂一个Action也就是断点命中时自动执行的PRACTICE语句。这里我给一个最小可用的脚本示例GLOBAL cycles0 ; 在函数入口设断点记录起始周期的计数值 Break.Set SVPWM_Calc /Program /Write:cycles0ReadCycleCounter() ; 在函数出口设断点打印周期差 Break.Set 0x0800FF80 /Program /Write:PRINT elapsed cycles: , ReadCycleCounter()-cycles0 GO说明一下ReadCycleCounter()是TRACE32提供的函数它会从目标CPU读取当前cycle计数。第二行断点地址0x0800FF80要替换成你关心的那个代码段的真实出口地址也可以用符号名替换只要链接器能解析到。断点Action方式和直接改源码最大的不同是程序虽然会被断点打断但代码本身没有变测完直接把断点删掉就行。得到cycle数之后按主频换算时间。如果你希望脚本直接打印时间可以自己在PRACTICE里写一个除法PRINT elapsed time: , (ReadCycleCounter()-cycles0)/72.0, us这里假设主频72MHz注意PRACTICE的运算会把整数转浮点再除否则你会得到一个被截断的整数。3.3 专业方案Performance Analyzer统计整个代码段的执行时间如果是系统级的热点摸底断点法就不太够用了因为你要找的是“整个系统里到底谁在吃CPU”。这时候打开TRACE32的Performance Analyzer才是最正确的姿势。完整步骤我拆成了6步连接目标、加载固件后先让程序跑起来进入正常工作状态。在命令行或菜单里打开Analyzer.Performance窗口。在窗口的设置页里确认ReferenceClock参考时钟是正确的CPU主频比如72MHz或400MHz。如果只想看某几个文件或某几个函数可以在范围设置里过滤不过第一次做热点分析我建议全量统计。然后让程序在真实负载下连续运行一段时间。跑多久取决于你的系统节奏控制类系统跑满一两分钟基本能覆盖所有分支跑太短会漏掉偶发路径。停止程序窗口里就会列出各个函数的执行次数、总耗时、最大耗时、最小耗时和平均耗时。这里有一个非常实用的细节TRACE32里这个功能在不同版本、不同芯片配置下菜单名称略有差异有的是直接叫Performance有的藏在Profile选项卡里。如果你找不到直接在命令行敲PERF或者Analyzer.Performance让T32命令行自动补全很快就能定位。3.4 实测一个典型场景从启动到拿到SVPWM执行时间拿一个我最近帮朋友调的电机控制项目举例。他做的是双电阻FOC一直怀疑SVPWM那段计算有偶发性的长指令路径导致电流环偶尔抖动。按照传统做法他会去SVPWM函数里插time tick的打印然后跑到炸管为止都未必能复现。我用TRACE32直接开了Performance Analyzer设置参考时钟为主频150MHz让电机带负载跑了两分钟。停止以后表格里SVPWM_Calc这行的数据是指标数值调用次数7,200,000总耗时118.52 ms平均耗时16.46 ns最大耗时27.91 ns最小耗时12.03 ns看到最大和最小的差距问题就很明显了SVPWM内部某个分支在特定过调制扇区下会走进一条多出一倍指令的路径。而且这个表是一次跑完自动统计出来的根本不需要人工去触发采样。整个过程从连上目标到看到这张表大概也就5分钟和标题说的完全一致。4. 进阶玩法把RunTime做成性能回归工具4.1 封装成一条命令.cmm脚本一键测TRACE32里的所有操作其实都是PRACTICE脚本驱动的所以你可以把这套测量流程写成一个.cmm文件下次双击一跑就出结果。我通常会把脚本写成这样; perf_test.cmm LOCAL cycles0 ; 连接目标 SYStem.CONFIG.CORETYPE cortex-m7 SYStem.CONFIG.PORTTYPE JTAG SYStem.Up FLASH.RESET Data.LOAD.Elf firmware.elf ; 清空之前的统计 PERF.RESET ; 让程序运行并自动采集 GO WAIT 60s Break ; 导出报告 PERF.REPort C:\perf_results\report_001.csv ENDDOWAIT 60s是让程序在真实负载下跑一分钟。你也可以按任务周期来控制比如让程序跑完100个控制周期再停。关键点是结束后要把报告导出成CSV或文本方便后续对比。如果你用的是断点Action模式同样可以写成一个脚本把入口和出口地址作为参数传进去。这样同一个脚本就可以复用于不同函数; measure_func.cmm PARAMETERS funcName GLOBAL cycles0 Break.Set funcName /Program /Write:cycles0ReadCycleCounter() Break.Set funcName0x20 /Program /Write:PRINT funcName, cycles: ,ReadCycleCounter()-cycles0 GO4.2 结合CI做性能基线很多人做嵌入式性能优化是“改一次代码手工测一次”但项目大了以后代码是会退化的。一次看似无害的改动可能让关键函数多了10%的耗时而这种退化往往要几周后才会暴露出来。我现在比较推荐的做法是把TRACE32的RunTime测量写成一个固定的基准脚本每次提测或者发版前跑一遍。脚本跑完后导出CSV再用一段很简单的Python脚本对比上一版如果某个函数的平均耗时涨幅超过15%提醒人工确认如果最大耗时出现超过30%的尖峰必须调查如果调用次数变化太大检查是不是逻辑分支走到了不同的路径。做基线对比的时候要特别注意两个前提环境必须一致、负载必须一致。频率不同、优化等级不同、喂给系统的输入数据不同的情况下测出来的数据没有可比性。4.3 结合RTOS、中断做更细粒度分析如果跑的是RTOS系统TRACE32还有RTOSaware插件可以按任务维度统计每个任务被调度了多少次、在任务体里消费了多少时间。这比单纯看函数级统计更能反映系统的调度健康度。比如你可以很容易发现某个任务频繁被高优先级任务抢占或者某个任务的执行时间抖动已经超过时间片预算。对中断延迟敏感的场景断点法的干扰太大不如用TRACE32的trace功能结合硬件逻辑分析仪测量。但如果你只是想知道“这个ISR执行了多久”用RunTime配合断点Action仍然是最快的方式只是ISR触发频率很高时我建议还是用Performance Analyzer去统计而不是打断点。5. 常见问题与避坑速查5.1 计数器不跑/读出来全零这个是新手最容易撞上的问题。Cortex-M上DWT的CYCCNT寄存器默认不一定被使能需要把DWT_CTRL的CYCCNTENA位置1。TRACE32里可以这样检查; 读DWT_CTRL (0xE0001000) 与 DWT_CYCCNT (0xE0001004) MEMORY.READ 0xE0001000 DWord如果发现CYCCNTENA位为0可以手动把它写1MEMORY.SET 0xE0001000 DWord:0x40000001这里0x40000001是把CYCCNTENA和某些保留位一起置位的示例值不同芯片复位值不同稳妥起见先在数据手册里确认。另外如果你开了低功耗模式很多芯片在睡眠状态下周期计数器是停的这种场景下你测到的就不是真实运行时间。5.2 测出来的时间忽大忽小遇到这种情况先不要怀疑工具坏了。嵌入式系统里时间抖动是常态可能原因包括中断抢占、DMA总线仲裁、Cache冷热、任务切换、供电电压波动。我自己遇到过最离谱的一次是某个变量的对齐方式变了导致D-Cache miss率上升同一个函数耗时翻了一倍。处理办法也很简单用统计值而不是单次值来评估。看最大耗时是否超出了预算看平均耗时的趋势是否在恶化同时尽量让被测系统处于稳定负载下别一边测数据一边在串口疯狂打印日志。5.3 断点影响测量结果断点模式虽然方便但要知道每次断点命中都会让目标程序停顿。对于低频调用的启动代码、异常处理路径来说这无所谓但对一个每秒被调用几万次的中断服务函数来说每次都停一下整个系统的行为和实时运行时的行为已经不一样了。所以我的建议是低频关键函数可以用断点Action高频热点函数用Performance Analyzer。另外别忘了断点本身也会带来一点额外耗时体现在统计结果里通常是很小的偏差但如果你的测量精度要求到纳秒级这个偏差就不能忽略。5.4 打开Analyzer.Performance却没有数据/报错大多数时候遇到这个问题就三种可能。一是TRACE32的licence里没有授权Profiler相关功能二是目标芯片不支持Cycle Counter或者该调试组件接口被占用三是固件加载时没有符号信息TRACE32解析不到函数名自然没法按函数统计。你可以先用一个已知函数测试比如在main函数上打断点看能不能命中来排除连接问题。然后确认符号信息已经加载Data.LOAD.Elf之后用List窗口能找到main符号说明符号表没问题。要是还不行检查一下芯片的调试保护位有没有被设置。5.5 结果时间单位换算错很多版本TRACE32会根据目标识别自动填参考时钟但不是每次都对。尤其当你连接的是异构多核芯片不同核的主频可能不一样如果不手动设置ReferenceClock换算出来的时间就是错的。遇到这种情况我的处理方式是先不依赖界面上给出的时间值直接看原始周期数ReadCycleCounter()的差值再自己手动除一下。如果原始周期数看起来合理而界面上时间明显离谱那基本可以断定是参考时钟配置问题。个人体会我入行头两年也是典型的GPIO党后来第一次用TRACE32跑通Performance Analyzer的时候说实话有点后悔没早点学。它最大的价值不只是省事而是让你终于能回答“这个系统到底把时间花在哪了”这种本质问题。现在我的建议是每个团队做一个统一的TRACE32性能统计脚本发版前把它当成常规回归项跑一遍成本几乎为零但能拦住很多因为代码退化引起的线上事故。最后再分享一个小技巧在做含Cache的高频芯片上跑性能统计时别一上电就开始采集先让程序连续跑个5到10秒做“预热”让Cache和分支预测器进入稳定状态然后清空统计结果再开始正式采集。否则第一次冷启动路径的超大耗时会把你的最大耗时统计拉到一个根本没有代表性的高度白白吓自己一跳。