23、日志与Trace分析：logcat音频标签过滤、systrace抓取音频线程、分析Buffer underrun与overrun
做音频低延时优化，最怕什么？
怕问题复现了，但抓不到证据。
怕延时已经抖成心电图了，你还在那猜是哪段代码出了问题。
我个人习惯，拿到一个音频卡顿、断音、爆音的问题，第一件事不是翻代码，而是先看日志和Trace。说白了，先让系统自己“交代”它干了什么。今天我们就聊聊怎么用logcat和systrace这两把刀，把音频延时问题的根给刨出来。
23.1 logcat音频标签过滤：别让噪音淹了你
Android的logcat输出量巨大，你不加过滤，基本等于大海捞针。我见过不少同事，直接logcat -c清空然后logcat裸跑，然后盯着满屏的“I/ActivityManager”发呆……嗯，这样效率太低了。
对于音频问题，我们重点关注这几个Tag：
| Tag | 含义 | 我常用的过滤命令 |
|---|---|---|
AudioFlinger |
音频核心服务，混音、输出线程都在这里 | logcat -s AudioFlinger |
AudioTrack |
应用层音频播放通道 | logcat -s AudioTrack |
AudioRecord |
应用层音频录制通道 | logcat -s AudioRecord |
audio_hw_primary |
硬件抽象层，直接跟驱动打交道 | logcat -s audio_hw_primary |
tinyalsa |
ALSA用户空间接口，能看到PCM数据流状态 | logcat -s tinyalsa |
APM_AudioPolicyManager |
音频策略管理，路由、设备切换相关 | logcat -s APM_AudioPolicyManager |
logcat -s AudioFlinger AudioTrack audio_hw_primary。这样既不会漏掉关键信息，又不会刷屏。
举个例子，当你看到AudioFlinger里频繁出现buffer overflow或underrun字样，基本可以断定底层已经扛不住了。这时候再去查上层应用，意义不大。
23.2 systrace抓取音频线程：让时间轴说话
logcat能告诉你“发生了什么”，但很难告诉你“什么时候发生的”以及“持续了多久”。这时候就得请出systrace了。
我个人做低延时优化时，systrace是必开的。它能把CPU调度、线程状态、Binder调用、中断处理全部按时间轴展示出来。音频问题，说白了就是时间问题。
抓取音频相关线程的命令：
# 抓取所有音频相关线程，持续10秒
python systrace.py -t 10 -o audio_trace.html \
--app=com.yourapp \
sched freq idle load am wm gfx view \
-a AudioFlinger AudioTrack AudioRecord打开生成的audio_trace.html，重点关注这几个线程：
- AudioOut_* 或 AudioIn_*：这是AudioFlinger创建的工作线程，负责真正的音频数据搬运。
- mixer_*：混音线程，多个音源叠加的地方。
- 你的应用主线程或音频处理线程：看看它是不是被其他任务阻塞了。
我曾经遇到一个案例，应用层音频线程每隔几百毫秒就出现一个“running”到“uninterruptible sleep”的跳变。点进去一看，是在等一个Binder调用返回。说白了，就是主线程在等一个耗时的I/O操作，导致音频数据没能及时写入缓冲区，underrun就来了。
23.3 分析Buffer underrun与overrun：从现象到根因
好，现在日志和Trace都抓到了，怎么分析？
我一般分三步走：
- 确认现象：logcat里有没有
underrun或overrun关键字？systrace里音频线程有没有长时间不运行？ - 定位瓶颈：是CPU不够（线程被抢占），还是锁竞争（Binder调用阻塞），还是驱动响应慢（中断延迟高）？
- 量化指标：underrun持续了多少毫秒？发生频率是多少？
举个例子，下面这段logcat输出：
I/AudioFlinger( 1234): Buffer underrun at position 1024, frames missing: 48
I/AudioFlinger( 1234): Buffer underrun at position 2048, frames missing: 32这说明音频数据每次写入都差了那么几十个采样点。48个帧，在48kHz采样率下就是1毫秒的断音。虽然人耳不一定能察觉单次1ms的断音，但如果每秒出现几十次，那就是明显的咔咔声了。
这时候打开systrace，看看AudioOut_*线程在发生underrun的时间点前后在干什么。我见过的情况：
- 线程被调度出去，等了5ms才回来——这是CPU负载过高，优先级不够。
- 线程在等一个
write()系统调用返回——这是驱动层处理太慢，或者DMA传输没完成。 - 线程在等
AudioTrack::obtainBuffer()——这是应用层写入不及时，缓冲区空了。
23.4 知识体系：一张图理清分析流程
下面这张图，是我自己总结的音频延时问题分析流程。每次遇到新问题，我就按这个框架走一遍，基本不会漏掉关键环节。
这张图从左到右，从上到下，就是我每次排查音频问题的标准路线。你照着走一遍，基本能把问题锁定在某个层面。
23.5 避坑指南：我踩过的几个坑
最后分享几个实战中容易忽略的点：
- 别只看平均延时：平均延时低不代表没有underrun。峰值延时才是杀手。systrace里要看最大间隔，不是平均间隔。
- 注意logcat的丢日志问题：当系统负载很高时，logcat本身也会丢日志。你看到的underrun次数可能只是冰山一角。配合systrace的计数事件会更准。
- 区分“应用层underrun”和“驱动层underrun”：
AudioTrack报underrun，可能是应用没及时写数据；audio_hw_primary报underrun，那是驱动没从DMA缓冲区拿到数据。两个层面，解法完全不同。
我曾经在一个项目里，logcat里underrun报得飞起，但systrace一看，音频线程跑得稳稳的，CPU占用也不高。后来才发现是DMA的buffer size配置太小，驱动层在中断处理里频繁重传。说白了，硬件参数没调对。这个坑，我印象很深。
好了，日志和Trace分析这块就聊到这儿。工具是死的，思路是活的。多抓几次，多对比正常和异常的时间轴，你慢慢就能一眼看出问题在哪。
公众号:蓝海资料掘金营，微信deep3321