Problems with usb soundcard in kernels > 3.3

Problems with usb soundcard in kernels > 3.3

[Bogdan Veringioiu]

Hello all,

After spending a couple of days searching the web for a solution, I 
write here to ask for help.
I am using an usb soundcard (Phoenix Audio Technologies Phnx MT201solo) 
on Debian Wheezy, and started to experience problems when using kernels 
 > 3.3.
The issue I am experiencing is a ~4 seconds delay in playing sound. I am 
reproducing the problem using aplay. The sound play is being delayed by 
more or less 4 seconds from the moment the file is sent to the card. I 
have tested with kernels 3.2 and 3.3, which work properly. I have 
noticed this delay/wait when using kernels 3.15, 3.16. Below are some 
details:

WORKING PROPERLY
# uname -rv
3.2.0-4-686-pae #1 SMP Debian 3.2.63-2
# dpkg -l | grep alsa
ii  alsa-base                            1.0.25+3~deb7u1 
all          ALSA driver configuration files
ii  alsa-utils                           1.0.25-4 
i386         Utilities for configuring and using ALSA
# dmesg
....
usb 3-1: New USB device found, idVendor=1de7, idProduct=0011
usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 3-1: Product: Phnx MT201solo
usb 3-1: Manufacturer: Phoenix Audio Technologies
....

# time aplay /usr/share/sounds/alsa/Rear_Left.wav
Playing WAVE '/usr/share/sounds/alsa/Rear_Left.wav' : Signed 16 bit 
Little Endian, Rate 48000 Hz, Mono

real	0m2.498s <--- this is OK
user	0m0.032s
sys	0m0.024s

DELAY INTRODUCED
# uname -rv
3.16-0.bpo.2-686-pae #1 SMP Debian 3.16.3-2~bpo70+1 (2014-09-21)
# dpkg -l | grep alsa
ii  alsa-base                          1.0.25+3~deb7u1               all 
          ALSA driver configuration files
ii  alsa-utils                         1.0.25-4 
i386         Utilities for configuring and using ALSA
# dmesg
....
usb 2-1: New USB device found, idVendor=1de7, idProduct=0011
usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 2-1: Product: Phnx MT201solo
usb 2-1: Manufacturer: Phoenix Audio Technologies
....
# time aplay /usr/share/sounds/alsa/Rear_Left.wav
Playing WAVE '/usr/share/sounds/alsa/Rear_Left.wav' : Signed 16 bit 
Little Endian, Rate 48000 Hz, Mono

real	0m6.387s <----4 more seconds delay, NOK
user	0m0.016s
sys	0m0.024s

I have done a strace, see below where the 4 seconds are lost, maybe it 
helps:

open("/dev/snd/pcmC0D0p", O_RDWR|O_NONBLOCK|O_CLOEXEC) = 4
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
ioctl(4, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbf823f4c) = 0
close(3)                                = 0
ioctl(4, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbf823dac) = 0
fcntl64(4, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
ioctl(4, AGPIOC_INFO, 0xbf823d14)       = 0
clock_gettime(CLOCK_MONOTONIC, {5839, 700325532}) = 0
ioctl(4, AGPIOC_SETUP, 0xbf823d1c)      = 0
mmap2(NULL, 4096, PROT_READ, MAP_SHARED, 4, 0x80000) = 0xb72db000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0x81000) = 0xb72da000
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4110, 0xbf823ee0)        = 0
ioctl(4, 0xc25c4111, 0xbf823ee0)        = 0
ioctl(4, 0xc0684113, 0xbf823d94)        = 0
ioctl(4, 0x80104132, 0xbf823cd0)        = 0
ioctl(4, 0x80104132, 0xbf823cd0)        = 0
mmap2(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED, 4, 0) = 0xb7293000
----> ioctl(4, 0x4140, 0xb7718ff4)            = 0 <---- !!! Here is 
where the 4 seconds are lost !!!
ioctl(4, 0xc0684113, 0xbf823e60)        = 0
ioctl(4, 0x4142, 0xb7709c16)            = 0
ioctl(4, AGPIOC_INFO, 0xbf8241a0)       = 0
shmget(0x56a4d6, 131072, IPC_CREAT|0660) = 163841
shmctl(163841, IPC_64|IPC_STAT, 0xbf82415c) = 0
shmctl(163841, IPC_64|IPC_SET, 0xbf82415c) = 0
....

I think this is a problem in the snd-usb-audio module introduced in 
kernels > 3.3.
Can anyone help me with this issue?

Thanks,
Bogdan

Re: Problems with usb soundcard in kernels > 3.3

[Clemens Ladisch]

Bogdan Veringioiu wrote:
> The issue I am experiencing is a ~4 seconds delay in playing sound.
> I am reproducing the problem using aplay. The sound play is being
> delayed by more or less 4 seconds from the moment the file is sent
> to the card. I have tested with kernels 3.2 and 3.3, which work
> properly. I have noticed this delay/wait when using kernels 3.15,
> 3.16.

Any messages in the system log when this happens?


Regards,
Clemens

Re: Problems with usb soundcard in kernels > 3.3

[Bogdan Veringioiu]

Hi,

thanks for your availability.
There is one message that appears in syslog, but it is always displayed when I test with aplay, unregarding the kernel version. It shows both with the working kernel (3.2) and with the problematic one (3.16).

--> with kernel 3.2.0-4-686-pae
/var/log/syslog
...
kernel: [ 2829.369380] 2:1:1: cannot get freq at ep 0x2
...

--> with kernel 3.16-0.bpo.2-686-pae
/var/log/syslog
...
kernel: [  199.353227] usb 2-1: 1:1: cannot get freq at ep 0x2
...

Bogdan

On 11/11/2014 02:32 PM, Clemens Ladisch wrote:
> Bogdan Veringioiu wrote:
> > The issue I am experiencing is a ~4 seconds delay in playing sound.
> > I am reproducing the problem using aplay. The sound play is being
> > delayed by more or less 4 seconds from the moment the file is sent
> > to the card. I have tested with kernels 3.2 and 3.3, which work
> > properly. I have noticed this delay/wait when using kernels 3.15,
> > 3.16.
>
> Any messages in the system log when this happens?
>
>
> Regards,
> Clemens
>

-- 
Bogdan Veringioiu

Amano Parking Europe N.V.
Uersfeld 24
52072 Aachen, Germany

e-mail: bogdan.veringioiu@amano.eu
web: www.amano.eu

Re: Problems with usb soundcard in kernels > 3.3

[Bogdan Veringioiu]

Hi,

any idea on how to further debug this issue?
Thanks,
Bogdan

On 11/11/2014 03:06 PM, Bogdan Veringioiu wrote:
> Hi,
>
> thanks for your availability.
> There is one message that appears in syslog, but it is always displayed
> when I test with aplay, unregarding the kernel version. It shows both
> with the working kernel (3.2) and with the problematic one (3.16).
>
> --> with kernel 3.2.0-4-686-pae
> /var/log/syslog
> ...
> kernel: [ 2829.369380] 2:1:1: cannot get freq at ep 0x2
> ...
>
> --> with kernel 3.16-0.bpo.2-686-pae
> /var/log/syslog
> ...
> kernel: [  199.353227] usb 2-1: 1:1: cannot get freq at ep 0x2
> ...
>
> Bogdan
>
> On 11/11/2014 02:32 PM, Clemens Ladisch wrote:
>> Bogdan Veringioiu wrote:
>> > The issue I am experiencing is a ~4 seconds delay in playing sound.
>> > I am reproducing the problem using aplay. The sound play is being
>> > delayed by more or less 4 seconds from the moment the file is sent
>> > to the card. I have tested with kernels 3.2 and 3.3, which work
>> > properly. I have noticed this delay/wait when using kernels 3.15,
>> > 3.16.
>>
>> Any messages in the system log when this happens?
>>
>>
>> Regards,
>> Clemens
>>
>

Re: Problems with usb soundcard in kernels > 3.3

[Clemens Ladisch]

Bogdan Veringioiu wrote:
> There is one message that appears in syslog, but it is always
> displayed when I test with aplay, unregarding the kernel version.
>
> --> with kernel 3.2.0-4-686-pae
> kernel: [ 2829.369380] 2:1:1: cannot get freq at ep 0x2
>
> --> with kernel 3.16-0.bpo.2-686-pae
> kernel: [  199.353227] usb 2-1: 1:1: cannot get freq at ep 0x2

This indicates a bug in the device's firmware.

The timeout for control messages was increased from 100 ms to 1000 ms
in kernel 3.3.


Regards,
Clemens

Re: Problems with usb soundcard in kernels > 3.3

[Bogdan Veringioiu]

Thank you very much.
Your insight was helpful.
Indeed the wait is caused by the timeout in control messages.
The timeout is now (kernels 3.15, 3.16) set according with the global 
timeout defined in usb.h (5 seconds):

-->linux/usb.h
#define USB_CTRL_GET_TIMEOUT  5000
#define USB_CTRL_SET_TIMEOUT  5000

-->sound/usb/helper.c
   if (requesttype & USB_DIR_IN)
     timeout = USB_CTRL_GET_TIMEOUT;
   else
     timeout = USB_CTRL_SET_TIMEOUT;
   err = usb_control_msg(dev, pipe, request, requesttype,
             value, index, buf, size, timeout);

so, this explains the 5 seconds delay.

In kernel 3.2, the timeout in helper.c was 1 second (hardcoded):

-->sound/usb/helper.c
   err = usb_control_msg(dev, pipe, request, requesttype,
             value, index, buf, size, 1000);

this explains the faster response in older kernels.

The timeout is received when reading the sample rate from the device,
and then the error message "cannot get freq..." is displayed in syslog.

I have modified the timeout (reverted to 1 second) as a test in the new 
kernel and recompiled the module, the result was as expected, faster 
response.

I will contact the manufacturer to ask about this problem.

Thank you again.
Bogdan



On 11/12/2014 03:36 PM, Clemens Ladisch wrote:
> Bogdan Veringioiu wrote:
> > There is one message that appears in syslog, but it is always
> > displayed when I test with aplay, unregarding the kernel version.
> >
> > --> with kernel 3.2.0-4-686-pae
> > kernel: [ 2829.369380] 2:1:1: cannot get freq at ep 0x2
> >
> > --> with kernel 3.16-0.bpo.2-686-pae
> > kernel: [  199.353227] usb 2-1: 1:1: cannot get freq at ep 0x2
>
> This indicates a bug in the device's firmware.
>
> The timeout for control messages was increased from 100 ms to 1000 ms
> in kernel 3.3.
>
>
> Regards,
> Clemens
>