usb headset causes "delay: estimated / actual" spam in dmesg

[Steve Magoun]

I sometimes have a USB headset plugged in to my computer. When the headset is plugged in, I get hundreds (thousands?) of messages like the following in dmesg and syslog:

[63467.527274] delay: estimated 384, actual 240
[63490.543473] delay: estimated 0, actual 240
[63490.543490] delay: estimated 528, actual 240
[63490.543853] delay: estimated 480, actual 240
[63493.545912] delay: estimated 96, actual 240
[63493.548295] delay: estimated 384, actual 240
[63494.546711] delay: estimated 0, actual 240
[63494.546728] delay: estimated 528, actual 240
[63500.551524] delay: estimated 0, actual 240
[63500.551544] delay: estimated 528, actual 240
[63500.551560] delay: estimated 528, actual 240

To reproduce:
1) Plug in a USB headset

Expected results:
No "delay: estimated" spam in the kernel log (dmesg/syslog/kern.log)

Actual results:
Hundreds of similar messages about estimated + actual delays in the kernel log.

Unplugging the USB headset makes the problem stop.

ProblemType: Bug
DistroRelease: Ubuntu 14.04
Package: linux-image-3.13.0-23-generic 3.13.0-23.45
ProcVersionSignature: Ubuntu 3.13.0-23.45-generic 3.13.8
Uname: Linux 3.13.0-23-generic x86_64
ApportVersion: 2.14.1-0ubuntu1
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC2: steve 2277 F.... pulseaudio
 /dev/snd/controlC1: steve 2277 F.... pulseaudio
 /dev/snd/controlC0: steve 2277 F.... pulseaudio
CurrentDesktop: Unity
Date: Wed Apr 9 11:11:23 2014
DistributionChannelDescriptor:
 # This is a distribution channel descriptor
 # For more information see http://wiki.ubuntu.com/DistributionChannelDescriptor
 canonical-oem-somerville-precise-amd64-20130203-1
EcryptfsInUse: Yes
HibernationDevice: RESUME=UUID=79084358-087f-4cee-a0be-e2f78361873f
InstallationDate: Installed on 2013-12-02 (127 days ago)
InstallationMedia: Ubuntu 12.04 "Precise" - Build amd64 LIVE Binary 20130203-13:50
MachineType: Dell Inc. XPS13 9333
ProcFB: 0 inteldrmfb
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.13.0-23-generic root=UUID=0b9db31c-747b-40ad-bbbd-13a9a29caece ro quiet splash vt.handoff=7
RelatedPackageVersions:
 linux-restricted-modules-3.13.0-23-generic N/A
 linux-backports-modules-3.13.0-23-generic N/A
 linux-firmware 1.127
SourcePackage: linux
UpgradeStatus: Upgraded to trusty on 2014-02-12 (55 days ago)
dmi.bios.date: 11/11/2013
dmi.bios.vendor: Dell Inc.
dmi.bios.version: A01
dmi.board.name: 0GFTRT
dmi.board.vendor: Dell Inc.
dmi.board.version: A00
dmi.chassis.type: 8
dmi.chassis.vendor: Dell Inc.
dmi.chassis.version: 0.1
dmi.modalias: dmi:bvnDellInc.:bvrA01:bd11/11/2013:svnDellInc.:pnXPS139333:pvr:rvnDellInc.:rn0GFTRT:rvrA00:cvnDellInc.:ct8:cvr0.1:
dmi.product.name: XPS13 9333
dmi.sys.vendor: Dell Inc.

[Brad Figg (brad-figg)]

This change was made by a bot.

[Joseph Salisbury (jsalisbury)]

Do you happen to know if this issue was introduced recently? Also, can you test the latest mainline kernel to see if it's already fixed upstream? It can be downloaded from:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.14-trusty/

[Tim Gardner (timg-tpi)]

This message appears to be coming from sound/usb/pcm.c: retire_playback_urb()
        /*
         * Report when delay estimate is off by more than 2ms.
         * The error should be lower than 2ms since the estimate relies
         * on two reads of a counter updated every ms.
         */
        if (abs(est_delay - subs->last_delay) * 1000 > runtime->rate * 2)
                snd_printk(KERN_DEBUG "delay: estimated %d, actual %d\n",
                        est_delay, subs->last_delay);

I think it is a totally useless message to repeat constantly and can be rate limited. Its also likely a function of your USB device firmware.

[Brad Figg (brad-figg)]

This bug is awaiting verification that the kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-trusty' to 'verification-done-trusty'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

[Steve Magoun (smagoun)]

The hundreds/thousands messages are not longer present with linux-image-3.13.0-26-generic, so marking this verification-done-trusty

Instead, we still get tens of messages like this:
May 14 11:25:24 aether kernel: [ 315.447988] retire_playback_urb: 829 callbacks suppressed
May 14 11:25:29 aether kernel: [ 320.458042] retire_playback_urb: 831 callbacks suppressed

There is an upstream patch for that issue; I'll file a separate bug.

[Launchpad Janitor (janitor)]

This bug was fixed in the package linux - 3.15.0-1.5

---------------
linux (3.15.0-1.5) utopic; urgency=low

  [ Tim Gardner ]

  * [Config] Add apm-mustang.dtb to kernel-image udeb
 -- Tim Gardner <email address hidden> Mon, 19 May 2014 14:47:42 -0700