search

thesofproject / sof

Sound Open Firmware
Other
560 stars 318 forks source link

[BUG] step up in output volume on Thinkpad X1 Carbon 7th #3072

Closed gobenji closed 4 years ago

gobenji commented 4 years ago

Describe the bug When playing some streams on the Thinkpad X1 Carbon 7th, the volume level is noticeably (~50%?) lower for the first ~0.5s.

To Reproduce I can hear it by playing the following sample via aplay: aplay -Dhw:0,0 output.wav The second bell ring sounds louder. Opening the file in ex. audacity shows that in fact the two bell rings are of the same amplitude.

Reproduction Rate Reproduces all the time when playing directly through alsa. Results are mixed when playing through pulseaudio. The volume step up is sometimes there, sometimes not; I don't know why. It seems to me that this occurs more frequently with sof firmware v1.5 than v1.4.3 but when alternating between the two by changing the files under /lib/firmware and unloading/reloading kernel modules, I can sometimes reproduce the issue with v1.4.3 as well. v1.5.1 is the same as v1.5 in this regard (also bad). This seems to occur regardless of mixer levels. It occurs in headphones and speakers.

Expected behavior Constant sound level.

Impact annoyance, in daily use it doesn't seem to occur with pulseaudio output if I boot with v1.4.3 sof firmware and don't touch it afterwards.

Environment 1) Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).

2) Name of the topology file

lgirdwood commented 4 years ago

@singalsu any comments ?

singalsu commented 4 years ago

@lgirdwood @gobenji Thanks for reporting! The volume linear ramp is 250 ms long and the first "beep" in this sound clip about the same length so large amount of it, e.g. first 100 ms, get a significant attenuation. The ramp was made long to avoid zipper noise (higher frequency rattle while adjusting volume). There has been also need to conceal noise sounds in the beginning but it's more a capture issue.

But since we have now the zero crossings detector timed volume ramp it should be safe to shorten a lot the ramp. I'll test it how it sounds and if OK I'll create a PR for topology.

singalsu commented 4 years ago

I created PR #3098 to address this. The topology change only works with v1.5.1 firmware but there can be some zipper noise rattle when the ramp is active. I can hear it with test signals easily, depending on music content less easily. But the beep beep notification becomes fully audible from beginning.

But the fixes for ramp rate adjustment and improvements to fractional time computation below ms granularity need new firmware build.

plbossart commented 4 years ago

@singalsu we may want to be careful here in terms of user-experience.

When playing with PulseAudio, the sink remains open for 5s before being closed. So if a beep is send while the stream is active but sending zeroes, we would have no ramp in the firmware. We will however have a ramp when the sink is inactive and the beep makes it active.

Conversely, when playing with ALSA we will always have a ramp since we close immediately.

I am starting to wonder if the ramp duration and its activation should not be controlled by ALSA controls?

Adding @kv2019i and @juimonen for comments on PulseAudio usage.

singalsu commented 4 years ago

@plbossart The ALSA audio open related fade-in ramp helps to avoid pop noise from codec in playback so this simple logic works for that. Pulse likely does also ramps so FW stream start ramp could be avoided for playback. But we don't have separate ramp duration parameters for start and normal volume adjust so some additional controls/parameters could be useful. Good to discuss to get this optimal for Pulse and CRAS usage. Bare ALSA is marginal use case.

gobenji commented 4 years ago

Just to provide some context, in my case I noticed this problem because I use this bell sound for the terminal bell via pulseaudio:

load-sample x11-bell /usr/share/sounds/freedesktop/stereo/window-attention.oga
load-module module-x11-bell sample=x11-bell display=:0

Because of the ramp-up, the first terminal bell after the device is idle sounds noticeably weaker than a closely following bell. I find that really annoying from a UX PoV. I usually test it by simply openning an empty terminal with bash and pressing <tab> a few times. As a workaround, I've edited /etc/pulse/default.pa and commented out load-module module-suspend-on-idle.

singalsu commented 4 years ago

The PR #3098 is merged now to git master. Successive FW releases will contain this fix.

@gobenji If you'd like to test you could build the topologies (sof-hda-generic-4ch.tplg) from git master and use it with v1.5.1 firmware. The difference to git master is that the ramp of 20 ms length is stepped in 20 ms that makes it sound a bit harsh. With the updated firmware the short ramp would use 125 us update rate. Whether the slightly harsh sounding beginning is an issue or not is quite subjective.

singalsu commented 4 years ago

I created a zip file with testbench simulations of volume component that demonstrates the effect of tplg and fw updates in the pull request.

alert_tone_volume_processed.zip

Here's screenshots of the wav files with spectrograms shown:

Screenshot from 2020-06-30 11-43-28 Screenshot from 2020-06-30 11-44-17 Screenshot from 2020-06-30 11-44-39

The reported issue shows well in the waveform. The ramp harshness with just topology updated may not be fully exposed by this demo. When playing back music muting and unmuting can make some rattle sound at times and be annoying. With both updated tplg and fw algorithm the perceived use case quality is good.

gobenji commented 4 years ago

@singalsu Thanks for tackling this problem so quickly. I tried to test the changes but the result was unsucessful.

Using the instructions from https://thesofproject.github.io/latest/getting_started/build-guide/build-with-docker.html I built topology files using the upstream docker image (thesofproject/sof). However, after installing sof-hda-generic-4ch.tplg into /lib/firmware and rebooting, I have no sound output at all.

The audio device finishes probing and appears in pulseaudio, however I see the following in dmesg:

sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 2
sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 20
sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 42
sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 50
sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 58
[...]
sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 58
sof-audio-pci 0000:00:1f.3: error: failed kcontrol value set for widget: 58
sof-audio-pci 0000:00:1f.3: error: restoring kcontrols after resume
sof-audio-pci 0000:00:1f.3: error: failed to restore pipeline after resume -22

I tried this from sof.git HEAD (882875fa). I also tried it from v1.5.1 tag (which corresponded with the sof-cnl.ri file in /lib/firmware at that moment) + a cherry-pick of commit 673e335a7a82 ("Tools: Topology: Change playback volume ramp duration to 20 ms"). The result was the same as above.

I don't think this is a problem when building because if I build from the v1.5.1 tag, I get exactly the same tplg file as in sof-bin:

ben@f3:~/local/src/sof$ sha1sum tools/build_tools/topology/sof-hda-generic-4ch.tplg ../sof-bin/lib/firmware/intel/sof-tplg-v1.5.1/sof-hda-generic-4ch.tplg 
f4130d5156105bc364cb85cd3c069b5980d6fb7d  tools/build_tools/topology/sof-hda-generic-4ch.tplg
f4130d5156105bc364cb85cd3c069b5980d6fb7d  ../sof-bin/lib/firmware/intel/sof-tplg-v1.5.1/sof-hda-generic-4ch.tplg

Please let me know if you have some advice.

BTW, in order to be able to use the upstream docker image, I have to apply the following small diff

--- a/scripts/docker-run.sh
+++ b/scripts/docker-run.sh
@@ -11,4 +11,5 @@
 #  ./scripts/docker-run.sh ./scripts/build-tools.sh

 docker run -i -t -v `pwd`:/home/sof/work/sof.git \
+       -e http_proxy="" -e https_proxy="" \
           --user `id -u` sof $@

otherwise, it uses

http_proxy="http://proxy-chain.intel.com:911"
https_proxy="http://proxy-chain.intel.com:912"
lgirdwood commented 4 years ago

@gobenji thanks for docker fix, @xiulipan do we have a place for merging docker fixes ? Btw @singalsu is on vacation.

singalsu commented 4 years ago

@gobenji I have now a similar device available for testing so I can test it myself too. I'll start today/tomorrow. I assume this problem still exists, right?

gobenji commented 4 years ago

I repeated the test in the description (double bell sound) with sof-cnl.ri and sof-hda-generic-4ch.tplg from sof-bin branch "stable-v1.5.1" and can still reproduce the same issue.

I also tried again from sof.git HEAD (420ef1b6) and built sof-hda-generic-4ch.tplg using the same procedure I described in my last comment. The resultng tplg file is:

ben@f3:~/local/src/sof$ sha1sum tools/build_tools/topology/sof-hda-generic-4ch.tplg
f1cc4e6758a89cb0774a5ad1556fbe79abb2e1e0  tools/build_tools/topology/sof-hda-generic-4ch.tplg

I got a similar problem as before with exactly the same error messages when loading the driver and trying to play a file (no sound output). Note that this was while still using sof-cnl.ri from stable-v1.5.1. I didn't try to deal with the signing procedure.

singalsu commented 4 years ago

I just tried a fresh built topology with X1 and Ubuntu's 5.4.0-44-generic kernel (I needed to enable focal proposed repository to get sound working, confirmed the long ramp to happen for your beep beep waveform with previous topology).

Now I got the same IPC errors in boot. Playback to headphones was silent. No errors reported by aplay nor errors seen in kernel messages during playback. The microphones capture works though. I'll try next build and install a new sof-dev kernel to see if it does the same.

singalsu commented 4 years ago

My bad, the ZC ramp type was not yet available in v1.5.1. It's quite obvious when enabling firmware trace:

[  3683870.208333] (        3.916667) c0 volume       1.2   ../audio/volume/volume.c:437   ERROR volume_set_chan(): invalid ramp type 2
[  3683876.208333] (        6.000000) c0 IPC                       src/ipc/handler.c:1004  ERROR ipc: comp 2 cmd 0 failed -22
singalsu commented 4 years ago

This patch for topology with v1.5.1 plays sound and uses a short 20 ms linear ramp without zero crossings detect. Patching only pipe-volume-playback.m4 should be sufficient but I changed here for completeness every ZC ramp type to non-ZC.

From a5e19bde1b0bed712acf8b9612834a2987fa56bd Mon Sep 17 00:00:00 2001
From: Seppo Ingalsuo <seppo.ingalsuo@linux.intel.com>
Date: Thu, 27 Aug 2020 15:01:52 +0300
Subject: [PATCH] Topology: Revert zero crossings detect in playback volume
 control

For test with firmware v1.5.1.

Signed-off-by: Seppo Ingalsuo <seppo.ingalsuo@linux.intel.com>
---
 tools/topology/sof/pipe-asrc-volume-playback.m4          | 2 +-
 tools/topology/sof/pipe-dcblock-volume-playback.m4       | 2 +-
 tools/topology/sof/pipe-eq-fir-volume-playback.m4        | 2 +-
 tools/topology/sof/pipe-eq-iir-eq-fir-volume-playback.m4 | 2 +-
 tools/topology/sof/pipe-eq-iir-volume-playback.m4        | 2 +-
 tools/topology/sof/pipe-src-volume-playback.m4           | 2 +-
 tools/topology/sof/pipe-volume-playback.m4               | 2 +-
 7 files changed, 7 insertions(+), 7 deletions(-)

diff --git a/tools/topology/sof/pipe-asrc-volume-playback.m4 b/tools/topology/sof/pipe-asrc-volume-playback.m4
index f488b07c7ae0..87da0bfdc0ae 100644
--- a/tools/topology/sof/pipe-asrc-volume-playback.m4
+++ b/tools/topology/sof/pipe-asrc-volume-playback.m4
@@ -57,7 +57,7 @@ W_ASRC(0, PIPELINE_FORMAT, 2, 2, MY_ASRC_CONF)
 define(MY_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(MY_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))
 W_VENDORTUPLES(MY_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))
 W_DATA(MY_PGA_CONF, MY_PGA_TOKENS)

diff --git a/tools/topology/sof/pipe-dcblock-volume-playback.m4 b/tools/topology/sof/pipe-dcblock-volume-playback.m4
index ac4f44171c4c..62409cf739d3 100644
--- a/tools/topology/sof/pipe-dcblock-volume-playback.m4
+++ b/tools/topology/sof/pipe-dcblock-volume-playback.m4
@@ -33,7 +33,7 @@ C_CONTROLMIXER(Master Playback Volume, PIPELINE_ID,
 define(MY_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(MY_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))
 W_VENDORTUPLES(MY_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))

 W_DATA(MY_PGA_CONF, MY_PGA_TOKENS)
diff --git a/tools/topology/sof/pipe-eq-fir-volume-playback.m4 b/tools/topology/sof/pipe-eq-fir-volume-playback.m4
index 02af5e2dcb67..9d73ed8d0599 100644
--- a/tools/topology/sof/pipe-eq-fir-volume-playback.m4
+++ b/tools/topology/sof/pipe-eq-fir-volume-playback.m4
@@ -35,7 +35,7 @@ define(DEF_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(DEF_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))

 W_VENDORTUPLES(DEF_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))

 W_DATA(DEF_PGA_CONF, DEF_PGA_TOKENS)
diff --git a/tools/topology/sof/pipe-eq-iir-eq-fir-volume-playback.m4 b/tools/topology/sof/pipe-eq-iir-eq-fir-volume-playback.m4
index 85022fef63b2..39f7fc1a1966 100644
--- a/tools/topology/sof/pipe-eq-iir-eq-fir-volume-playback.m4
+++ b/tools/topology/sof/pipe-eq-iir-eq-fir-volume-playback.m4
@@ -37,7 +37,7 @@ define(DEF_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(DEF_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))

 W_VENDORTUPLES(DEF_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))

 W_DATA(DEF_PGA_CONF, DEF_PGA_TOKENS)
diff --git a/tools/topology/sof/pipe-eq-iir-volume-playback.m4 b/tools/topology/sof/pipe-eq-iir-volume-playback.m4
index fc71eb72c6f5..9a9647937c64 100644
--- a/tools/topology/sof/pipe-eq-iir-volume-playback.m4
+++ b/tools/topology/sof/pipe-eq-iir-volume-playback.m4
@@ -35,7 +35,7 @@ define(DEF_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(DEF_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))

 W_VENDORTUPLES(DEF_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))

 W_DATA(DEF_PGA_CONF, DEF_PGA_TOKENS)
diff --git a/tools/topology/sof/pipe-src-volume-playback.m4 b/tools/topology/sof/pipe-src-volume-playback.m4
index 118fed76c6b7..a5e435cd5b85 100644
--- a/tools/topology/sof/pipe-src-volume-playback.m4
+++ b/tools/topology/sof/pipe-src-volume-playback.m4
@@ -53,7 +53,7 @@ define(DEF_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(DEF_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))

 W_VENDORTUPLES(DEF_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))

 W_DATA(DEF_PGA_CONF, DEF_PGA_TOKENS)
diff --git a/tools/topology/sof/pipe-volume-playback.m4 b/tools/topology/sof/pipe-volume-playback.m4
index cb7d2ad67a27..7fd48dc96934 100644
--- a/tools/topology/sof/pipe-volume-playback.m4
+++ b/tools/topology/sof/pipe-volume-playback.m4
@@ -33,7 +33,7 @@ define(DEF_PGA_TOKENS, concat(`pga_tokens_', PIPELINE_ID))
 define(DEF_PGA_CONF, concat(`pga_conf_', PIPELINE_ID))

 W_VENDORTUPLES(DEF_PGA_TOKENS, sof_volume_tokens,
-LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "2"'
+LIST(`     ', `SOF_TKN_VOLUME_RAMP_STEP_TYPE   "0"'
      `     ', `SOF_TKN_VOLUME_RAMP_STEP_MS     "20"'))

 W_DATA(DEF_PGA_CONF, DEF_PGA_TOKENS)
-- 
2.25.1

Since v1.5.1 is the latest release there's no released fix for the fairly large attenuation of the first beep. My mistake here was to assume the git master topology would work with v1.5.1. Release v1.5.1 remains OK and does not have the muted play or IPC errors issue that the git master topology triggered. Except attenuation with long ramp... Hope there will be soon a new release soon to fix that.

lgirdwood commented 4 years ago

@gobenji there are also some volume fixes in v1.6-rc3 https://github.com/thesofproject/sof-bin/tree/stable-v1.6

gobenji commented 4 years ago

Thanks for the heads up. I just tried with the files from stable-v1.6 commit d211dd0 but I'm still experiencing the same step up in volume when playing the sound sample from c0 using aplay. Just to confirm, the md5sum of the files I used are:

8ce3f53dff8d6885329ce263380ae0cf  /lib/firmware/intel/sof/sof-cnl.ri
da4eb75a834f248ff9b38dec3b1ca93f  /lib/firmware/intel/sof-tplg/sof-hda-generic-4ch.tplg
lgirdwood commented 4 years ago

@singalsu fyi could ZC be disabled or could this be something else (e.g. codec related) ?

singalsu commented 4 years ago

@gobenji You have same v1.6 topology and FW md5sums as I have. Could you please try the following with firmware trace. The ramp lengths for playback pipelines should be 20 ms now. The two 250 ms long ramps are for PCM6C and PCM7C for DMIC capture. The 400 long ramps are for PCM0C and PCM1C.

$ sudo /usr/local/bin/sof-logger -c 24.0 -l /lib/firmware/intel/sof/v1.6/sof-cnl-v1.6.ldc -t | grep initial_ramp
[225383318.583333] (       15.833333) c0 pga          1.2   ../audio/volume/volume.c:379  vol->initial_ramp = 20, vol->ramp = 2, vol->min_value = 0, vol->max_value = 65536
[225384797.625000] (       15.541667) c0 pga          2.10  ../audio/volume/volume.c:379  vol->initial_ramp = 400, vol->ramp = 0, vol->min_value = 0, vol->max_value = 2072775
[225386301.833333] (       15.541667) c0 pga          3.20  ../audio/volume/volume.c:379  vol->initial_ramp = 20, vol->ramp = 2, vol->min_value = 0, vol->max_value = 65536
[225387176.208333] (       15.541667) c0 pga          4.28  ../audio/volume/volume.c:379  vol->initial_ramp = 400, vol->ramp = 0, vol->min_value = 0, vol->max_value = 2072775
[225388317.750000] (       15.500000) c0 pga          7.42  ../audio/volume/volume.c:379  vol->initial_ramp = 20, vol->ramp = 2, vol->min_value = 0, vol->max_value = 65536
[225389215.708333] (       15.583333) c0 pga          8.50  ../audio/volume/volume.c:379  vol->initial_ramp = 20, vol->ramp = 2, vol->min_value = 0, vol->max_value = 65536
[225390267.708333] (       15.541667) c0 pga          9.58  ../audio/volume/volume.c:379  vol->initial_ramp = 20, vol->ramp = 2, vol->min_value = 0, vol->max_value = 65536
[225391518.375000] (       15.583333) c0 pga          10.65 ../audio/volume/volume.c:379  vol->initial_ramp = 250, vol->ramp = 0, vol->min_value = 0, vol->max_value = 655434
[225393401.625000] (       15.458333) c0 pga          11.73 ../audio/volume/volume.c:379  vol->initial_ramp = 250, vol->ramp = 0, vol->min_value = 0, vol->max_value = 655434

Subjectively the two beeps sound similarly loud to me. If you got the above trace output and if the 20 ms feels still too long we can try to shorten it with a custom topology. This time the kernel and FW should allow it.

gobenji commented 4 years ago

I've tried to run the sof-logger tool but I get in one of two situations:

Meanwhile, to provide an objective report of what's going on, I've used a patch cable and connected the line out from the laptop into the input of a usb sound card. It only has a mic-in so it's a mono recording but it's enough to get an idea of what's happening: Screenshot_loopback-recording The top track is the loopback recording of the sound file from c0 being played three times. The bottom track shows the original sound file for comparison. As reported in my earlier comment, we can see that the problem is only apparent when the device is coming out of idle. This is the corresponding audacity project.

gobenji commented 4 years ago

BTW, I was beginning to wonder if this is a problem of the sound card and is not related to sof... I remembered that I first reported this problem because it was a regression. I've just gone back and tested with snd_intel_dspcfg.dsp_driver=1 to force the legacy (non sof...) driver. Using the same double bell sample, I confirmed that there is no step up in volume - the problem is not apparent when running in legacy mode. So it does seem that this problem is related to sof in some way.

gobenji commented 4 years ago

Hmm, it seems I spoke too fast. I can reproduce the same problem (or very similar) when running in legacy mode: Screenshot_legacy So I guess that this is a problem of the sound card in the end. In any case, it is no related to sof. I'm very sorry for leading you on a wild goose chase for so long. Please feel free to close this issue as invalid unless you think that this can be worked around in sof somehow.

lgirdwood commented 4 years ago

@gobenji no worries, it's always good to check, it tunrns out we may have an issue with logger though if it's empty during playback. @akloniex @bkokoszx @slawblauciak is this a logger issue ? This was a logger v1.6 binary so unexpected.

paulstelian97 commented 4 years ago

On the logger:

Note that there is no /sys/kernel/debug/sof/trace in my case so I've left out the -t option.

What feels weird to me is why DMA trace is not available (for the -t option). etrace is much more hacky (it works even when firmware is stuck and might even show some logs before getting stuck that don't show up in DMA trace, but it has some unexpected characteristics). So I'm bringing the question up on why DMA trace isn't available.

gobenji commented 4 years ago

Regarding sof-logger, maybe I should also mention that when I run it and the output is empty, the tool exits right away. Here is an strace of sof-logger running as described previously, in case that's of any use: output.txt This is on a debian 5.8.0-2-amd64 kernel (based on stable v5.8.10) I've also double-checked that there is no trace file available:

root@f3:~# l /sys/kernel/debug/sof/
total 0
drwxr-xr-x  2 root root 0 Oct 11 18:11 .
drwx------ 41 root root 0 Oct 11 18:11 ..
-r--r--r--  1 root root 0 Oct 11 18:11 cc_version
-r--r--r--  1 root root 0 Oct 11 18:11 debug
-r--r--r--  1 root root 0 Oct 11 18:11 dsp
-r--r--r--  1 root root 0 Oct 11 18:11 etrace
-r--r--r--  1 root root 0 Oct 11 18:11 exception
-r--r--r--  1 root root 0 Oct 11 18:11 fw_version
-r--r--r--  1 root root 0 Oct 11 18:11 hda
-r--r--r--  1 root root 0 Oct 11 18:11 inbox
-r--r--r--  1 root root 0 Oct 11 18:11 outbox
-r--r--r--  1 root root 0 Oct 11 18:11 pp
-r--r--r--  1 root root 0 Oct 11 18:11 regs
-r--r--r--  1 root root 0 Oct 11 18:11 stream
plbossart commented 4 years ago

@gobenji it's always interesting to see error reports, even if they are classified as 'normal' later. We appreciate the time you spent and information provided.

If this happens with the legacy driver as well, it could very well be some ramp applied in the amplifier. I would test with a constant amplitude sine wave and see what the envelope looks like. If we see a ramp done at that level, then maybe we need to disable volume ramps in the SOF code, that'd be an interesting behavior to provide to users. @singalsu FYI.

singalsu commented 4 years ago

The ramp can be disabled in topology per PGA instance by setting the token SOF_TKN_VOLUME_RAMP_STEP_MS to zero. Though that would disable the ramp from all volume transitions too. I wonder if a minor ABI version bump would allow to add token for stream start unmute ramp enable/disable or a separata length token for it (zero for disable).

plbossart commented 4 years ago

@singalsu if the firmware does any sort of volume changes then I think the firmware needs to apply the relevant ramps. Disabling ramps during firmware-controlled volume changes isn't something the amps or codec can compensate for.

It's more when the volume is 0dB that we should consider disabling ramps. The firmware does nothing and hands-over the start/stop ramp management to the external device.

Am I making any sense or do I need another coffee :-)?

singalsu commented 4 years ago

@plbossart Yes, makes sense. I think pulseaudio tries to use FW volume controls when available vs. using internal stream gain so the scenario of only 0 dB gain in use is not something to assume for playback. What do you think about adding token to separately control the stream start unmute ramp if know that the playback codec does the same thing (now tied to volume adjust ramp setting)?

plbossart commented 4 years ago

I think that would be a good addition @singalsu. In general everything that an external chip might do should be exposed with a 'disable' control. Now we also want to be careful with the logic, in ALSA controls something is on or off, we don't do disable=1, that should be enable=0.

juimonen commented 4 years ago

Hi, I get this also with my x1. You can get it in ubuntu just by hitting the backspace in terminal to get the "ping" notification. It happens only when the DSP goes to D3, you can see it in dmesg. If you hit the ping again before D3, there isn't any slow ramping. So this is related to dsp waking up, and I guess then the codec itself making some extra ramps...

gobenji commented 4 years ago

If this happens with the legacy driver as well, it could very well be some ramp applied in the amplifier. I would test with a constant amplitude sine wave and see what the envelope looks like. If we see a ramp done at that level, then maybe we need to disable volume ramps in the SOF code, that'd be an interesting behavior to provide to users. @singalsu FYI.

I've tested with a 1s 440HZ sine wave sample: sine With the Thinkpad X1 line out, ~62-76ms of the sample is clipped (at the beginning I guess..), then there is a ~12ms ramp up. This is similar when using the legacy driver or the sof driver. In that screenshot it looks like the beginning of the sof driver sample (#3) is not aligned correctly; in fact it's aligned according to the end of the sample. For comparison, I repeated the same test with the line out of the Thinkpad Thunderbolt 3 dock which hosts a usb sound card (USB id 17ef:3083). With that device, ~17ms of the sample is clipped and there is only minimal ramp up. With the X1 line out, when playing the same sample a second time in close succession, the duration was as expected (1s) - nothing was clipped - but there was still a ramp up (~19ms this time). In the case of the usb adapter, the behavior was the same when playing a second sample in close succession; 17ms was still clipped. audacity project with recordings

In summary, each device has different quirks... The main takeaway in this context is that using sof doesn't seem to make a difference for this issue.

gobenji commented 4 years ago

Hi, I get this also with my x1. You can get it in ubuntu just by hitting the backspace in terminal to get the "ping" notification. It happens only when the DSP goes to D3, you can see it in dmesg. If you hit the ping again before D3, there isn't any slow ramping. So this is related to dsp waking up, and I guess then the codec itself making some extra ramps...

How do you see the state of the dsp in dmesg?

I tried to disable runtime PM for the device but it did not avoid the step up.

echo on > /sys/bus/pci/devices/0000:00:1f.3/power/control

I can see that the device remains "active" according to runtime_status, however the beginning of a sample is still noticeably clipped if I wait more than ~1s between playing two samples.

As mentioned in a previous comment, a workaround for this problem when using pulseaudio is to avoid using module-suspend-on-idle.

juimonen commented 4 years ago

@gobenji

I have this in cat /etc/modprobe.d/sof-dyndbg.conf options snd_sof_intel_byt dyndbg=+p options snd_sof_intel_bdw dyndbg=+p options snd_sof_intel_ipc dyndbg=+p options snd_sof_intel_hda_common dyndbg=+p options snd_sof_intel_hda dyndbg=+p options snd_sof dyndbg=+p options snd_sof_pci dyndbg=+p options snd_sof_acpi dyndbg=+p options snd_sof_of dyndbg=+p options snd_sof_nocodec dyndbg=+p options soundwire_bus dyndbg=+p options soundwire_generic_allocation dyndbg=+p options soundwire_cadence dyndbg=+p options soundwire_intel_init dyndbg=+p options soundwire_intel dyndbg=+p

probably too much lines there, but anyway you should see sof logs in dmesg. At least with me it says DSP goes to D3 and then I get these low volumes when waking up. I mean it is the driver reporting, so I can't be totally sure about if DSP is really in suspend, but let's assume so (so eventually this means that codec goes to suspend).

So I think it doesn't matter who makes the codec suspend, it can be pulseaudio (suspend-on-idle disabled -> alsa devices closed -> dsp&codec go to suspend after some delay), or I think there's some delay in the driver for PM to kick in also (I think usual amount is 2s). So depending on the driver PM delay, you could probably reproduce/not reproduce this with aplay also.

juimonen commented 4 years ago

@gobenji I think this is annoying issue, we should really ask the codec vendor is this wake up ramp necessary and can we do something about it. Probably it is there because of some clicks/pops when powering the amps, but maybe it could be shorter...

plbossart commented 4 years ago

I tried to disable runtime PM for the device but it did not avoid the step up.

echo on > /sys/bus/pci/devices/0000:00:1f.3/power/control

this will only change the PCI device status, and we know the ramp is applied by the external codec. I would try to go one level deeper:

echo on > /sys/bus/pci/devices/0000:00:1f.3/hdaudioC0D0/power/control

I can see that the device remains "active" according to runtime_status, however the beginning of a sample is still noticeably clipped if I wait more than ~1s between playing two samples.

As mentioned in a previous comment, a workaround for this problem when using pulseaudio is to avoid using module-suspend-on-idle.

Indeed that will keep zeroes flowing into the amp. That's a bit overkill but that's classic. We use similar solutions for keep HDMI receivers awake and remove ramps on startup.

gobenji commented 4 years ago

After enabling the dynamic debug messages, I also see messages like the following around the time I'm playing samples:

sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 1
sof-audio-pci 0000:00:1f.3: Current DSP power state: D0I0
...
sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power 0
sof-audio-pci 0000:00:1f.3: Current DSP power state: D3

When doing

echo on > /sys/bus/pci/devices/0000:00:1f.3/power/control

like before, I see that the device stays in D0I0, but still, if I wait long enough (~ >2s) in between samples, there's the ramp up like mentioned earlier.

Interestingly, when leaving the power control to auto, I can get the following sequence of events:

power state D0I0
play sound -> step up
wait a little bit but not so long that the device goes to D3
play sound -> step up
power state D3

So the step up is not directly related to the power state shown by these messages I think.

I tried to disable runtime PM for the device but it did not avoid the step up.

echo on > /sys/bus/pci/devices/0000:00:1f.3/power/control

this will only change the PCI device status, and we know the ramp is applied by the external codec. I would try to go one level deeper:

echo on > /sys/bus/pci/devices/0000:00:1f.3/hdaudioC0D0/power/control

@plbossart Correct! On my machine it's

echo on > /sys/bus/pci/devices/0000:00:1f.3/ehdaudio0D0/power/control

and this indeed prevents the issue.

I had to fiddle quite a bit to come up with a functional udev rule to apply this setting automatically. The following rule seemed straightforward

ACTION=="add", SUBSYSTEM=="hdaudio", ATTR{chip_name}=="ALC285", TEST=="power/control", ATTR{power/control}="on"

however it was not effective. udev logs that the write completes successfully however it seems to be reset later on, not by udev.

ACTION=="add", SUBSYSTEM=="sound", \
        ATTRS{subsystem_vendor}=="0x17aa", ATTRS{subsystem_device}=="0x2292", \
        TEST=="../../../ehdaudio0D0/power/control", \
        ATTR{../../../ehdaudio0D0/power/control}="on"

This rule matches on /devices/pci0000:00/0000:00:1f.3/skl_hda_dsp_generic/sound/card0 which generates events later than the hdaudio device. It seems to do the job so far and I'm now using this workaround instead of changing the pulseaudio config.

plbossart commented 4 years ago 
ACTION=="add", SUBSYSTEM=="sound", \
        ATTRS{subsystem_vendor}=="0x17aa", ATTRS{subsystem_device}=="0x2292", \
        TEST=="../../../ehdaudio0D0/power/control", \
        ATTR{../../../ehdaudio0D0/power/control}="on"

This rule matches on /devices/pci0000:00/0000:00:1f.3/skl_hda_dsp_generic/sound/card0 which generates events later than the hdaudio device. It seems to do the job so far and I'm now using this workaround instead of changing the pulseaudio config.

Fascinating, I didn't think of using udev to alter the power management behavior. @kv2019i @ranj063 FYI.