Re: [alsa-devel] Adjust volume may cause audio playback corruption
2012/5/12 cee1 fykcee1@gmail.com:
Hi all,
We're using PA on our product, and sometimes audio playback may corrupt after adjusting volume.
We found a way to (relatively) easily reproduce the problem:
- Play sample.mp3 through totem in repeat mode.
- In gnome-volume-control, Hardware tap, repeat to shift between "Off
profile" and "Analog Stereo Duplex profile".
When the problem happens, the corruption continues until I:
- Do one more shift between "Off profile" and "Analog Stereo Duplex profile".
- Close totem (close all PA playback clients).
- Adjust volume.
When the problem happens, open another PA client doing audio playback, is also corrupt.
Some additional information:
- Output of alsa-info.sh on our product:
http://dev.lemote.com/files/upload/software/PA-apc/alsa-info-lemote
- PA daemon log:
http://dev.lemote.com/files/upload/software/PA-apc/pulseaudio.log
- The corrupted sound:
http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg
- The sample mp3: http://dev.lemote.com/files/upload/software/PA-apc/sample.mp3
When the problem happens today, I notice: 1) PA complains "alsa-source.c: Overrun!". I doesn't run any recording application then. Curious. 2) Playback becomes good automatically when play sample.mp3 again(note totem is in repeat playing mode). It says sink becomes idle(I didn't touch totem, so totem should keep playing back).
Any idea?
Following is PA daemon log: I: [alsa-source] ratelimit.c: 1226 events suppressed I: [alsa-source] alsa-source.c: Overrun! I: [alsa-source] alsa-source.c: Increasing minimal latency to 1.00 ms D: [alsa-source] alsa-source.c: latency set to 20.00ms D: [alsa-source] alsa-source.c: hwbuf_unused=62008 D: [alsa-source] alsa-source.c: setting avail_min=442 I: [alsa-source] alsa-source.c: Overrun! I: [alsa-source] alsa-source.c: Increasing minimal latency to 2.00 ms D: [alsa-source] alsa-source.c: latency set to 20.00ms D: [alsa-source] alsa-source.c: hwbuf_unused=62008 D: [alsa-source] alsa-source.c: setting avail_min=442 I: [alsa-source] alsa-source.c: Overrun! I: [alsa-source] alsa-source.c: Increasing minimal latency to 4.00 ms D: [alsa-source] alsa-source.c: latency set to 20.00ms D: [alsa-source] alsa-source.c: hwbuf_unused=62008 D: [alsa-source] alsa-source.c: setting avail_min=442 I: [alsa-source] alsa-source.c: Overrun! I: [alsa-source] alsa-source.c: Increasing minimal latency to 8.00 ms D: [alsa-source] alsa-source.c: latency set to 20.00ms D: [alsa-source] alsa-source.c: hwbuf_unused=62008 D: [alsa-source] alsa-source.c: setting avail_min=442 I: [alsa-source] alsa-source.c: Overrun! I: [alsa-source] alsa-source.c: Increasing minimal latency to 16.00 ms D: [alsa-source] alsa-source.c: latency set to 20.00ms D: [alsa-source] alsa-source.c: hwbuf_unused=62008 D: [alsa-source] alsa-source.c: setting avail_min=442 I: [alsa-source] alsa-source.c: Overrun! I: [alsa-source] alsa-source.c: Increasing minimal latency to 26.00 ms D: [alsa-source] alsa-source.c: latency set to 26.00ms D: [alsa-source] alsa-source.c: hwbuf_unused=60952 D: [alsa-source] alsa-source.c: setting avail_min=706 D: [alsa-sink] protocol-native.c: Underrun on 'Playback Stream', 0 bytes in queue. D: [alsa-sink] protocol-native.c: Requesting rewind due to rewrite. D: [alsa-sink] sink-input.c: Requesting rewind due to corking D: [alsa-sink] alsa-sink.c: Requested to rewind 16208 bytes. D: [alsa-sink] alsa-sink.c: Limited to 15096 bytes. D: [alsa-sink] alsa-sink.c: before: 3774 D: [alsa-sink] alsa-sink.c: after: 3642 D: [alsa-sink] alsa-sink.c: Rewound 14568 bytes. D: [alsa-sink] sink.c: Processing rewind... D: [alsa-sink] sink.c: latency = 4156 D: [alsa-sink] sink-input.c: Have to rewind 14568 bytes on render memblockq. D: [alsa-sink] sink-input.c: Have to rewind 29136 bytes on implementor. D: [alsa-sink] source.c: Processing rewind... D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes idle, timeout in 5 seconds. D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun. D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun. D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun. D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun. D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun. D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_14.2.analog-stereo is 0x0004, suspending I: [alsa-sink] alsa-sink.c: Device suspended... I: [pulseaudio] alsa-sink.c: Updating rate for device front:0, new rate is 44100 I: [pulseaudio] sink.c: Changed sampling rate successfully D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun. D: [alsa-sink] sink-input.c: Requesting rewind due to uncorking D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_14.2.analog-stereo is 0x0000, resuming I: [alsa-sink] alsa-sink.c: Trying resume... I: [alsa-sink] alsa-util.c: Trying to disable ALSA period wakeups, using timers only D: [alsa-sink] alsa-util.c: Maximum hw buffer size is 371 ms D: [alsa-sink] alsa-util.c: Set buffer size first (to 16384 samples), period size second (to 8192 samples). I: [alsa-sink] alsa-util.c: ALSA period wakeups disabled D: [alsa-sink] alsa-sink.c: Latency set to 90.00ms D: [alsa-sink] alsa-sink.c: hwbuf_unused=49660 D: [alsa-sink] alsa-sink.c: setting avail_min=15503 I: [alsa-sink] alsa-sink.c: Time scheduling watermark is 20.00ms I: [alsa-sink] alsa-sink.c: Resumed successfully... D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. I: [alsa-sink] alsa-sink.c: Starting playback. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_14.2.analog-stereo becomes busy. D: [pulseaudio] module-udev-detect.c: /dev/snd/controlC0 is accessible: yes D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half. D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by half.
We've tried PA 1.0-0ubuntu3, 1.1-0ubuntu15 and 2.0, the problem continues.
The problem can also be reproduced on an AMD turion 64 x2 board with ubuntu 10.10 and ubuntu 12.04:
- Output of alsa-info:
ubuntu 10.10(32bit) http://dev.lemote.com/files/upload/software/PA-apc/alsa-info-ubuntu-10.10 ubuntu 12.04(32bit) http://dev.lemote.com/files/upload/software/PA-apc/alsa-info-ubuntu-12.04
Note:
- The AMD turion 64 x2 board uses the same chipset as our product.
- gnome-volume-control is removed in ubuntu 12.04, thus we compiled
it: http://dev.lemote.com/files/upload/software/PA-apc/gnome-volume-control
2012/5/17 cee1 fykcee1@gmail.com:
2012/5/12 cee1 fykcee1@gmail.com:
Hi all,
We're using PA on our product, and sometimes audio playback may corrupt after adjusting volume.
We found a way to (relatively) easily reproduce the problem:
- Play sample.mp3 through totem in repeat mode.
- In gnome-volume-control, Hardware tap, repeat to shift between "Off
profile" and "Analog Stereo Duplex profile".
When the problem happens, the corruption continues until I:
- Do one more shift between "Off profile" and "Analog Stereo Duplex profile".
- Close totem (close all PA playback clients).
- Adjust volume.
When the problem happens, open another PA client doing audio playback, is also corrupt.
Some additional information:
- Output of alsa-info.sh on our product:
http://dev.lemote.com/files/upload/software/PA-apc/alsa-info-lemote
- PA daemon log:
http://dev.lemote.com/files/upload/software/PA-apc/pulseaudio.log
- The corrupted sound:
http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg
- The sample mp3: http://dev.lemote.com/files/upload/software/PA-apc/sample.mp3
When the problem happens today, I notice:
- PA complains "alsa-source.c: Overrun!". I doesn't run any recording
application then. Curious. 2) Playback becomes good automatically when play sample.mp3 again(note totem is in repeat playing mode). It says sink becomes idle(I didn't touch totem, so totem should keep playing back).
Update:
We've found a way the can reproduce the problem more quickly on our product: 1. do audio playback 2. alsamixer, select 'Master', press 'm' and hold for a while.
Then release 'm', playback corrupts(sounds similar to http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg). I notice the following in PA daemon log: ( 439.779| 55.236) D: [alsa-sink][modules/alsa/alsa-sink.c:1261 sink_get_volume_cb()] Read hardware volume: 0: 78% 1: 78% ([0x31a4e488]) ( 439.780| 0.000) D: [alsa-sink][modules/alsa/alsa-sink.c:1266 sink_get_volume_cb()] in dB: 0: -6.40 dB 1: -6.40 dB ([0x31a4e488]) ( 439.781| 0.001) I: [pulseaudio][modules/module-device-restore.c:723 subscribe_callback()] Storing volume/mute for device+port sink:alsa_output.pci-0000_00_14.2.analog-stereo:analog-output. ([0x7f891270]) ( 439.782| 0.001) D: [alsa-sink][modules/alsa/alsa-sink.c:1607 process_rewind()] Requested to rewind 65536 bytes. ([0x31a4e9d8]) ( 439.782| 0.000) D: [alsa-sink][modules/alsa/alsa-sink.c:1630 process_rewind()] Limited to 11248 bytes. ([0x31a4e9d8]) ( 439.783| 0.000) D: [alsa-sink][modules/alsa/alsa-sink.c:1633 process_rewind()] before: 2812 ([0x31a4e9d8]) ( 439.783| 0.000) D: [alsa-sink][modules/alsa/alsa-sink.c:1641 process_rewind()] after: 2812 ([0x31a4e9d8]) ( 439.783| 0.000) D: [alsa-sink][modules/alsa/alsa-sink.c:1649 process_rewind()] Rewound 11248 bytes. ([0x31a4e9d8]) ( 439.783| 0.000) D: [alsa-sink][pulsecore/sink.c:935 pa_sink_process_rewind()] Processing rewind... ([0x31a4e998]) ( 439.783| 0.000) D: [alsa-sink][pulsecore/sink.c:3617 pa_sink_volume_change_rewind()] latency = 632 ([0x31a4e928]) ( 439.784| 0.000) D: [alsa-sink][pulsecore/sink-input.c:984 pa_sink_input_process_rewind()] Have to rewind 11248 bytes on render memblockq. ([0x31a4e940]) ( 439.784| 0.000) D: [alsa-sink][pulsecore/source.c:864 pa_source_process_rewind()] Processing rewind... ([0x31a4e958])
I guess it is 'rewind' that cause the problem? What does rewind do? Why we need rewind here?
BTW, PA has module-device-restore and module-stream-restore, dose that means we don't need alsa-restore.service/store stuffs? What is the difference between device-restore and stream-restore?
---- Regards, cee1
cee1 wrote:
We've found a way the can reproduce the problem more quickly on our product:
- do audio playback
- alsamixer, select 'Master', press 'm' and hold for a while.
Then release 'm', playback corrupts(sounds similar to http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg).
Is the output supposed to be playing or muted at this time?
This appears to be a problem with PA's volume handling. It might be caused by incorrect dB volume information of the HDA codec, or by a bug in PA.
What does rewind do? Why we need rewind here?
It allows to rewrite already written parts of the audio buffer; it's used to apply the new volume to samples that have not yet been actually played.
Regards, Clemens
在 2012年5月18日星期五，Clemens Ladisch 写道：
cee1 wrote:
We've found a way the can reproduce the problem more quickly on our
product:
- do audio playback
- alsamixer, select 'Master', press 'm' and hold for a while.
Then release 'm', playback corrupts(sounds similar to http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg).
Is the output supposed to be playing or muted at this time?
Playing
This appears to be a problem with PA's volume handling. It might be caused by incorrect dB volume information of the HDA codec, or by a bug in PA.
What does rewind do? Why we need rewind here?
It allows to rewrite already written parts of the audio buffer; it's used to apply the new volume to samples that have not yet been actually played.
Regards, Clemens
2012/5/18 cee1 fykcee1@gmail.com:
在 2012年5月18日星期五，Clemens Ladisch 写道：
cee1 wrote:
We've found a way the can reproduce the problem more quickly on our product:
- do audio playback
- alsamixer, select 'Master', press 'm' and hold for a while.
Then release 'm', playback corrupts(sounds similar to http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg).
Is the output supposed to be playing or muted at this time?
Playing
Seems something to do with process_rewind(modules/alsa/alsa-sink.c), I tried commenting out snd_pcm_rewind block in process_rewind() and set out_frames=0 or out_frames=in_frames, the problem seems gone.
A bug in snd_pcm_rewind()/driver?
---- Regards, cee1
2012/5/18 cee1 fykcee1@gmail.com:
2012/5/18 cee1 fykcee1@gmail.com:
在 2012年5月18日星期五，Clemens Ladisch 写道：
cee1 wrote:
We've found a way the can reproduce the problem more quickly on our product:
- do audio playback
- alsamixer, select 'Master', press 'm' and hold for a while.
Then release 'm', playback corrupts(sounds similar to http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg).
I've written a small program[1] that will let PA mute/unmute repeatedly.
I find the problem is something to do with rewind_safeguard, If I adjust rewind_safeguard to eighth of the original value, it can also be easily reproduced through pa-mute-test.c on the AMD turion 64 x2 board in ubuntu 12.04: --- a/src/modules/alsa/alsa-sink.c +++ b/src/modules/alsa/alsa-sink.c @@ -86,8 +86,8 @@
#define VOLUME_ACCURACY (PA_VOLUME_NORM/100) /* don't require volume adjustments to be perfectly correct. do
-#define DEFAULT_REWIND_SAFEGUARD_BYTES (256U) /* 1.33ms @48kHz, we'll never rewind less than this */ -#define DEFAULT_REWIND_SAFEGUARD_USEC (1330) /* 1.33ms, depending on channels/rate/sample we may rewind more +#define DEFAULT_REWIND_SAFEGUARD_BYTES (32U) /* 1.33ms @48kHz, we'll never rewind less than this */ +#define DEFAULT_REWIND_SAFEGUARD_USEC (166) /* 1.33ms, depending on channels/rate/sample we may rewind more t
struct userdata { pa_core *core;
Should we calculate limit_nbytes considering tsched_watermark? e.g.(which works on our platform) @@ -1614,7 +1614,7 @@ static int process_rewind(struct userdata *u) { unused_nbytes = (size_t) unused * u->frame_size;
/* make sure rewind doesn't go too far, can cause issues with DMAs */ - unused_nbytes += u->rewind_safeguard; + unused_nbytes += u->tsched_watermark;
if (u->hwbuf_size > unused_nbytes) limit_nbytes = u->hwbuf_size - unused_nbytes;
---- [1]. See pa-mute-test.c in attachment, using build.sh to build it.
Regards, -- cee1
Hi,
2012/5/18 cee1 fykcee1@gmail.com:
2012/5/18 cee1 fykcee1@gmail.com:
在 2012年5月18日星期五，Clemens Ladisch 写道：
cee1 wrote:
We've found a way the can reproduce the problem more quickly on our product:
- do audio playback
- alsamixer, select 'Master', press 'm' and hold for a while.
Then release 'm', playback corrupts(sounds similar to http://dev.lemote.com/files/upload/software/PA-apc/corrupted_sound.ogg).
Is the output supposed to be playing or muted at this time?
Playing
Seems something to do with process_rewind(modules/alsa/alsa-sink.c), I tried commenting out snd_pcm_rewind block in process_rewind() and set out_frames=0 or out_frames=in_frames, the problem seems gone.
A bug in snd_pcm_rewind()/driver?
Some questions about rewind :-) 1. When rewind happens, it is possible to go into underrun, right? 2. The hardware doesn't know control->appl_ptr, it will go through a buffer size and then wrap back, go through the buffer again? 3. About substream->ops->pointer, in HDA, it was implemented by position buffer. Is it an atomic operation of update(by HDA controller) /read(by driver)? 4. [alsa-libs] snd_pcm_mmap_commit() -> snd_pcm_hw_mmap_commit(), which will forward pcm->appl.ptr(and wrap back if is bigger than pcm->boundary) and then pass the new appl.ptr to kernel through SNDRV_PCM_IOCTL_SYNC_PTR ioctl. In kernel side, it will assign pcm->appl.ptr to control->appl_ptr directly.
The question is in alsa-libs appl_ptr stays in [0, pcm->boundary), but in kernel side appl_ptr stays in [0, runtime->boundary), will it have problem if pcm->boundary != runtime->boundary? For example, sometimes kernel is 64bits but the userland is 32bits, then the width of 'long' in kernel will not be equal to width of 'long' in userland on some platform.
participants (2)
-
cee1 -
Clemens Ladisch