[BUG] Playback speed is 2x too slow with SoundWire link based on audio cardinal clock

[plbossart]

Describe the bug

When the SoundWire link clock is configured to 12.288 or 6.144 MHz (Audio Cardinal clock as source), the playback duration is 2x longer than normal

This does not happen with 12 or 6 MHz (Audio PLL as source) or with 9.6/4.8 MHz (Xtal as source).

To Reproduce Steps to reproduce the behavior: (e.g. list commands or actions used to reproduce the bug)

Reproduction Rate

100%

Expected behavior playback duration is correct

Impact

showstopper

Environment

This relies on a Linux kernel change https://github.com/thesofproject/linux/pull/4605 and can be seen on both MTL and LNL RVPs with RT711 on link 0

Screenshots or console output

root@jf-mtlp-rvp-sdw-2:~# time aplay -Dhw:0,0 -c2 -r48000  -fS16_LE /dev/zero -d10
Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

real    0m20.822s

git bisect start
# status: waiting for both good and bad commits
# bad: [09257fd2c9b181a8af6d4dd0a580444503c44b75] topology2: intel: bt-ssp-config: use cardinal clock as source
git bisect bad 09257fd2c9b181a8af6d4dd0a580444503c44b75
# status: waiting for good commit(s), bad commit known
# bad: [d05588e11595044d52cc42699ed9795e4a5c2705] west.yml: Update rimage revision to 4fb9fe00575b
git bisect bad d05588e11595044d52cc42699ed9795e4a5c2705
# status: waiting for good commit(s), bad commit known
# bad: [e7e500651730c77969e616f853b2db5789a24246] west.yml: update Zephyr to 3.4.99
git bisect bad e7e500651730c77969e616f853b2db5789a24246
# status: waiting for good commit(s), bad commit known
# bad: [1cc853d1e975904c24d3153b46db518b2f1578f7] Audio: SRC: Use only module API and fix IPC4 capture direction
git bisect bad 1cc853d1e975904c24d3153b46db518b2f1578f7
# status: waiting for good commit(s), bad commit known
# bad: [9632135d331f941a177840ba92fb349fc3de6a49] west.yml: upgrade zephyr to 9028ad5d71
git bisect bad 9632135d331f941a177840ba92fb349fc3de6a49
# status: waiting for good commit(s), bad commit known
# good: [7d5c3238e33d97ca2d1a0de0ea0843578c1a6749] west.yml: upgrade zephyr to e40859f7
git bisect good 7d5c3238e33d97ca2d1a0de0ea0843578c1a6749
# good: [8a1ba8e47afe00d03d6b04c872220069874632fe] cadence: register module logs in Zephyr
git bisect good 8a1ba8e47afe00d03d6b04c872220069874632fe
# bad: [b532c31f9456e7f276592266b0f12d871a31fcbd] drivers: imx: ipc: Add macro for interrupt_clear() on ARM64
git bisect bad b532c31f9456e7f276592266b0f12d871a31fcbd
# bad: [7e19dfb5faa24b9598b9a57052196328c3f8a6af] xtensa-build-zephyr.py: move one-time cmake arguments check later
git bisect bad 7e19dfb5faa24b9598b9a57052196328c3f8a6af
# good: [e5eb7dfc764e1497c6854cae3773cd10486c6760] topology2: tokens: Split the tokens for input/output pin index
git bisect good e5eb7dfc764e1497c6854cae3773cd10486c6760
# bad: [d604a3242da09391bfc3ae002119f8f5844f81c0] src: drop wrong type-casts to match cache annotations
git bisect bad d604a3242da09391bfc3ae002119f8f5844f81c0
# good: [228ecf57680ed12c9087bf6d2a02c1689936cedb] topology2: hdmi-generic: Fix audio format for DAI copier
git bisect good 228ecf57680ed12c9087bf6d2a02c1689936cedb
# bad: [6f96d0f37eaac19baa87334b99e3f7ded0e3868e] topology2: rename NUM_SDW_AMPS to NUM_SDW_AMP_LINKS
git bisect bad 6f96d0f37eaac19baa87334b99e3f7ded0e3868e
# bad: [e79b6343b89673212f9eec2efdab03a6b21617f7] host-zephyr: Fix glitches
git bisect bad e79b6343b89673212f9eec2efdab03a6b21617f7
# first bad commit: [e79b6343b89673212f9eec2efdab03a6b21617f7] host-zephyr: Fix glitches

[plbossart]

e79b6343b89673212f9eec2efdab03a6b21617f7 is the first bad commit
commit e79b6343b89673212f9eec2efdab03a6b21617f7
Author: Serhiy Katsyuba <serhiy.katsyuba@intel.com>
Date:   Thu Apr 20 11:16:13 2023 +0200

    host-zephyr: Fix glitches

    Fixes glitches when host copier has different container size on
    source and sink.

    Signed-off-by: Serhiy Katsyuba <serhiy.katsyuba@intel.com>

 src/audio/host-zephyr.c | 43 +++++++++++++++++++++++++------------------

[plbossart]

@bardliao can you reproduce my bisect results?

@serhiy-katsyuba-intel @kv2019i FYI, I have no idea how a link configuration change might be impacted by host-dma changes, but git bisect won't lie.

[marc-hb]

e79b6343b896 is very old! Have you tried reverting it on a recent branch, does that also make a difference? There are some conflicts but they seem manageable.

but git bisect won't lie.

... except when test results are non-deterministic. Good you wrote: "Reproduction Rate: 100%"

[serhiy-katsyuba-intel]

@plbossart , https://github.com/thesofproject/sof/pull/7477 fixes the calculation of amount of bytes to copy from/to host DMA buffer when host copier does format conversion between 16 <--> 32 bit container size. If that commit triggers the issue, I'd suggest to check if buffers size is sufficient for the audio format. I guess, there is 16 to 32 bit container conversion in host-copier in your topology (otherwise the fix will have no effect) and so host-copier sink buffer size must be 384 bytes minimum for 1 ms period. If that buffer is smaller (or any other downstream buffer for 32-bit container) when the fix will make host-copier to get less data and playback will take more time.

Not sure how this is related to SoundWire frequency. Maybe besides changes to frequency also some changes to topology were introduced that modified either buffers size or audio format to 32-bit inside the pipeline?

[bardliao]

@bardliao can you reproduce my bisect results?

@serhiy-katsyuba-intel @kv2019i FYI, I have no idea how a link configuration change might be impacted by host-dma changes, but git bisect won't lie.

Yes, I can reproduce the issue with the "host-zephyr: Fix glitches" commit and can't reproduce with the "228ecf57680ed12c9087bf6d2a02c1689936cedb topology2: hdmi-generic: Fix audio format for DAI copier" commit which is the commit right before "host-zephyr: Fix glitches".

[serhiy-katsyuba-intel]

@bardliao , do you have a dmesg log for the case when the issue is reproduced? It can show buffers size and formats.

[plbossart]

@serhiy-katsyuba-intel the firmware buffers and formats are exactly the same between the working 9.6 and 12MHz case and the non-working 12.288MHz. The only thing that changes is that the link is a bit faster and the SoundWire frame shape is a bit different (64x8 instead of 50x10).

[bardliao]

@bardliao , do you have a dmesg log for the case when the issue is reproduced? It can show buffers size and formats.

@serhiy-katsyuba-intel dmesg.txt

[wszypelt]

Due to the fact that at this point this bug, doesn't directly affect the current FW, lowering it to P3

[marc-hb]

Is the "Audio Cardinal clock" (whatever that is) never going to be used?

[plbossart]

It's one of those things that are not needed until they are... using 12.288MHz gives a 64 rows x 8 columns, whereas 9.6 gives 50 rows x 8 columns. It's not a really significant difference until 32 bits are really required for each stream and bandwidth requirements exceed what the bus can deliver. It's still important but not urgent.