Closed fxthomas closed 2 years ago
plbossart
commented
3 years ago Thanks for reporting this @fxthomas
Nothing really comes to my mind as a possible issue and our good friend @jwrdegoede has played quite a bit with SOF on CherryTrail.
Do you have the ability to test with the latest SOF development kernel (branch topic/sof-dev)?
@bardliao anything on the RT5640 that could help explain a sustained 'beeep'?
bardliao
commented
3 years ago I guess it is something related to clock. @fxthomas Could you check is the "Platform Clock" widget always on the right state? I.e. It should be On in playback and Off after playback. You can cat the "Platform Clock" node in /sys/kernel/debug/asoc/
fxthomas
commented
3 years ago Thanks for the quick answers!
Do you have the ability to test with the latest SOF development kernel (branch topic/sof-dev)?
The one that's in https://github.com/thesofproject/linux/tree/topic/sof-dev? Never done a custom kernel build before, but the docs look clear enough. I'm compiling it right now.
You can cat the "Platform Clock" node in /sys/kernel/debug/asoc//dapm/.
It's in /sys/kernel/debug/asoc/sof-bytcht rt5640/dapm/Platform Clock for me. With the same kernel it's off before playback, on during playback and beeping, off after restarting the sound server ; will test again when I have the topic/sof-dev build running.
shumingfan
commented
3 years ago @fxthomas Would you please dump the codec registers?
dump codec registers: cat /sys/kernel/debug/regmap/i2c-10EC5640:00/registers
BTW, is it possible to measure the MCLK frequency on your side?
jwrdegoede
commented
3 years ago I've been testing SOF + BYT/CHT with pipewire instead of pulseaudio as audioserver this weekend and I did notice some instabilities where sound stopped playing (no beep though) until I stopped all audio-playback for a while and then tried again.
There were also some issues with pipewire not properly executing the UCM enable-seq for capture, so the capture pipeline was not working while the gnome-control-center sound-pane did try to use it (for the input vu-meter) so that might have been part of what I was seeing.
I switched back to SST to try and debug pipewire issues without also having SOF in play, during this I learned: https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/866 that pipewire defaults to 24 bits (or maybe even 32 when advertised?) where pulseaudo will always pick s16_le as format if available.
@fxthomas did you specify e.g. "-Dhw:1" when testing with aplay ? Otherwise you are still going through the audio-server (through the alsa-plugin for the audio-server) I believe and then you may have been testing with pipewire. Also did you specify a format with the -f param to aplay ?
I wonder if the SOF CI is testing with 24 / 32 bits sample sizes on BYT/CHT and I wonder if the bigger sample size may be causing issues with e.g. the stack on the DSP, or just some things becoming slower enough to sometimes be a problem ?
lgirdwood
commented
3 years ago I wonder if the SOF CI is testing with 24 / 32 bits sample sizes on BYT/CHT and I wonder if the bigger sample size may be causing issues with e.g. the stack on the DSP, or just some things becoming slower enough to sometimes be a problem ?
Yes this will have impact on FW buffers and processing headroom. 24bit is on the CI test list for CHT, but it's likely not stressed like 16bit is (sinec it's the primary use case on the older HW). The CHT multi format test is here.
jwrdegoede
commented
3 years ago Yes this will have impact on FW buffers and processing headroom. 24bit is on the CI test list for CHT, but it's likely not stressed like 16bit is (sinec it's the primary use case on the older HW).
Ok, so that is what I expected, in that case it seems to me that it would be better if pipewire were to just use 16 bit formats on these device ? Also note that the SOF driver is even advertising 32 bit formats (S32_LE) I would not be surprised if pipewire actually picks that one.
If you agree that pipewire just using 16bit formats would be better, then the question becomes how we achieve this. I think that ideally the SOF driver should not advertise 24bit/32bit formats (on BYT/CHT) to userspace in that case. Or maybe have a module option to advertise these or not ?
plbossart
commented
3 years ago @jwrdegoede The SOF driver just reports what the topology defines, there is no hard-coded format. I would be surprised if there was any difference, the dai is already configured to support 24 bits.
fxthomas
commented
3 years ago @fxthomas did you specify e.g. "-Dhw:1" when testing with aplay ? Otherwise you are still going through the audio-server (through the alsa-plugin for the audio-server) I believe and then you may have been testing with pipewire.
Yes, I used -D sysdefault:CARD=bytcrrt5640 in SST (and the equivalent for SOF), and also made sure pipewire/pulse were not running (systemd sockets/services stopped and no processes running).
Also did you specify a format with the -f param to aplay ?
In the linked pipewire issue comment I noted the aplay command-lines I used for testing with the SST driver, and these included -f and a few other settings.
For a quick summary, the only two that worked in the SST driver were:
$ ffmpeg -i input.mp3 -f s16le -c:a pcm_s16le -ar 48000 -ac 2 test_s16le_48000.raw
$ aplay -D sysdefault:CARD=bytcrrt5640 -f s16_le -r 48000 -c 2 -v test_s16le_48000.raw
$ ffmpeg -i input.mp3 -f s32le -c:a pcm_s32le -ar 96000 -ac 2 test_s32le_96000.raw
$ aplay -D sysdefault:CARD=bytcrrt5640 -f s24_le -r 48000 -c 2 -v test_s32le_96000.rawIn the SOF driver, the beeping occurs after some time whether I use aplay or Pipewire or Pulse in any mode.
Also I said (famous last words!):
will test again when I have the topic/sof-dev build running....but while it boots just fine I'm having some trouble figuring out how to enable SOF in this build, because it is apparently not as simple as the default 5.11 kernel I'm running. I need to read the docs, I'm just a poor newcomer to that world :wink:
plbossart
commented
3 years ago @fxthomas there is a kernel parameter to select SOF, by default SST is the default.
copy this to any file in /etc/modprobe.d/
options snd-intel-dspcfg dsp_driver=3
plbossart
commented
3 years ago alternatively there's also a build config CONFIG_SND_INTEL_BYT_PREFER_SOF
but I am not sure if it's in our development version just yet.
fxthomas
commented
3 years ago options snd-intel-dspcfg dsp_driver=3
That's the one I used, it worked on the official 5.11 kernel but not on the SOF branch when I tried. I'm rebuilding the branch right now from scratch, let's see if I can make that work better.
CONFIG_SND_INTEL_BYT_PREFER_SOF
Looks like it's there in https://github.com/thesofproject/linux/commit/3620c5394b8b. If I can't make it work with the module option I'll try this one next.
fxthomas
commented
3 years ago I finally got some success!
Some observations first:
topic/sof-dev and enable the SOF driver on it, using the same configuration as v5.11.4-arch1 as a base, merged with kconfig-sof-default.sh from the SOF repository. I didn't experience any beeping, everything works well.lsmod outputs), but the same kernel has the same modules when loaded in SST or in SOF mode. Is that normal?aplay now stops with a write error when the beep occurs (it used to just hang there), see aplay-5.11.4-arch-sof-after3.logTests for v5.11.4-arch1 (SOF, pure ALSA):
Tests for v5.11.4-arch1 (SST, pure ALSA):
Tests for topic/sof-dev (SOF, pure ALSA):
Tests for topic/sof-dev (SOF, Pipewire 0.3.23, default configuration):
Tests for topic/sof-dev (SST, pure ALSA):
plbossart
commented
3 years ago
- I upgraded to v5.11.4-arch1 which still beeps after a couple of minutes, but no longer persistently: the beep stops after a couple of seconds (hey, that's an improvement!). I used that as a basis for the test below.
that's still with the SST driver, yes?
- I was able to compile
topic/sof-devand enable the SOF driver on it, using the same configuration as v5.11.4-arch1 as a base, merged withkconfig-sof-default.shfrom the SOF repository. I didn't experience any beeping, everything works well.
Good. You should see the same result with v5.11.4, there are no significant differences for Baytrail/Cherrytrail.
- In both kernels all buffer formats (incl. e.g. S32LE) seem functional with the SOF driver, contrary to the SST driver, and Pipewire does not need special configuration.
- @shumingfan The registers are below. I don't know how to measure MCLK, is this documented somewhere?
I don't see anything that catches my eye here, except perhaps for the fact that:
- Some loaded modules are a little different in the two kernels (see the attached
lsmodoutputs), but the same kernel has the same modules when loaded in SST or in SOF mode. Is that normal?
yes, that's normal. there are two drivers registering for the same ACPI ID, so both will be loaded but only one selected with the run-time detection. So some modules are loaded but their probe will fail. They will still show as loaded modules.
aplaynow stops with a write error when the beep occurs (it used to just hang there), see aplay-5.11.4-arch-sof-after3.log
Not following. is this with the SOF or SST driver?
fxthomas
commented
3 years ago On Thu, Mar 11, 2021, 01:59 Pierre-Louis Bossart @.***> wrote:
yes, that's normal. there are two drivers registering for the same ACPI ID, so both will be loaded but only one selected with the run-time detection. So some modules are loaded but their probe will fail. They will still show as loaded modules.
Thanks, that's good to know!
that's still with the SST driver, yes?
Not following. is this with the SOF or SST driver?
Ah that wasn't clear, sorry. The beeping issue is with SOF.
With SST both kernels play sound fine in S16LE only. Other formats being advertised in a broken state is a separate issue that's being worked around in the kernel if I understand correctly.
With SOF all formats seem to play correctly, but topic/sof-dev has no
issue, while the official 5.11.0~4 Arch kernels beep after a couple of
minutes as described.
During my tests everything on the system besides the kernel is the same,
and I tried to reuse as much as possible the same build/package
configuration for the topic/sof-dev build as the official kernel ; the
SOF-provided kernel config is merged on top of the one from the official
kernel, and that's pretty much it.
—
You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/thesofproject/sof/issues/3868#issuecomment-796337848, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAEVZWX2Z4AKSUTXPX5QHZDTDABV7ANCNFSM4YC77CXA .
plbossart
commented
3 years ago thanks @fxthomas I must admit not having any clues on what might cause this beep issue with the SOF driver in v5.11, or what we did recently that could explain that it's no longer beeping.
In this kind of cases, I would try to bisect to try to find more leads.
a) start with commit 3620c5394b8b234ca77e562758127a6bb9e64720 ('ASoC: SOF: remove superfluous NULL check in debugfs read'). That's the last commit based on v5.11-rcX in our development tree b) check plain vanilla v5.11, and then bisect until you find something...
It'll typically take 15 iterations but to reduce compilation time you can try generating a .config with our script, that compiles in 4mn on my host device since we've removed tons of things that aren't required for audio. see https://github.com/thesofproject/kconfig/blob/master/kconfig-sof-default.sh
Sorry I don't have a more direct way of helping.
fxthomas
commented
3 years ago Got it, thanks for the pointers to the relevant commits and all the help anyway, I already have a much better view of how I troubleshoot this — and learned tons about the Linux audio stack along the way! I'll let you know when I get results from the bisect.
plbossart
commented
3 years ago btw I was trying on a Cherrytrail+rt5640 (headset only, no speakers) and I didn't hear anything bad with topic/sof-dev either. I only test with -Dhw:0,0 since that's the main path and there are known issues with the mixer in the firmware.
fxthomas
commented
3 years ago Hmm, I'm actually back to square one. I was watching a video on the same kernel I compiled in my earlier tests from topic/sof-dev with the SOF driver + Pipewire 0.3.23, and the same beeping appeared after 30/40 min. That's much better than the official kernel, but the issue is still there.
At this point it very well could be an hardware issue, but there's not much of interest in the logs/dmesg...
fxthomas
commented
3 years ago For more information, I took a recording by plugging the rt5640 output jack to an external recorder's input jack. Here is the output right before the beeping happens:
Zoom on the region:
Interestingly the L/R channels seem to swap after a while (I noticed this earlier, but on the spectrogram above the discontinuities are very visible), see a zoom at one of them:
(Recording available here. The sound is not very clean — you can hear a bit of noise that can't be heard directly with headphones on the machine, but the beeping is exactly as I heard multiple times on this bug)
jwrdegoede
commented
3 years ago That part about the channel-swap is interesting, as discussed in #3699 I was seeing this during my testing too, but this got fixed recently. I just checked and the fix for that is not in the 1.6.1 firmware which you are using.
In my testing the swapping only happened between open/closing of the device but I never tested for long periods at a time, so maybe the swapping you are seeing is the same; and with some luck it is also the root-cause of the beep (so the swap triggering while playing causes the beep).
I asked one of the SOF devs to provide my with a test-build of the upcoming 1.7 firmware which does include the fix for this, so that I could confirm that the channel-swap issue is fixed.
It would be good if you can (re)test with that firmware bulld. I've attached that here. To install this, simply replace /lib/firmware/intel/sof/sof-cht.ri with the one from the attached zip and then reboot.
fxthomas
commented
3 years ago It would be good if you can (re)test with that firmware bulld. I've attached that here.
Done, the beeping is still there but I didn't hear any channel swapping. Given the seemingly random nature of all this I'm not quite ready to call it, but it looks like a small improvement at least!
Looking at the curves in my earlier message I get the impression that the beep is just caused by a 2ms buffer (96 samples@48kHz in the recording) not getting updated somewhere in the driver stack and repeating ad infinitum. Does that particular number ring a bell?
Can runtime PM in one of the platform drivers (codec/LPE/something else I'm not aware of) cause this somehow? Is there a way I can see the PM state e.g. in /sys or /proc?
lgirdwood
commented
3 years ago @fxthomas thanks, I've listened to the ogg file and it sounds like the DMA repeats the last period continually. Can you confirm the following for me. 1) media player or aplay does not report XRUNs - no XRUNs means the host side DMA is working as expected and copying data from host buffer to DSP buffer. 2) alsamixer works and you can change DSP volumes (note this is not codec volume, the DSP controls are named differently). 3) Stream works again after pause - i.e. aplay -i stops and restarts the audio (it may even fix the tone).
I suspect here that the SSP port has an error condition and is not able to get new data from DMA.
diff --git a/src/drivers/intel/baytrail/ssp.c b/src/drivers/intel/baytrail/ssp.c
index de5dc1346..3711309e7 100644
--- a/src/drivers/intel/baytrail/ssp.c
+++ b/src/drivers/intel/baytrail/ssp.c
@@ -534,6 +534,8 @@ static void ssp_stop(struct dai *dai, int direction)
{
struct ssp_pdata *ssp = dai_get_drvdata(dai);
+ dai_err(dai,"SSSR is 0x%x", ssp_read(dai, SSSR));
+
spin_lock(&dai->lock);
/* stop Rx if neeed */This will dump SSP status at stream stop. It will hopefully show an error condition.
plbossart
commented
3 years ago @fxthomas we don't support pm_runtime for SOF on Cherrytrail, so this is likely a firmware issue indeed.
fxthomas
commented
3 years ago we don't support pm_runtime for SOF on Cherrytrail, so this is likely a firmware issue
Thanks for confirming!
media player or aplay does not report XRUNs Stream works again after pause - i.e. aplay -i stops and restarts the audio (it may even fix the tone).
I didn't see any XRUNs.
In the latest kernels (5.11.4+) aplay actually stops with a write error after 4-5 seconds beeping, see at the end of the log I posted in https://github.com/thesofproject/sof/issues/3868#issuecomment-796304449:
aplay: pcm_write:2058: write error: Input/output errorThe recording I shared was under Pipewire, where the beeping still stays persistent until I restart the PW service (presumably because it retries to establish the link continually).
alsamixer works and you can change DSP volumes (note this is not codec volume, the DSP controls are named differently).
How do I distinguish between the two? I see a lot of entries for controling DAC/ADC/mixer components like Stereo ADC MIXL ADC2, are these the ones I should be looking for?
This will dump SSP status at stream stop. It will hopefully show an error condition.
Unfortunately I don't have a drivers/intel directory in neither topic/sof-dev branch nor the official 5.11.6 sources. Should I look elsewhere?
lgirdwood
commented
3 years ago I didn't see any XRUNs.
In the latest kernels (5.11.4+)
aplayactually stops with a write error after 4-5 seconds beeping, see at the end of the log I posted in #3868 (comment):aplay: pcm_write:2058: write error: Input/output error
ok, so this is useful (I can rule out a few of the questions I asked above) - we have a pipeline like
host dma -> buffer -> volume -> buffer -> I2S DMAThe DMA ALSA position is updated by the host DMA position, but the host DMA position may block if there is not free space in the pipeline (the pipeline is emptied by the DMA I2S - which sounds like it's repeating the last period consistently and not emptying the DATA).
The pipeline buffers above have 2 periods so the timing headroom might be tight if PW is writting close to the host DMA position. I assume you have exactly the same error if you do
aplay -Dhw:0,0 -v --test-position -f dat 48kHzStereoWavfile.wavFwiw, I recommend using audacity to generate a sine wave stereo wav file with 48kHz sample rate. This shows up really well when captured for debugging and shows exactly what's happening (as you know what comes next).
Btw, can you run sof-logger when the issue happens. See
https://thesofproject.github.io/latest/developer_guides/debugability/logger/index.html
The ldc files for logger are in here https://github.com/thesofproject/sof-bin
You will also need to build the logger, See https://thesofproject.github.io/latest/getting_started/build-guide/build-from-scratch.html#step-4-build-topology-and-tools
fxthomas
commented
3 years ago I assume you have exactly the same error if you do [...]
Yes, using --test-position has the same issue.
Fwiw, I recommend using audacity to generate a sine wave stereo wav file with 48kHz sample rate.
I will do that next time! :wink:
Btw, can you run sof-logger when the issue happens.
I built 536800a09c1abc36ac74e17cebb2cd7865ed85a0 (v1.6.1) that corresponds to the sof-firmware package I have installed from the official repos (source), using ./scripts/build-tools.sh (PKGBUILD used to do the build).
I then tried the following, but that does not seem to do anything on the official 5.11.6 kernel:
$ sudo sof-logger -l /usr/lib/firmware/intel/sof/v1.6.1/sof-cht-v1.6.1.ldc -n
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
$ sudo sof-logger -l /usr/lib/firmware/intel/sof/v1.6.1/sof-cht-v1.6.1.ldc -n -F verbose='*'
error: Unable to open out file '/sys/kernel/debug/sof/filter'
error: failed to apply trace filter, -13.
$ sudo ls /sys/kernel/debug/sof
cc_version debug dmac0 dmac1 dmac2 dram etrace exception fw_version inbox iram outbox shim ssp0 ssp1 ssp2 ssp3 ssp4 ssp5 streamOn the topic/sof-dev build I have from earlier it doesn't even work (but /sys/kernel/debug/sof/filter appears to be present this time!):
$ sudo sof-logger -l /usr/lib/firmware/intel/sof/v1.6.1/sof-cht-v1.6.1.ldc -n
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
error: Invalid filename length or ldc file does not match firmwareDo I need special debug kernel options to get sof-logger to work? The issue is far easier to reproduce on the official kernel, so if it is possible to enable it dynamically at runtime it'd be great!
Alternatively, do I need to rebuild it to work on a different kernel?
Sorry for the lot of questions, I hope that does not bother you too much!
lgirdwood
commented
3 years ago @fxthomas ah, I think the newer tool updates are expecting a filter (its a new-ish feature), however this tool should work without filer enabled (you get all the trace). This this is a bug (i.e. the tool should just carry on if it cant find filter). The LDC file has to match the FW version, it's basically contains all the strings for every FW trace() call. Can you check dmesg for FW version and make sure your LDC version matches the number in dmesg.
jwrdegoede
commented
3 years ago So I just accidentally trigger this on a HP Pavilion X2 10-n000nd, Bay Trail Z3736F SoC with an ALC5642 (rt5640) codec.
This is with kernel-5.12-rc3 and the official 1.6.1 SOF-fw binaries from sof-bin, using pipewire as sound-server with pipewire configured to use S16LE as sample-format.
I do have the .lc file and sof-logger binary for 1.6.1 installed, so I've grabbed sof-logger output for the beep/hang:
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 23634797.968750] ( 23634798.000000) c0 dma-trace src/trace/dma-trace.c:327 ERROR FW ABI 0x3011000 DBG ABI 0x5002000 tag v1.6.1 src hash 0x459cfb8c (ldc hash 0x459cfb8c)
[112590005.416667] ( 88955208.000000) c0 dw-dma src/drivers/dw/dma.c:283 ERROR dw_dma_start(): dma 1 channel 1 not ready ena 0x2 status 0x3
[112590020.208333] ( 14.791667) c0 host 3.15 src/audio/host.c:317 ERROR host_copy_one_shot(): dma_copy() failed, ret = 4294967280
[112590031.302083] ( 11.093750) c0 pipe 3.19 src/audio/pipeline.c:1029 ERROR pipeline_copy(): ret = -16, start->comp.id = 16, dir = 1
[112590044.583333] ( 13.281250) c0 pipe 3.19 src/audio/pipeline.c:1219 ERROR pipeline_task(): xrun recover failed! pipeline will be stopped!Killing pipewire and then restarting it fixes the "beep" sound. sof-logger does not show any new messages after this.
fxthomas
commented
3 years ago So I just accidentally trigger this
Nice! Let me know if you need help with testing.
I think the newer tool updates are expecting a filter (its a new-ish feature)
Got it, interesting.
however this tool should work without filer enabled (you get all the trace)
I don't get anything if I do cat /sys/kernel/debug/sof/etrace, so I'm wondering if there isn't something else I need to enable.
Can you check dmesg for FW version and make sure your LDC version matches the number in dmesg.
Kernel says this earlier in the boot (I probably should have looked at that earlier, sorry...):
$ sudo dmesg | grep sof
[ 15.072008] sof-audio-acpi 808622A8:00: unknown sof_ext_man header type 3 size 0x30
[ 15.072036] sof-audio-acpi 808622A8:00: Firmware info: version 1:5:0-96cc6
[ 15.072042] sof-audio-acpi 808622A8:00: Firmware: ABI 3:18:1 Kernel ABI 3:18:0
[ 15.072048] sof-audio-acpi 808622A8:00: warn: FW ABI is more recent than kernel
[ 15.084662] sof-audio-acpi 808622A8:00: Firmware info: version 1:5:0-96cc6
[ 15.084676] sof-audio-acpi 808622A8:00: Firmware: ABI 3:18:1 Kernel ABI 3:18:0
[ 15.084683] sof-audio-acpi 808622A8:00: warn: FW ABI is more recent than kernel
[ 15.152649] sof-audio-acpi 808622A8:00: Topology: ABI 3:17:0 Kernel ABI 3:18:0
[ 15.158380] sof-audio-acpi 808622A8:00: ASoC: Parent card not yet available, widget card binding deferred
[ 15.168675] input: sof-bytcht rt5640 Headset as /devices/pci0000:00/808622A8:00/bytcr_rt5640/sound/card1/input22LDC file is the exact same as the v1.6.1 sof-bin package from the repository, however it says when I dump it:
$ sof-logger -d /usr/lib/firmware/intel/sof/v1.6.1/sof-cht-v1.6.1.ldc
logger ABI Version is 5:2:0
ldc_file ABI Version is 5:2:0
...How come the version numbers are so different? Did the kernel fail to load the correct firmware? Am I looking at the wrong thing?
For topic/sof-devel I get a little less warnings but the same versions:
[ 18.157628] sof-audio-acpi-intel-byt 808622A8:00: unknown sof_ext_man header type 3 size 0x30
[ 18.157683] sof-audio-acpi-intel-byt 808622A8:00: Firmware info: version 1:5:0-96cc6
[ 18.157693] sof-audio-acpi-intel-byt 808622A8:00: Firmware: ABI 3:18:1 Kernel ABI 3:18:0
[ 18.174999] sof-audio-acpi-intel-byt 808622A8:00: Firmware info: version 1:5:0-96cc6
[ 18.175018] sof-audio-acpi-intel-byt 808622A8:00: Firmware: ABI 3:18:1 Kernel ABI 3:18:0
[ 19.054692] sof-audio-acpi-intel-byt 808622A8:00: Topology: ABI 3:17:0 Kernel ABI 3:18:0
[ 19.087468] sof-audio-acpi-intel-byt 808622A8:00: ASoC: Parent card not yet available, widget card binding deferredThe bit about sof-audio-acpi-intel-byt is weird, I have a Cherrytrail CPU (Atom x5-Z8350) but unless I'm mistaken byt is for Baytrail and cht for Cherrytrail, right? I assume the two share an implementation?
jwrdegoede
commented
3 years ago The bit about sof-audio-acpi-intel-byt is weird, ... I assume the two share an implementation?
Yes the Bay Trail and Cherry Trail SoCs have the same audio-block. Notice that the HP x2 on which I reproduced this has a BYT SoC and not a CHT SoC like yours has, so both are impacted by this bug.
lgirdwood
commented
3 years ago however this tool should work without filer enabled (you get all the trace)
I don't get anything if I do
cat /sys/kernel/debug/sof/etrace, so I'm wondering if there isn't something else I need to enable.
There are 2 trace debugFS pipes, one is for errors only and is persistent (etrace) and the other (trace) is for all messages. etrace being empty means there have been no errors. However, we did add a "trace is working" message recently that should show the version in etrac too, so there should at least be some data. v1.7-rc should show this, but I cant remeber for v1.6...
Can you check dmesg for FW version and make sure your LDC version matches the number in dmesg.
Kernel says this earlier in the boot (I probably should have looked at that earlier, sorry...):
$ sudo dmesg | grep sof [ 15.072008] sof-audio-acpi 808622A8:00: unknown sof_ext_man header type 3 size 0x30 [ 15.072036] sof-audio-acpi 808622A8:00: Firmware info: version 1:5:0-96cc6 [ 15.072042] sof-audio-acpi 808622A8:00: Firmware: ABI 3:18:1 Kernel ABI 3:18:0 [ 15.072048] sof-audio-acpi 808622A8:00: warn: FW ABI is more recent than kernel [ 15.084662] sof-audio-acpi 808622A8:00: Firmware info: version 1:5:0-96cc6 [ 15.084676] sof-audio-acpi 808622A8:00: Firmware: ABI 3:18:1 Kernel ABI 3:18:0 [ 15.084683] sof-audio-acpi 808622A8:00: warn: FW ABI is more recent than kernel [ 15.152649] sof-audio-acpi 808622A8:00: Topology: ABI 3:17:0 Kernel ABI 3:18:0 [ 15.158380] sof-audio-acpi 808622A8:00: ASoC: Parent card not yet available, widget card binding deferred [ 15.168675] input: sof-bytcht rt5640 Headset as /devices/pci0000:00/808622A8:00/bytcr_rt5640/sound/card1/input22LDC file is the exact same as the v1.6.1 sof-bin package from the repository, however it says when I dump it:
Looks like you need the v1.5 LDC files here. The kernel will look in /lib/firmware/sof/ directory for firmwares.
lgirdwood
commented
3 years ago So I just accidentally trigger this on a HP Pavilion X2 10-n000nd, Bay Trail Z3736F SoC with an ALC5642 (rt5640) codec.
This is with kernel-5.12-rc3 and the official 1.6.1 SOF-fw binaries from sof-bin, using pipewire as sound-server with pipewire configured to use S16LE as sample-format.
I do have the .lc file and sof-logger binary for 1.6.1 installed, so I've grabbed sof-logger output for the beep/hang:
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT [ 23634797.968750] ( 23634798.000000) c0 dma-trace src/trace/dma-trace.c:327 ERROR FW ABI 0x3011000 DBG ABI 0x5002000 tag v1.6.1 src hash 0x459cfb8c (ldc hash 0x459cfb8c) [112590005.416667] ( 88955208.000000) c0 dw-dma src/drivers/dw/dma.c:283 ERROR dw_dma_start(): dma 1 channel 1 not ready ena 0x2 status 0x3 [112590020.208333] ( 14.791667) c0 host 3.15 src/audio/host.c:317 ERROR host_copy_one_shot(): dma_copy() failed, ret = 4294967280 [112590031.302083] ( 11.093750) c0 pipe 3.19 src/audio/pipeline.c:1029 ERROR pipeline_copy(): ret = -16, start->comp.id = 16, dir = 1 [112590044.583333] ( 13.281250) c0 pipe 3.19 src/audio/pipeline.c:1219 ERROR pipeline_task(): xrun recover failed! pipeline will be stopped!
This is a host DMA copy failure. i.e. the host DMA has failed to copy data from host DDR to DSP SRAM. Trace uses the same DMA so this may kill trace too.
I've done some digging and the SST FW splits the DMAC usage with DMAC1 doing host DDR <-> DSP SRAM and DMAC0 doing DSP SRAM <-> SSP i.e.
/* Init DMAC1 for Mem2Mem Transfers */
/*
* Channel 0 - Unused
* Channel 1 - Unused
* Channels 2-7 - Mem to Mem
*/
/* Init DMAC0 for Mem2Phe and Phe2Mem Transfers
/*
* Channel 0 - SSP2 to Mem - Src_Id = 0
* Channel 1 - Mem to SSP2 - Dest_Id = 5
* Channels 2-7 - Unused
*/It may be that we need to do the same on BYT/CHT for reliable operation. @jwrdegoede is this something you could hack and hardcode in FW ? (please also force trace to use DMAC1 chn 2 - 7 and dont use any "unused" channels). ? If this works I can do a cleaner fix. Sorry I dont have the HW.
jwrdegoede
commented
3 years ago @jwrdegoede is this something you could hack and hardcode in FW ?
I have 0 experience hacking on SOF so far, I don't even have a build-environment setup for it; and ATM I'm buried in a bunch of kernel regressions related to various drivers/platform/x86 kernel bugs (I'm the pdx86 subsys maintainer), so I also really don't have time to dig into this, sorry.
lgirdwood
commented
3 years ago @jwrdegoede no worries, I think I have an idea of where to look when time permits. Looks like the DMA channels are mutually exclusive between the DMACs.
plbossart
commented
3 years ago @jwrdegoede @lgirdwood @kv2019i another thing I was thinking of is the 1024 period size used by pipewire.
All the SOF topology and tests is based on 48 sample multiples, and while we can allow for 1024 periods this will introduce additional issues we don't see when all the periods are based on ms multiples. This should be fine for HDaudio audio but I am not sure how well this might work on legacy devices.
Is there a way to force pipewire to use ms-based periods?
keyonjie
commented
3 years ago It could be related to the scheduler missing a task and lead to xrun, we use multi-chan domain on BYT, Hi @iuliana-prodan have you hit similar issue on IMX?
jwrdegoede
commented
3 years ago @jwrdegoede @lgirdwood @kv2019i another thing I was thinking of is the 1024 period size used by pipewire. All the SOF topology and tests is based on 48 sample multiples, and while we can allow for 1024 periods this will introduce additional issues we don't see when all the periods are based on ms multiples. This should be fine for HDaudio audio but I am not sure how well this might work on legacy devices.
The /etc/pipewire/media-session.d/alsa-monitor.conf file has a (commented) api.alsa.period-size setting.
But AFAIK @fxthomas has been reproducing the beep with direct-playback using "aplay -Dhw:#", so pipewire is not involved.
iuliana-prodan
commented
3 years ago It could be related to the scheduler missing a task and lead to xrun, we use multi-chan domain on BYT, Hi @iuliana-prodan have you hit similar issue on IMX?
I didn't get any such issue on iMX.
I even test it today on an i.MX8QM with Firmware info: version 1:7:0-0a926 (today's sof/master) and Linux version 5.11.0-rc1-next-20210104 and I head no beeping sound.
plbossart
commented
3 years ago @jwrdegoede @lgirdwood @kv2019i another thing I was thinking of is the 1024 period size used by pipewire. All the SOF topology and tests is based on 48 sample multiples, and while we can allow for 1024 periods this will introduce additional issues we don't see when all the periods are based on ms multiples. This should be fine for HDaudio audio but I am not sure how well this might work on legacy devices.
The /etc/pipewire/media-session.d/alsa-monitor.conf file has a (commented) api.alsa.period-size setting.
thanks for the pointers.
But AFAIK @fxthomas has been reproducing the beep with direct-playback using "aplay -Dhw:#", so pipewire is not involved.
you're right, for some reason I was convinced this was due to PipeWire.
fxthomas
commented
3 years ago Tangentially, I finally got rid of the warnings, so sof-logger works on the official kernel, without warnings but also without any additional messages. My topic/sof-dev build still shows warnings as before and I was not able to get anything out of it either.
(It turns out, I was still using the test firmware build from https://github.com/thesofproject/sof/issues/3868#issuecomment-799243758 because I'm just a dumb human who sometimes forgets changes I make if I don't make them a proper package...)
plbossart
commented
3 years ago @fxthomas I have been testing SOF on a CHT device and it's been fine so far, I have Spotify on top of PipeWire and SOF (1.6.1 + kernel v5.12-rc5+)
Can you upload the file you are using and the exact command you are using? I'd really like to go to the bottom of this repeated noise.
fxthomas
commented
3 years ago Aha! I was finally able to reproduce it on my topic/sof-dev build after about an hour watching videos, and sof-logger finally shows something! :tada:
$ sudo sof-logger -l /usr/lib/firmware/intel/sof/v1.6.1/sof-cht-v1.6.1.ldc -t -n
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 18838477.187500] ( 18838478.000000) c0 dma-trace src/trace/dma-trace.c:327 ERROR FW ABI 0x3011000 DBG ABI 0x5002000 tag v1.6.1 src hash 0x459cfb8c (ldc hash 0x459cfb8c)
[ 18838492.083333] ( 14.895833) c0 ll-schedule ./schedule/ll_schedule.c:345 task add 0xff309880 dma-trace-task <2b972272-c5b1-4b7e-926f-0fc5cb4c4690>
[ 18838495.312500] ( 3.229167) c0 ll-schedule ./schedule/ll_schedule.c:349 task params pri 4 flags 0 start 500000 period 500000
[ 18838499.687500] ( 4.375000) c0 ll-schedule /schedule/timer_domain.c:176 timer_domain_register domain->type 1 domain->clk 1 domain->ticks_per_ms 19200 period 500000
[ 18838506.458333] ( 6.770833) c0 ll-schedule ./schedule/ll_schedule.c:252 num_tasks 1 total_num_tasks 1
[ 19628475.781250] ( 789969.312500) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19630418.020833] ( 1942.239624) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19632835.208333] ( 2417.187500) c0 component src/audio/component.c:130 comp new mixer <bc06c037-12aa-417c-9a97-89282e321a76> type 6 id 1.1
[ 19633265.625000] ( 430.416656) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19635448.802083] ( 2183.177002) c0 component src/audio/component.c:130 comp new pga <b77e677e-5ff4-4188-af14-fba8bdbf8682> type 5 id 1.2
[ 19635464.843750] ( 16.041666) c0 pga 1.2 ../audio/volume/volume.c:379 vol->initial_ramp = 250, vol->ramp = 0, vol->min_value = 0, vol->max_value = 65536
[ 19637432.656250] ( 1967.812500) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19637762.500000] ( 329.843750) c0 component src/audio/component.c:130 comp new dai <c2b00d27-ffbc-4150-a51a-245c79c5e54b> type 2 id 1.3
[ 19637778.177083] ( 15.677083) c0 dai src/lib/dai.c:164 dai_get 1.2 new sref 2
[ 19637782.187500] ( 4.010417) c0 dma src/lib/dma.c:126 dma_get() ID 0 sref = 2 busy channels 0
[ 19649970.104167] ( 12187.916992) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19650181.145833] ( 211.041672) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19650975.729167] ( 794.583313) c0 pipe src/audio/pipeline.c:78 pipeline new pipe_id 1 period 1000 priority 1
[ 19651309.322917] ( 333.593750) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19651425.416667] ( 116.093750) c0 buffer src/audio/buffer.c:79 buffer new size 0x300 id 1.5 flags 0x0
[ 19651614.427083] ( 189.010422) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19651727.864583] ( 113.437500) c0 buffer src/audio/buffer.c:79 buffer new size 0x300 id 1.6 flags 0x0
[ 19651867.760417] ( 139.895828) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19652036.510417] ( 168.750000) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19652155.416667] ( 118.906250) c0 component src/audio/component.c:130 comp new host <8b9d100c-6d78-418f-90a3-e0e805d0852b> type 1 id 2.8
[ 19652171.718750] ( 16.302084) c0 dma src/lib/dma.c:126 dma_get() ID 1 sref = 2 busy channels 1
[ 19652331.250000] ( 159.531250) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19652450.989583] ( 119.739586) c0 component src/audio/component.c:130 comp new pga <b77e677e-5ff4-4188-af14-fba8bdbf8682> type 5 id 2.9
[ 19652466.979167] ( 15.989583) c0 pga 2.9 ../audio/volume/volume.c:379 vol->initial_ramp = 250, vol->ramp = 0, vol->min_value = 0, vol->max_value = 413542
[ 19652585.937500] ( 118.958336) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19652697.239583] ( 111.302086) c0 buffer src/audio/buffer.c:79 buffer new size 0x300 id 2.10 flags 0x0
[ 19652833.906250] ( 136.666672) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19652944.375000] ( 110.468750) c0 buffer src/audio/buffer.c:79 buffer new size 0x300 id 2.11 flags 0x0
[ 19653089.427083] ( 145.052078) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19653246.406250] ( 156.979172) c0 component src/audio/component.c:130 comp new dai <c2b00d27-ffbc-4150-a51a-245c79c5e54b> type 2 id 2.12
[ 19653262.083333] ( 15.677083) c0 dai src/lib/dai.c:164 dai_get 1.2 new sref 3
[ 19653266.145833] ( 4.062500) c0 dma src/lib/dma.c:126 dma_get() ID 0 sref = 3 busy channels 0
[ 19653396.406250] ( 130.260422) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19653512.343750] ( 115.937500) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19653645.416667] ( 133.072922) c0 pipe src/audio/pipeline.c:78 pipeline new pipe_id 2 period 1000 priority 0
[ 19653783.854167] ( 138.437500) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19653898.593750] ( 114.739586) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19654016.875000] ( 118.281250) c0 component src/audio/component.c:130 comp new host <8b9d100c-6d78-418f-90a3-e0e805d0852b> type 1 id 3.15
[ 19654033.125000] ( 16.250000) c0 dma src/lib/dma.c:126 dma_get() ID 1 sref = 3 busy channels 1
[ 19654186.614583] ( 153.489578) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19654299.843750] ( 113.229164) c0 component src/audio/component.c:130 comp new pga <b77e677e-5ff4-4188-af14-fba8bdbf8682> type 5 id 3.16
[ 19654315.833333] ( 15.989583) c0 pga 3.16 ../audio/volume/volume.c:379 vol->initial_ramp = 250, vol->ramp = 0, vol->min_value = 0, vol->max_value = 65536
[ 19654439.479167] ( 123.645836) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19654549.270833] ( 109.791664) c0 buffer src/audio/buffer.c:79 buffer new size 0x300 id 3.17 flags 0x0
[ 19654687.447917] ( 138.177078) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19654795.052083] ( 107.604164) c0 buffer src/audio/buffer.c:79 buffer new size 0x300 id 3.18 flags 0x0
[ 19655202.239583] ( 407.187500) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19655574.843750] ( 372.604156) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19655695.364583] ( 120.520836) c0 pipe src/audio/pipeline.c:78 pipeline new pipe_id 3 period 1000 priority 0
[ 19655841.718750] ( 146.354172) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19655959.166667] ( 117.447914) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19656079.479167] ( 120.312500) c0 component src/audio/component.c:130 comp new host <8b9d100c-6d78-418f-90a3-e0e805d0852b> type 1 id 4.21
[ 19656095.677083] ( 16.197916) c0 dma src/lib/dma.c:126 dma_get() ID 0 sref = 4 busy channels 0
[ 19656247.135417] ( 151.458328) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19656368.229167] ( 121.093750) c0 component src/audio/component.c:130 comp new pga <b77e677e-5ff4-4188-af14-fba8bdbf8682> type 5 id 4.22
[ 19656384.270833] ( 16.041666) c0 pga 4.22 ../audio/volume/volume.c:379 vol->initial_ramp = 250, vol->ramp = 0, vol->min_value = 0, vol->max_value = 65536
[ 19656514.739583] ( 130.468750) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19656622.656250] ( 107.916664) c0 buffer src/audio/buffer.c:79 buffer new size 0xf00 id 4.23 flags 0x0
[ 19656754.322917] ( 131.666672) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19656873.229167] ( 118.906250) c0 buffer src/audio/buffer.c:79 buffer new size 0xf00 id 4.24 flags 0x0
[ 19657013.489583] ( 140.260422) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657124.635417] ( 111.145836) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657232.187500] ( 107.552086) c0 pipe src/audio/pipeline.c:78 pipeline new pipe_id 4 period 5000 priority 0
[ 19657369.895833] ( 137.708328) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657472.968750] ( 103.072914) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657579.583333] ( 106.614586) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657694.791667] ( 115.208336) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657808.645833] ( 113.854164) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19657926.562500] ( 117.916664) c0 ipc src/ipc/handler.c:624 ipc: pm core mask 0x1 -> enable
[ 19722297.864583] ( 64371.300781) c0 mixer 1.1 src/audio/pipeline.c:127 connect buffer 18 as source
[ 19728379.375000] ( 6081.510254) c0 mixer 1.1 src/audio/pipeline.c:127 connect buffer 24 as source
[ 19728836.302083] ( 456.927094) c0 mixer 1.1 src/audio/pipeline.c:125 connect buffer 5 as sink
[ 19728954.270833] ( 117.968750) c0 pga 1.2 src/audio/pipeline.c:127 connect buffer 5 as source
[ 19729074.427083] ( 120.156250) c0 pga 1.2 src/audio/pipeline.c:125 connect buffer 6 as sink
[ 19729197.343750] ( 122.916664) c0 dai 1.3 src/audio/pipeline.c:127 connect buffer 6 as source
[ 19729320.989583] ( 123.645836) c0 host 2.8 src/audio/pipeline.c:127 connect buffer 11 as source
[ 19729478.489583] ( 157.500000) c0 pga 2.9 src/audio/pipeline.c:125 connect buffer 11 as sink
[ 19729700.156250] ( 221.666672) c0 pga 2.9 src/audio/pipeline.c:127 connect buffer 10 as source
[ 19729822.864583] ( 122.708336) c0 dai 2.12 src/audio/pipeline.c:125 connect buffer 10 as sink
[ 19731849.947917] ( 2027.083374) c0 host 3.15 src/audio/pipeline.c:125 connect buffer 17 as sink
[ 19734056.302083] ( 2206.354248) c0 pga 3.16 src/audio/pipeline.c:127 connect buffer 17 as source
[ 19734195.989583] ( 139.687500) c0 pga 3.16 src/audio/pipeline.c:125 connect buffer 18 as sink
[ 19734325.000000] ( 129.010422) c0 host 4.21 src/audio/pipeline.c:125 connect buffer 23 as sink
[ 19734441.562500] ( 116.562500) c0 pga 4.22 src/audio/pipeline.c:127 connect buffer 23 as source
[ 19734577.500000] ( 135.937500) c0 pga 4.22 src/audio/pipeline.c:125 connect buffer 24 as sink
[ 19734727.708333] ( 150.208328) c0 dai src/lib/dai.c:164 dai_get 1.2 new sref 4
[ 19734734.062500] ( 6.354167) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:108 ssp_set_config(), config->format = 16385
[ 19734747.083333] ( 13.020833) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:475 ssp_set_config(), done
[ 19734752.916667] ( 5.833333) c0 dai src/lib/dai.c:189 dai_put 1.2 new sref 3
[ 19734757.291667] ( 4.375000) c0 dai 1.3 src/audio/dai.c:878 dai_config() dai type = 1 index = 2
[ 19734760.781250] ( 3.489583) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[ 19734771.875000] ( 11.093750) c0 dai 2.12 src/audio/dai.c:878 dai_config() dai type = 1 index = 2
[ 19734775.364583] ( 3.489583) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[ 19734915.416667] ( 140.052078) c0 dai src/lib/dai.c:164 dai_get 1.2 new sref 4
[ 19734921.666667] ( 6.250000) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:108 ssp_set_config(), config->format = 16385
[ 19734934.739583] ( 13.072917) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:475 ssp_set_config(), done
[ 19734941.041667] ( 6.302083) c0 dai src/lib/dai.c:189 dai_put 1.2 new sref 3
[ 19734945.416667] ( 4.375000) c0 dai 1.3 src/audio/dai.c:878 dai_config() dai type = 1 index = 2
[ 19734955.104167] ( 9.687500) c0 dai 2.12 src/audio/dai.c:878 dai_config() dai type = 1 index = 2
[ 19735108.177083] ( 153.072922) c0 pipe 4.25 src/audio/pipeline.c:246 pipeline complete, clock freq 343000000Hz
[ 19735113.229167] ( 5.052083) c0 memory src/lib/alloc.c:1030 heap: buffer status
[ 19735116.406250] ( 3.177083) c0 memory src/lib/alloc.c:999 heap: 0xff31b600 size 47616 blocks 1 caps 0x61
[ 19735119.739583] ( 3.333333) c0 memory src/lib/alloc.c:1001 used 23296 free 24320
[ 19735123.072917] ( 3.333333) c0 memory src/lib/alloc.c:1032 heap: runtime status
[ 19735126.250000] ( 3.177083) c0 memory src/lib/alloc.c:999 heap: 0xff317000 size 17920 blocks 7 caps 0x61
[ 19735129.583333] ( 3.333333) c0 memory src/lib/alloc.c:1001 used 8688 free 9232
[ 19735132.812500] ( 3.229167) c0 memory src/lib/alloc.c:1009 block 1 base 0xff317200 size 32
[ 19735136.093750] ( 3.281250) c0 memory src/lib/alloc.c:1012 count 32 free 1
[ 19735139.322917] ( 3.229167) c0 memory src/lib/alloc.c:1009 block 2 base 0xff317600 size 64
[ 19735142.656250] ( 3.333333) c0 memory src/lib/alloc.c:1012 count 32 free 32
[ 19735145.885417] ( 3.229167) c0 memory src/lib/alloc.c:1009 block 3 base 0xff317e00 size 128
[ 19735149.166667] ( 3.281250) c0 memory src/lib/alloc.c:1012 count 32 free 13
[ 19735152.395833] ( 3.229167) c0 memory src/lib/alloc.c:1009 block 4 base 0xff318e00 size 256
[ 19735155.729167] ( 3.333333) c0 memory src/lib/alloc.c:1012 count 32 free 12
[ 19735158.958333] ( 3.229167) c0 memory src/lib/alloc.c:1009 block 5 base 0xff31ae00 size 512
[ 19735162.239583] ( 3.281250) c0 memory src/lib/alloc.c:1012 count 2 free 2
[ 19735165.468750] ( 3.229167) c0 memory src/lib/alloc.c:1009 block 6 base 0xff31b200 size 1024
[ 19735168.750000] ( 3.281250) c0 memory src/lib/alloc.c:1012 count 1 free 1
[ 19737303.645833] ( 2134.895752) c0 pipe 3.19 src/audio/pipeline.c:246 pipeline complete, clock freq 343000000Hz
[ 19737434.322917] ( 130.677078) c0 pipe 2.13 src/audio/pipeline.c:246 pipeline complete, clock freq 343000000Hz
[ 19737549.479167] ( 115.156250) c0 pipe 1.4 src/audio/pipeline.c:246 pipeline complete, clock freq 343000000Hz
[ 19737695.104167] ( 145.625000) c0 pga 4.22 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 0, value = 65536
[ 19737698.437500] ( 3.333333) c0 pga 4.22 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 1, value = 65536
[ 19737912.083333] ( 213.645828) c0 pga 3.16 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 0, value = 65536
[ 19737915.416667] ( 3.333333) c0 pga 3.16 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 1, value = 65536
[ 19738126.145833] ( 210.729172) c0 pga 2.9 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 0, value = 65536
[ 19738129.479167] ( 3.333333) c0 pga 2.9 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 1, value = 65536
[ 19738340.104167] ( 210.625000) c0 pga 1.2 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 0, value = 65536
[ 19738343.437500] ( 3.333333) c0 pga 1.2 ../audio/volume/volume.c:643 volume_ctrl_get_cmd(), channel = 1, value = 65536
[ 65633849.479167] ( 45895508.000000) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[ 65634034.218750] ( 184.739578) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 0 channel 2 put
[ 65634051.718750] ( 17.500000) c0 pipe 3.19 src/audio/pipeline.c:538 pipe params dir 0 frame_fmt 0 buffer_fmt 0 rate 48000
[ 65634055.104167] ( 3.385417) c0 pipe 3.19 src/audio/pipeline.c:542 pipe params stream_tag 0 channels 2 sample_valid_bytes 2 sample_container_bytes 2
[ 65634084.062500] ( 28.958334) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535
[ 65634122.083333] ( 38.020832) c0 dai 1.3 src/audio/dai.c:349 dai_playback_params() dest_dev = 5 stream_id = 0 src_width = 4 dest_width = 4
[ 65634125.520833] ( 3.437500) c0 dai 1.3 src/audio/dai.c:355 dai_playback_params() fifo 0xff2a2010
[ 65634134.114583] ( 8.593750) c0 pipe 3.19 src/audio/pipeline.c:669 pipe prepare
[ 65635528.229167] ( 1394.114624) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[ 65635713.020833] ( 184.791672) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 0 channel 2 put
[ 65635730.677083] ( 17.656250) c0 pipe 2.13 src/audio/pipeline.c:538 pipe params dir 1 frame_fmt 0 buffer_fmt 0 rate 48000
[ 65635734.583333] ( 3.906250) c0 pipe 2.13 src/audio/pipeline.c:542 pipe params stream_tag 0 channels 2 sample_valid_bytes 2 sample_container_bytes 2
[ 65635761.145833] ( 26.562500) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535
[ 65635793.125000] ( 31.979166) c0 dai 2.12 src/audio/dai.c:410 dai_capture_params() src_dev = 4 stream_id = 0 src_width = 4 dest_width = 4
[ 65635796.562500] ( 3.437500) c0 dai 2.12 src/audio/dai.c:416 dai_capture_params() fifo 0xff2a2010
[ 65635804.947917] ( 8.385417) c0 pipe 2.13 src/audio/pipeline.c:669 pipe prepare
[ 65641041.406250] ( 5236.458496) c0 pipe 3.19 src/audio/pipeline.c:949 pipe reset
[ 65641046.875000] ( 5.468750) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 1 channel 1 put
[ 65642081.979167] ( 1035.104126) c0 pipe 2.13 src/audio/pipeline.c:949 pipe reset
[ 65642087.500000] ( 5.520833) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 1 channel 2 put
[260586445.833333] (194944352.000000) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[260586630.260417] ( 184.427078) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 0 channel 2 put
[260586650.625000] ( 20.364584) c0 pipe 3.19 src/audio/pipeline.c:538 pipe params dir 0 frame_fmt 2 buffer_fmt 0 rate 48000
[260586654.010417] ( 3.385417) c0 pipe 3.19 src/audio/pipeline.c:542 pipe params stream_tag 0 channels 2 sample_valid_bytes 4 sample_container_bytes 4
[260586683.229167] ( 29.218750) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535
[260586721.562500] ( 38.333332) c0 dai 1.3 src/audio/dai.c:349 dai_playback_params() dest_dev = 5 stream_id = 0 src_width = 4 dest_width = 4
[260586724.947917] ( 3.385417) c0 dai 1.3 src/audio/dai.c:355 dai_playback_params() fifo 0xff2a2010
[260586733.541667] ( 8.593750) c0 pipe 3.19 src/audio/pipeline.c:669 pipe prepare
[260886167.135417] ( 299433.593750) c0 pipe 3.19 src/audio/pipeline.c:863 pipe trigger cmd 1
[260886178.437500] ( 11.302083) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:587 ssp_trigger()
[260886185.833333] ( 7.395833) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:526 ssp_start()
[260886197.656250] ( 11.822917) c0 ll-schedule ./schedule/ll_schedule.c:345 task add 0xff317640 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[260886200.885417] ( 3.229167) c0 ll-schedule ./schedule/ll_schedule.c:349 task params pri 0 flags 0 start 0 period 1000
[260886204.583333] ( 3.697917) c0 ll-schedule /dma_multi_chan_domain.c:112 dma_multi_chan_domain_register()
[260886208.802083] ( 4.218750) c0 ll-schedule ./schedule/ll_schedule.c:252 num_tasks 1 total_num_tasks 1
[260886213.906250] ( 5.104167) c0 ll-schedule ./schedule/ll_schedule.c:345 task add 0xff317680 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[260886217.187500] ( 3.281250) c0 ll-schedule ./schedule/ll_schedule.c:349 task params pri 1 flags 0 start 0 period 1000
[260886220.885417] ( 3.697917) c0 ll-schedule /dma_multi_chan_domain.c:112 dma_multi_chan_domain_register()
[260886225.677083] ( 4.791667) c0 ll-schedule /dma_multi_chan_domain.c:73 dma_multi_chan_domain_irq_register()
[260886231.093750] ( 5.416667) c0 ll-schedule ./schedule/ll_schedule.c:252 num_tasks 2 total_num_tasks 2
[273350383.385417] ( 12464152.000000) c0 pipe 3.19 src/audio/pipeline.c:863 pipe trigger cmd 0
[273350391.041667] ( 7.656250) c0 dw-dma src/drivers/dw/dma.c:406 dw_dma_stop(): dma 0 channel 0 stop
[273350743.125000] ( 352.083344) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:587 ssp_trigger()
[273350751.979167] ( 8.854167) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:558 ssp_stop(), TX stop
[273350760.520833] ( 8.541667) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:565 ssp_stop(), SSP port disabled
[273350768.541667] ( 8.020833) c0 ll-schedule ./schedule/ll_schedule.c:437 task cancel 0xff317640 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[273350772.083333] ( 3.541667) c0 ll-schedule ./schedule/ll_schedule.c:290 num_tasks 1 total_num_tasks 1
[273350775.520833] ( 3.437500) c0 ll-schedule /dma_multi_chan_domain.c:215 dma_multi_chan_domain_unregister()
[273350779.479167] ( 3.958333) c0 ll-schedule ./schedule/ll_schedule.c:437 task cancel 0xff317680 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[273350783.437500] ( 3.958333) c0 ll-schedule ./schedule/ll_schedule.c:290 num_tasks 0 total_num_tasks 0
[273350786.822917] ( 3.385417) c0 ll-schedule /dma_multi_chan_domain.c:215 dma_multi_chan_domain_unregister()
[273350792.864583] ( 6.041667) c0 ll-schedule /dma_multi_chan_domain.c:191 dma_multi_chan_domain_irq_unregister()
[273351605.833333] ( 812.968750) c0 pipe 3.19 src/audio/pipeline.c:949 pipe reset
[273351611.302083] ( 5.468750) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 1 channel 1 put
[417323384.479167] (143971776.000000) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[417323569.218750] ( 184.739578) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 0 channel 2 put
[417323589.583333] ( 20.364584) c0 pipe 3.19 src/audio/pipeline.c:538 pipe params dir 0 frame_fmt 2 buffer_fmt 0 rate 48000
[417323592.968750] ( 3.385417) c0 pipe 3.19 src/audio/pipeline.c:542 pipe params stream_tag 0 channels 2 sample_valid_bytes 4 sample_container_bytes 4
[417323622.187500] ( 29.218750) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535
[417323660.520833] ( 38.333332) c0 dai 1.3 src/audio/dai.c:349 dai_playback_params() dest_dev = 5 stream_id = 0 src_width = 4 dest_width = 4
[417323663.958333] ( 3.437500) c0 dai 1.3 src/audio/dai.c:355 dai_playback_params() fifo 0xff2a2010
[417323672.500000] ( 8.541667) c0 pipe 3.19 src/audio/pipeline.c:669 pipe prepare
[417613341.770833] ( 289669.281250) c0 pipe 3.19 src/audio/pipeline.c:863 pipe trigger cmd 1
[417613353.177083] ( 11.406250) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:587 ssp_trigger()
[417613358.489583] ( 5.312500) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:526 ssp_start()
[417613368.645833] ( 10.156250) c0 ll-schedule ./schedule/ll_schedule.c:345 task add 0xff317640 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[417613371.875000] ( 3.229167) c0 ll-schedule ./schedule/ll_schedule.c:349 task params pri 0 flags 0 start 0 period 1000
[417613375.572917] ( 3.697917) c0 ll-schedule /dma_multi_chan_domain.c:112 dma_multi_chan_domain_register()
[417613379.739583] ( 4.166667) c0 ll-schedule ./schedule/ll_schedule.c:252 num_tasks 1 total_num_tasks 1
[417613384.947917] ( 5.208333) c0 ll-schedule ./schedule/ll_schedule.c:345 task add 0xff317680 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[417613388.177083] ( 3.229167) c0 ll-schedule ./schedule/ll_schedule.c:349 task params pri 1 flags 0 start 0 period 1000
[417613391.927083] ( 3.750000) c0 ll-schedule /dma_multi_chan_domain.c:112 dma_multi_chan_domain_register()
[417613396.666667] ( 4.739583) c0 ll-schedule /dma_multi_chan_domain.c:73 dma_multi_chan_domain_irq_register()
[417613402.083333] ( 5.416667) c0 ll-schedule ./schedule/ll_schedule.c:252 num_tasks 2 total_num_tasks 2
[487894754.218750] ( 70281352.000000) c0 pipe 3.19 src/audio/pipeline.c:863 pipe trigger cmd 0
[487894761.927083] ( 7.708333) c0 dw-dma src/drivers/dw/dma.c:406 dw_dma_stop(): dma 0 channel 0 stop
[487895106.510417] ( 344.583344) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:587 ssp_trigger()
[487895115.416667] ( 8.906250) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:558 ssp_stop(), TX stop
[487895124.010417] ( 8.593750) c0 <uid?> 1.2 .../intel/baytrail/ssp.c:565 ssp_stop(), SSP port disabled
[487895132.083333] ( 8.072917) c0 ll-schedule ./schedule/ll_schedule.c:437 task cancel 0xff317640 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[487895135.729167] ( 3.645833) c0 ll-schedule ./schedule/ll_schedule.c:290 num_tasks 1 total_num_tasks 1
[487895139.114583] ( 3.385417) c0 ll-schedule /dma_multi_chan_domain.c:215 dma_multi_chan_domain_unregister()
[487895143.072917] ( 3.958333) c0 ll-schedule ./schedule/ll_schedule.c:437 task cancel 0xff317680 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[487895147.031250] ( 3.958333) c0 ll-schedule ./schedule/ll_schedule.c:290 num_tasks 0 total_num_tasks 0
[487895150.416667] ( 3.385417) c0 ll-schedule /dma_multi_chan_domain.c:215 dma_multi_chan_domain_unregister()
[487895156.458333] ( 6.041667) c0 ll-schedule /dma_multi_chan_domain.c:191 dma_multi_chan_domain_irq_unregister()
[487895301.822917] ( 145.364578) c0 pipe 3.19 src/audio/pipeline.c:949 pipe reset
[487895307.291667] ( 5.468750) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 1 channel 1 put
[489529872.812500] ( 1634565.500000) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 0 request channel 0
[489530057.604167] ( 184.791672) c0 dw-dma src/drivers/dw/dma.c:253 dw_dma_channel_put(): dma 0 channel 2 put
[489530077.968750] ( 20.364584) c0 pipe 3.19 src/audio/pipeline.c:538 pipe params dir 0 frame_fmt 2 buffer_fmt 0 rate 48000
[489530081.354167] ( 3.385417) c0 pipe 3.19 src/audio/pipeline.c:542 pipe params stream_tag 0 channels 2 sample_valid_bytes 4 sample_container_bytes 4
[489530110.572917] ( 29.218750) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535
[489530148.906250] ( 38.333332) c0 dai 1.3 src/audio/dai.c:349 dai_playback_params() dest_dev = 5 stream_id = 0 src_width = 4 dest_width = 4
[489530152.343750] ( 3.437500) c0 dai 1.3 src/audio/dai.c:355 dai_playback_params() fifo 0xff2a2010
[489530160.885417] ( 8.541667) c0 pipe 3.19 src/audio/pipeline.c:669 pipe prepareHopefully that should give you ideas ;)
@plbossart The files I used to test it on were music files, so I can't post them on GitHub. However I can reproduce reliably on the official kernel after a couple of minutes, with:
systemctl --user stop pipewire pipewire-pulse pipewire.socket pipewire-pulse.socketaplay doesn't try to resample, e.g.: ffmpeg -i input.mp3 -f s32le -c:a pcm_s32le -ar 48000 -ac 2 test_s32le_48000.rawaplay -D sysdefault:CARD=rt5640 -f s32_le -r 48000 -c 2 -v test_s32le_48000.raw -iplbossart
commented
3 years ago Thanks @fxthomas
@lgirdwood does this one look legit to you?
[489530110.572917] ( 29.218750) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535Thanks @fxthomas
@lgirdwood does this one look legit to you?
[489530110.572917] ( 29.218750) c0 dw-dma src/drivers/dw/dma.c:190 dw_dma_channel_get(): dma 1 request channel 65535
@plbossart 65535(0xFFFF) is illegitimate for SSP dai DMA we always ask for channel 0 and it will return the real allocated channel index, though for HDA dai, we could use 0xFFFFFFFF to ask for not handling with a dma_channel_get().
But, for the dw_dma_channel_get(), no matter what channel index you have asked for, it will always allocated a real channel (e.g. with index 0~7), so this is not necessary lead to any problem IMO.
Looks there is some memory error here, someone can reproduce it should debug with printing out the 'channel' in the dai_config() when issue happen here, in case some stack overflow happen, it could crash/hang the FW then the SSP could output the last samples all the time, and then persistent beeping sound will be heard.
Afsalmc
commented
3 years ago May be not very useful , But i can confirm the same bug in Baytrail Z3735f / bytht rt5640 (bytcr-rt5640) regardless of PW or Pulseaudio .
fxthomas
commented
3 years ago Just a quick update: the issue is also still present in official builds of kernel 5.12.7 with sof-bin firmware version 1.7.
I discovered one more thing after https://github.com/thesofproject/sof-docs/issues/347#issuecomment-850844323: firmware trace logging seems to be responsible for the fact that the issue is much harder to reproduce.
Enabling it in my official kernel (without recompiling) almost makes the issue disappear, just like it did with my custom build earlier.
@Afsalmc does enabling sof_debug like in the comment linked above also help in your case?
Afsalmc
commented
3 years ago Just a quick update: the issue is also still present in official builds of kernel 5.12.7 with sof-bin firmware version 1.7.
I discovered one more thing after thesofproject/sof-docs#347 (comment): firmware trace logging seems to be responsible for the fact that the issue is much harder to reproduce.
Enabling it in my official kernel (without recompiling) almost makes the issue disappear, just like it did with my custom build earlier.
@Afsalmc does enabling
sof_debuglike in the comment linked above also help in your case?
It's a surprise for me . No beeps so far after enabling sof_dubg .been playing audio for 15+ minutes , and usually this was enough for like 5 + beeps in my machine . Will do more tests and report back . Thanks .
Afsalmc
commented
3 years ago I have experienced No beeps so far .
I had this issue while trying to debug https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/530 on an HP Detachable x2 ultrabook, where we're trying to see if the SOF driver is somehow more stable than SST.
This issue happens with raw ALSA (neither Pipewire/Pulseaudio running) as well as with both PW/PA.
The following sequence reproduces the issue 100% of the time:
options snd-intel-dspcfg dsp_driver=3on a 5.11 kerneldmesg | grep sofaplay -D <device name> file.wavfor example)As far as I can tell the beep only goes away when starting (if running raw ALSA) or restarting (if already running) the Pipewire/Pulseaudio server, which restores proper playback until the next beep.
The default SST driver is stable for basic audio output in S16LE, despite issues in other areas.
Environment 1) Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
Logs:
dmesgat allsof-logger, is there a way for me to compile it without bringing up the whole toolchain?I'm not familiar at all with SOF, so if this is the wrong place for a report do let me know!