[snd-usb-audio] frequent "delay: estimated xxx, actual yyy" messages

[snd-usb-audio] frequent "delay: estimated xxx, actual yyy" messages

[Guillaume Clement]

Hello,

I am using an USB soundcard (ID : 046d:0a24 : Logitech Speaker Lapdesk N550).

During playback, I have frequent messages like these :

delay: estimated 795, actual 662
delay: estimated 133, actual 0
delay: estimated 751, actual 662
delay: estimated 89, actual 0


When those messages appear, I am hearing some "cracks" from the soundcard.


I've tried to make some research on this, I only found some messages that hint 
about some interrupt problems. I'm not using any closed source driver and I 
can reproduce the issue with any computer running Linux.


On interesting thing to notice is that it happens only when the CPU is near 
idle. To workaround the problem, I can just do something like : 

nice -n 20 dd if=/dev/zero of=/dev/null bs=1k count=500G


This would keep my CPU busy and I have no more messages nor cracks.




This does not seem to be a recent regression since I've experienced this since 
I bought the lapdesk in december or so. I am still experiencing this issue 
with the latest rc (linux-3.4rc3 at the moment)

I tried using different .asoundrc setups, tried to install pulseaudio (usually 
I'm using bare alsa) and still experience the problem.


Below is some information that might help locating the problem. I can make 
some test if needed and even code if I have some information on where the 
problem might me located.






Note: those commands are typed during playback.

$ cat /proc/asound/N550/stream0 
Logitech, Inc. Logitech Speaker Lapdesk N550 at usb-0000:00:1d.0-2, full speed 
: USB Audio

Playback:
  Status: Running
    Interface = 1
    Altset = 1
    URBs = 2 [ 20 20 ]
    Packet Size = 200
    Momentary freq = 44100 Hz (0x2c.199a)
  Interface 1
    Altset 1
    Format: S16_LE
    Channels: 2
    Endpoint: 1 OUT (ADAPTIVE)
    Rates: 44100, 48000

$ cat /proc/asound/N550/pcm0p/info 
card: 0
device: 0
subdevice: 0
stream: PLAYBACK
id: USB Audio
name: USB Audio
subname: subdevice #0
class: 0
subclass: 0
subdevices_count: 1
subdevices_avail: 0

$ cat /proc/asound/N550/pcm0p/sub0/hw_params 
access: RW_INTERLEAVED
format: S16_LE
subformat: STD
channels: 2
rate: 44100 (44100/1)
period_size: 5513
buffer_size: 22050


$ cat /proc/asound/N550/pcm0p/sub0/info 
card: 0
device: 0
subdevice: 0
stream: PLAYBACK
id: USB Audio
name: USB Audio
subname: subdevice #0
class: 0
subclass: 0
subdevices_count: 1
subdevices_avail: 0


$ cat /proc/asound/N550/pcm0p/sub0/status 
state: RUNNING
owner_pid   : 1210
trigger_time: 3264.436419606
tstamp      : 3302.883104696
delay       : 20904
avail       : 2646
avail_max   : 21026
-----
hw_ptr      : 1695160
appl_ptr    : 1714564


$ cat /proc/asound/N550/pcm0p/sub0/sw_params 
tstamp_mode: NONE
period_step: 1
avail_min: 5513
start_threshold: 16537
stop_threshold: 22050
silence_threshold: 0
silence_size: 0
boundary: 1445068800

Re: [snd-usb-audio] frequent "delay: estimated xxx, actual yyy" messages

[Pierre-Louis Bossart]

On 4/21/2012 5:22 AM, Guillaume Clement wrote:
> Hello,
>
> I am using an USB soundcard (ID : 046d:0a24 : Logitech Speaker Lapdesk N550).
>
> During playback, I have frequent messages like these :
>
> delay: estimated 795, actual 662
> delay: estimated 133, actual 0
> delay: estimated 751, actual 662
> delay: estimated 89, actual 0
>
>
> When those messages appear, I am hearing some "cracks" from the soundcard.
>
>
> I've tried to make some research on this, I only found some messages that hint
> about some interrupt problems. I'm not using any closed source driver and I
> can reproduce the issue with any computer running Linux.
>
>
> On interesting thing to notice is that it happens only when the CPU is near
> idle. To workaround the problem, I can just do something like :
>
> nice -n 20 dd if=/dev/zero of=/dev/null bs=1k count=500G
>
>
> This would keep my CPU busy and I have no more messages nor cracks.
I'm the one who introduced this warning when I added support for a 
better delay estimate based on the frame counter instead of bytes 
submitted (back in September 2011). When writing new data the estimate 
using the frame counter and the byte count should be identical, but this 
message shows something goes wrong.
Somehow I don't understand how a more precise delay would cause such 
errors. The delay is only important for pulseaudio, it shouldn't affect 
plain vanilla alsa. You could try and reverse the patch to see if this 
improves anything? If not, you have another problem in your setup...
-Pierre

Re: [snd-usb-audio] frequent "delay: estimated xxx, actual yyy" messages

[Guillaume Clement]

On 4/23/2012 12:43:11 Pierre-Louis Bossart wrote :
> I'm the one who introduced this warning when I added support for a
> better delay estimate based on the frame counter instead of bytes
> submitted (back in September 2011). When writing new data the estimate
> using the frame counter and the byte count should be identical, but this
> message shows something goes wrong.
> Somehow I don't understand how a more precise delay would cause such
> errors. The delay is only important for pulseaudio, it shouldn't affect
> plain vanilla alsa. 

Could the delay not be the cause, but a side effect ? Unfortunately I don't 
know anything about the internals here.


What I do know is that there is a lapdesk of another series by the same 
vendor, that has exactly the same behaviour. I do know those two lapdesks work 
fine under other OSes. 

The problem can also be reproduced under various Linux distributions.



Do you have any idea why keeping my CPU busy removes the problem ? That could 
be a hint as to where the real problem lies. 

> You could try and reverse the patch to see if this
> improves anything? If not, you have another problem in your setup...

By reversing the patch, I made the problem worse. 

Is there a way to get more debugging information ? I already tried to get some 
output with xrun_debug as pointed in the wiki, but things don't look weird to 
me (I only get logs about hwptr_update and period_update)

Re: [snd-usb-audio] frequent "delay: estimated xxx, actual yyy" messages

[Clemens Ladisch]

Guillaume Clement wrote:
> Could the delay not be the cause, but a side effect ?

Yes, that's probable.  It might be possible that some interrupt got
delayed too much, or that packets were completed in wrong order.

> Do you have any idea why keeping my CPU busy removes the problem ?

I'd guess that an idle CPU needs a longer time to wake up.
What CPU and what CPU frequency governor are you using?


Regards,
Clemens

Re: [snd-usb-audio] frequent "delay: estimated xxx, actual yyy" messages

[Guillaume Clement]

Le mardi 24 avril 2012 15:59:15 vous avez écrit :
> Guillaume Clement wrote:
> > Could the delay not be the cause, but a side effect ?
> 
> Yes, that's probable.  It might be possible that some interrupt got
> delayed too much, or that packets were completed in wrong order.

I've noticed that using the touchpad triggers the issues, even in console mode 
when I don't start X. Some other factors seem to trigger it, like some 
graphical operations or hard disk usage (but again, only when the CPU is low 
usage).

I forgot to mention that my integrated soundcard does not have this issue. I 
deactivated the integrated soundcard  in the BIOS and that didn't help.

> 
> > Do you have any idea why keeping my CPU busy removes the problem ?
> 
> I'd guess that an idle CPU needs a longer time to wake up.
> What CPU and what CPU frequency governor are you using?


On my laptop, I've got an Atom Z520 @ 1.33GHz. I was using the ondemand 
governor. I switched to performance, with no effect.

I tried to disable as many modules as possible (even my graphics card, wifi, 
touchscreen) with no luck so far.

I tried again on several of my other computers and I could not reproduce the 
problem, even on another netbook. It's quite weird becaues I thought I 
reproduced it with several hardware back in December, but I guess I was 
mistaken, sorry about that.