在开源大流行和AI会写代码的时代里,软件调试正变得越来越难。
为什么呢?原因有很多。比较重要的一点是开源和AI两股力量都导致代码很容易得到,很容易得到就导致代码迅速聚拢和堆积,形成一个庞大的代码系统,这些代码有的来自开源,有的来自AI,有的来自人工。然后,代码聚集容易,消化困难。五花八门、纵横交错的代码堆积到一起后,有些地方并不刚好契合,有的能工作到一起,有的就不能工作到一起。一旦出了问题,很难找原因和调试。
空说无凭,还是举个例子吧。最近大约一个月时间里,我一直在调试,解决了一个问题之后,还有下一个。因此,可以选的例子很多,今天讲一下刚刚解决的“声卡无声”问题吧。
我曾经写过一篇文章,题目叫《比内存被踩还难调试的问题》。在那篇文章里,我把声音问题称作比内存被踩还难调试的问题。今天看来,当时的问题还算简单,只是用户空间的配置问题。与上一次相比,这一次的问题还要难很多。
升级到内核6
简单来说,这一次的问题发生在新升级的Linux内核6上。所谓内核6是说Linux内核的主版本号是6,具体说是6.1.115。上一次的内核版本是5.10。内核6是Linux内核目前的最高版本。
有人说,把Linux内核从5升级到6很难吗?是的,很难。如果你觉得很简单,那么请再想一想。
为什么呢?一个简单的原因是,Linux内核恪守的原则是保持应用程序兼容,内核空间的代码不需要兼容。不需要兼容的好处是可以放开量修改,发现不好的就改,怎么合理就怎么改,不需要考虑兼容老的代码。因为此,导致新的内核经常有“破坏性”的修改。
以幽兰代码本为例,本来使用的是内核5,经过1年多的努力,各项功能已经工作的比较好。但是当把代码切换到内核6后,很快就测试出来了一堆问题。
从用户空间开始排查
我是从上周五(5月9日)开始调查这个声音问题的。我先用aplay播放wav文件,果然没有声音。使用声音设置界面测试,可以看到界面上的声音动画在跳动,但是也没有声音,看来很容易重现问题。
问题重现之后,接下来的任务就是要找BUG,从哪里下手呢?
我先用pw-config检查配置文件,没有发现问题。
geduer@ulan:~$ pw-config{ "config.path": "/usr/share/pipewire/pipewire.conf"}
接下来使用alsactl info命令来观察声音设备,列出了两个声音设备,一个是es8326,另一个是HDMI声音接口,这个结果和实际情况是完全一致的。
geduer@ulan:~$ alsactl info## Sound card#- card: 0 id: rockchipes8326 name: rockchip-es8326 longname: rockchip-es8326 driver_name: rockchip-es8326 mixer_name: components: controls_count: 21 pcm: - stream: PLAYBACK devices: - device: 0 id: dailink-multicodecs ES8326.3-0019-0 name: dailink-multicodecs ES8326.3-0019-0 subdevices: - subdevice: 0 name: subdevice #0 - stream: CAPTURE devices: - device: 0 id: dailink-multicodecs ES8326.3-0019-0 name: dailink-multicodecs ES8326.3-0019-0 subdevices: - subdevice: 0 name: subdevice #0## Sound card#- card: 1 id: rockchiphdmi0 name: rockchip-hdmi0 longname: rockchip-hdmi0 driver_name: rockchip-hdmi0 mixer_name: components: controls_count: 6 pcm: - stream: PLAYBACK devices: - device: 0 id: rockchip-hdmi0 i2s-hifi-0 name: rockchip-hdmi0 i2s-hifi-0 subdevices: - subdevice: 0 name: subdevice #0
使用strace追踪alsactl的工作过程,可以看到它打开声音设备的细节。
openat(AT_FDCWD, "/dev/snd/controlC0", O_RDONLY|O_CLOEXEC) = 3ioctl(3, SNDRV_CTL_IOCTL_CARD_INFO, 0x7fe48bc5b0) = 0close(3) = 0openat(AT_FDCWD, "/dev/snd/controlC0", O_RDWR|O_CLOEXEC) = 3ioctl(3, SNDRV_CTL_IOCTL_PVERSION, 0x7fe48bc9f4) = 0ioctl(3, SNDRV_CTL_IOCTL_CARD_INFO, 0x7fe48bc9a0) = 0newfstatat(1, "", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x1), ...}, AT_EMPTY_PATH) = 0write(1, "#\n", 2#) = 2write(1, "# Sound card\n", 13# Sound card) = 13write(1, "#\n", 2#) = 2write(1, "- card: 0\n id: rockchipes8326\n "..., 83- card: 0 id: rockchipes8326 name: rockchip-es8326 longname: rockchip-es8326) = 83write(1, " driver_name: rockchip-es8326\n", 31 driver_name: rockchip-es8326
使用pw-top命令来观察,也可以看到音频数据播放的活动过程,数据的流向也是正确的。
测试时,起初我用aplay播放小的wav文件,但是很快就结束了,后来改用mpv播放我喜欢的梁祝音乐,整个乐曲的长度大约4分多钟,足够测试用了。
开启内核空间的动态打印
在用户空间没有发现异常后,我把战场转移到内核空间。找到声卡设备的驱动程序es8326.c。看到里面有使用dev_xxx这样的动态打印,于是便先通过虚文件接口将其启用。
sudo su
cd /sys/kerenl/debug/dynamic_debug
echo "module snd_soc_es8326 +p" > control
顺便还启用了声卡有关的一些动态打印:
echo "module snd_soc_core +p" > control
这样启用后,再播放声音时,可以看到内核空间是有活动的。
[ 1437.259697] dailink-multicodecs: ASoC: ES8326 HiFi <-> fe470000.i2s info:[ 1437.259749] dailink-multicodecs: ASoC: rate mask 0x7fe[ 1437.259777] dailink-multicodecs: ASoC: ch min 2 max 2[ 1437.259803] dailink-multicodecs: ASoC: rate min 8000 max 96000[ 1437.265594] ES8326 3-0019: Update DAI routes for ES8326 HiFi playback[ 1437.265648] ES8326 3-0019: Connecting DAI route Playback -> I2S IN[ 1437.265774] rockchip-i2s-tdm fe470000.i2s: stream[0]: ffffff8100caac00, rate: 48000, channels: 2, width: 16[ 1437.265824] rockchip-i2s-tdm fe470000.i2s: data: 48000, fifo: 16, fifo time: 333 us, stall time: 120 us[ 1437.265873] rockchip-i2s-tdm fe470000.i2s: Update DAI routes for fe470000.i2s playback[ 1437.277468] ES8326 3-0019: es8326_set_bias_level SND_SOC_BIAS_ON
上面的做法是临时性的,重启还需要重新设置,而且看不到启动时的,于是我打开幽兰的启动配置文件ylboot.ini,在内核的命令行参数选项中增加如下内容:
dyndbg='module snd_soc_es8326 +p' loglevel=7
修改后的ini文件为:
[sum]default=krnl6
[krnl5]kernel=/Image-5xinitramfs=initrd.img-5.10.110-rockchip-rk3588-taiyiBootArgs=systemd.debug_shell=1 cloud-init=disableddtb=/dtb/rockchip/yourland.dtb
[krnl6]kernel=Image6dtb=/dtb/rockchip/yourland6.dtbinitramfs=BootArgs=systemd.debug_shell=1 cloud-init=disabled dyndbg="module snd_soc_es8326 +p" loglevel=8rootfs=/dev/nvme0n1p4
这样,就可以看到8326驱动在启动时打印的消息。
geduer@ulan:~$ dmesg | grep 8326[ 44.566939] Kernel command line: root=/dev/nvme0n1p4 rootfstype=ext4 rw console=ttyFIQ0,1500000 psi=1 rootwait quiet splash earlyprintk earlyprintk=ttyFIQ0,1500000 verbose nokaslr systemd.debug_shell=1 cloud-init=disabled dyndbg="module snd_soc_es8326 +p" loglevel=8[ 46.832623] NET: Registered PF_NETLINK/PF_ROUTE protocol family[ 49.472245] ES8326 3-0019: master mode 0[ 49.472262] ES8326 3-0019: mic1-src 22[ 49.472273] ES8326 3-0019: mic2-src 44[ 49.472284] ES8326 3-0019: jack-pol 7[ 49.472294] ES8326 3-0019: mclk-rate return -22[ 49.472304] ES8326 3-0019: mclk-rate 12288000[ 49.472852] ES8326 3-0019: Getting irq success.[ 49.483858] rk-multicodecs es8326-sound: Has no ADC channel[ 49.583233] ES8326 3-0019: Enter into es8326_set_jack jack:(____ptrval____)[ 49.595620] input: rockchip-es8326 Headset as /devices/platform/es8326-sound/sound/card0/input1[ 49.804914] ES8326 3-0019: es8326_hpdetect_work fb=0x00[ 49.804936] ES8326 3-0019: No headset detected[ 50.065381] #0: rockchip-es8326
除了上面的试验外,中间还浪费了一些时间在检查设备文件权限,以及pipewire服务上。因此,一天时间很快过去了。周五晚上7点多时,我突然想起了求助外援。去年在做WoA的声卡驱动时,认识了非常熟悉es8326芯片的彭工。于是我找到彭工的微信,给他发了一条消息:
“你好彭工,我们在升级Linux内核6,升级后没有声音,系统能检测到设备,播放时看起来在正常工作,但是听不到任何声音,偶尔听到pop声,方便时可否指点一下思路?”
排查硬件寄存器
回到家里后,我收到彭工的回复:“可以打印寄存器值出来看看”
看了这个建议后,我由衷地赞赏彭工,他的建议很专业,不盲目猜测,建议收集故障数据。寄存器是软硬件之间的桥梁,把声卡芯片的寄存器读出来,就知道声卡芯片的状态啊。
想到这里,我又鼓足了信心。周一一早到办公室,就安装i2c工具。
然后通过i2c接口把es8326的寄存器转储出来,发给了彭工。
几分钟后,收到彭工的回复:“这个看起来没有初始化吧”
我看了一下驱动的代码,应该是初始化了的啊。为了比较差异,我又找来一台使用内核5的幽兰,也把寄存器转储出来。
二者比较,的确有不少差异。
接下来,花了不少时间来熟悉和比较寄存器。以下是不同情况时的一些截图。
其二。
其三。
在这个过程中,还找到了读设备寄存器的另一种方法:通过debugfs下的regmap接口。
root@ulan:/sys/kernel/debug/regmap/3-0019# cat registers
00: 8001: 7f02: 0003: 0504: 0105: 0006: 3007: 2d08: 2609: 260a: 1f0b: 1f0c: 1f0d: 030e: 000f: ff10: c8
花了一上午时间比较寄存器后,仍没有发现实质性的问题。8326的寄存器总共有256个字节。i2cdump一次就可以都显示出来,比较也很容易。但是有些差异可能是合理的,因为环境不同可能就是有一些差异。
感觉有些疲倦后,我尝试使用第二个HDMI声音设备播放声音,另一端连接一个有音响的显示器,结果很正常,我播放的是horse.wav,可以听到马的一声长鸣,这个声音在寂静的办公室里响起,格外响亮。
在我一边比较寄存器,一边看代码时,下面几行代码引起了我的注意:
static int es8326_suspend(struct snd_soc_component *component){ /* TBD */ snd_soc_component_write(component, 0x19, 0x06); return 0;}
这个函数是电源管理相关的,用于把设备挂起,进入省电模式,这样的处理如果不完善,那么可能把设备搞出异常来。而且这个函数体内还有个/*TBD*/,更让我觉得它可能不靠谱。
更重要的是,看上面的第一幅寄存器状态截图,偏移0x19处的值恰好是0x06,和这个函数要写的值完全吻合。依此推理,这个函数已经被调用过,它把es8326的0x19写成了0x6,让设备进入挂起状态......
按理说,使用设备时,会先恢复设备,调用对应的resume函数,但是看一下resume的实现,也好简单,而且也有个/*TBD*/。
static int es8326_resume(struct snd_soc_component *component){ /* TBD */ snd_soc_component_write(component, 0x2b, 0x80); return 0;}
这样推测后,我的精神再次振奋起来,准备着手整顿es8326驱动的电源管理代码。短文已经不短,欲知结果如何,容我明晚继续写(白天还有新的BUG要解)。
(写文章很辛苦,恳请各位读者点击“在看”,欢迎转发)
*************************************************
正心诚意,格物致知,以人文情怀审视软件,以软件技术改变人生
扫描下方二维码或者在微信中搜索“盛格塾”小程序,可以阅读更多文章和有声读物
也欢迎关注格友公众号