Bug 230434

Summary: [DWC OTG] USB sound card fails to record
Product: Base System Reporter: chris
Component: usbAssignee: Hans Petter Selasky <hselasky>
Status: Closed FIXED    
Severity: Affects Only Me CC: hselasky
Priority: ---    
Version: CURRENT   
Hardware: arm64   
OS: Any   
Attachments:
Description Flags
dmesg output
none
lsusb output
none
Fix for issue
none
Updated fix for issue.
none
Updated fix for issue (v2) none

Description chris 2018-08-07 11:21:15 UTC
I have a Griffin iMic USB audio sound card connected to a Raspberry Pi 3 B+ and am running FreeBSD-CURRENT r335760.

After loading  the snd_uaudio kernel module the device is correctly detected as per the following dmesg log:

ugen0.7: <Griffin Technology, Inc iMic USB audio system> at usbus0
uaudio0 on uhub1
uaudio0: <Griffin Technology, Inc iMic USB audio system, class 0/0, rev 1.10/0.0
6, addr 7> on usbus0
uaudio0: Play: 48000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 44100 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 40000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 32000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 24000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 22050 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 16000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 11025 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 8000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: No MIDI sequencer.
pcm0: <USB audio> on uaudio0

On trying to record from the device the user application concerned fails, and I find in the dmesg output a series of the following errors:

pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
uaudio0: No HID volume keys found.
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
sndbuf_remalloc(): b=0xfffffd00053cf600 0 -> 4096 [4096]
pcm0: chn_resizebuf(): PCMDIR_REC (virtual) timeout=21 b[0/0/0] bs[4096/128/32] limit=170
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
pcm0: chn_resizebuf(): PCMDIR_REC (virtual) timeout=21 b[0/0/0] bs[4096/128/32] limit=170
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
pcm0: chn_resizebuf(): PCMDIR_REC (virtual) timeout=21 b[0/0/0] bs[4096/128/32] limit=170
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
pcm0: chn_resizebuf(): PCMDIR_REC (virtual) timeout=21 b[0/0/0] bs[4096/128/32] limit=2048
pcm0: chn_start(): PCMDIR_REC (virtual) threshold i=4096 j=1
pcm0: chn_start(): VCHAN PARENT starting! (PCMDIR_REC/running) (ready=0 force=1 i=1 j=0 intrtimeout=21 latency=16ms)
pcm0: chn_trigger() pcm0:record:dsp0.r0: calling go=0x00000001 , prev=0x00000000
pcm0: chn_trigger() pcm0:virtual:dsp0.vr0: calling go=0x00000001 , prev=0x00000000
pcm0: chn_read(): pcm0:virtual:dsp0.vr0: record interrupt timeout, channel dead
pcm0: chn_trigger() pcm0:record:dsp0.r0: calling go=0xffffffff , prev=0x00000001
pcm0: chn_trigger() pcm0:virtual:dsp0.vr0: calling go=0xffffffff , prev=0x00000001
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0
sndbuf_remalloc(): b=0xfffffd00053cf600 4096 -> 32768 [32768]
pcm0: chn_resizebuf(): PCMDIR_REC (virtual) timeout=21 b[0/0/0] bs[32768/1024/32] limit=2048
pcm0: chn_resizebuf(): PCMDIR_REC (hardware) timeout=21 b[3072/1536/2] bs[4096/2048/2] limit=0

I have tried different sampling rates with the same results. The Griffin iMic works fine on FreeBSD 11.2 on Intel.

Any support would be appreciated.

Many thanks.
Comment 1 Hans Petter Selasky freebsd_committer freebsd_triage 2018-08-07 11:39:59 UTC
Hi,

No recording endpoints are recognised. There should be a Record: line.

uaudio0: Play: 48000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 44100 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 40000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 32000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 24000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 22050 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 16000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 11025 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 8000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: No MIDI sequencer.

A first step would be to enable:

sysctl hw.usb.uaudio_debug=16

before plugging the device and then post the result debug prints.

Also a dump of the USB descriptors are appreciated using lsusb from ports.
Comment 2 Hans Petter Selasky freebsd_committer freebsd_triage 2018-08-07 12:04:59 UTC
FYI:

lsusb is part of /usr/ports/sysutils/usbutils
Comment 3 chris 2018-08-07 16:24:04 UTC
Created attachment 195979 [details]
dmesg output
Comment 4 chris 2018-08-07 16:25:11 UTC
Created attachment 195980 [details]
lsusb output
Comment 5 chris 2018-08-07 16:26:18 UTC
Thanks Hans for picking-up this bug for me. Please find debug attachments as requested.

Cheers

Chris
Comment 6 Hans Petter Selasky freebsd_committer freebsd_triage 2018-08-07 19:21:40 UTC
In the debug messages pasted recording is supported:

uaudio_attach: audio rev 1.00
uaudio_attach: 8 mixer controls
uaudio0: Play: 48000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 44100 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 40000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 32000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 24000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 22050 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 16000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 11025 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Play: 8000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 48000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 44100 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 40000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 32000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 24000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 22050 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 16000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 11025 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: Record: 8000 Hz, 2 ch, 16-bit S-LE PCM format, 2x8ms buffer.
uaudio0: No MIDI sequencer.

If you "dd if=/dev/dsp0 of=/dev/null bs=256" does it fail?

Try to use 8kHz instead of 48kHz with your app. Does it still fail?

The RPi has some limitations what it can do w.r.t USB. In general I recommend high-speed USB audio devices. Your device appears to be full-speed - right?
Comment 7 chris 2018-08-08 14:46:11 UTC
Hi,

I tried:

dd if=/dev/dsp0 of=/dev/null bs=256

But it failed with:

dd: /dev/dsp0: Invalid argument
0+0 records in
0+0 records out
0 bytes transferred in 5.052607 secs (0 bytes/sec)

I also have tried sampling at 8kHz with the same problem.

Thanks

Chris
Comment 8 Hans Petter Selasky freebsd_committer freebsd_triage 2018-08-08 15:17:16 UTC
Can you try connecting the device via an external and self-powered USB 2.0 HUB?

--HPS
Comment 9 chris 2018-08-08 17:18:06 UTC
I've not got a powered USB hub to test it with. I have tried taking the other devices out of the USB just in case the problem is power related, but have had the same results. The iMic is a USB 2.0 device to answer your earlier question.

Chris
Comment 10 chris 2018-10-11 15:17:40 UTC
I tried connecting the USB sound card using a powered USB hub and the problem remains.
Comment 11 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-11 15:24:23 UTC
Can you also trace the USB device while trying to record:

usbdump -i usbusX -f Y -s 65536

dd if=/dev/dsp0 of=/dev/null bs=128


--HPS
Comment 12 chris 2018-10-11 15:51:49 UTC
Have I got this right:

The soundcard is on usbus0 and is /dev/dsp0.0, so am I right using:

usbdump -i usbus0 -f 0.0 -s 65536
Comment 13 chris 2018-10-11 15:59:34 UTC
The device filter I have wrong, it is 0.7 and the output from usbdump is:

16:54:53.405462 usbus0.7 SUBM-ISOC-EP=00000084,SPD=FULL,NFR=8,SLEN=0,IVAL=0
16:54:53.405472 usbus0.7 DONE-ISOC-EP=00000084,SPD=FULL,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
Comment 14 chris 2018-10-11 16:00:43 UTC
dd output as follows:

[tmp]# dd if=/dev/dsp0.0 of=/dev/null bs=128
dd: /dev/dsp0.0: Invalid argument
0+0 records in
0+0 records out
0 bytes transferred in 5.006964 secs (0 bytes/sec)
[tmp]#
Comment 15 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-11 16:10:09 UTC
Did you start usbdump before doing dd and after CTRL+C usbdump after dd has exited?
Comment 16 chris 2018-10-11 16:12:58 UTC
Yes, I did this. I could not seem to get the filter expression to work so let it capture all packets and pasted above the output from 0.7. Is this OK?
Comment 17 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-11 16:13:58 UTC
Can you join #bsdusb on EF-net ?
Comment 18 chris 2018-10-11 16:16:29 UTC
No, sorry.
Comment 19 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-11 16:30:12 UTC
I'm a little surprised that you get a timeout that quickly.

What is HZ set to?

sysctl -a | grep hz

If hz=1000, then it should be OK.

--HPS
Comment 20 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-11 16:32:51 UTC
I'll give my RPI3 a spin over the weekend and see if I can reproduce this issue.
Comment 21 chris 2018-10-11 17:04:38 UTC
Thanks for your patience Hans. 

kern.clockrate: { hz = 1000, tick = 1000, profhz = 8129, stathz = 127 }
kern.hz: 1000

Looks OK.
Comment 22 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-16 13:27:59 UTC
Hi,

I managed to reproduce the issue. It is a minor issue in the chipdriver DWC OTG.

I'm currently testing some patches. Stay tuned.

--HPS

diff --git a/sys/dev/usb/controller/dwc_otg.c b/sys/dev/usb/controller/dwc_otg.c
index 6bf42b98b7f..5d58e779ff1 100644
--- a/sys/dev/usb/controller/dwc_otg.c
+++ b/sys/dev/usb/controller/dwc_otg.c
@@ -1458,6 +1458,9 @@ dwc_otg_host_data_rx(struct dwc_otg_softc *sc, struct dwc_otg_td *td)
                                /* check if we are complete */
                                if (td->tt_xactpos == HCSPLT_XACTPOS_BEGIN) {
                                        goto complete;
+                               } else if (td->hcsplt != 0) {
+                                       /* get next CSPLIT packet */
+                                       goto receive_pkt;
                                } else {
                                        /* get more packets */
                                        goto busy;
Comment 23 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-16 14:34:15 UTC
Created attachment 198213 [details]
Fix for issue
Comment 24 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-16 14:44:21 UTC
The RPI3 has some limitation on the ISOCHRONOUS schedule, so you might need to set:

sysctl dev.pcm.0.rec.vchanrate=32000
sysctl dev.pcm.0.play.vchanrate=32000

In order to use duplex audio!

Or get a HIGH-speed USB audio device.

--HPS
Comment 25 chris 2018-10-16 15:22:35 UTC
Many thanks indeed Hans for your work. Glad that you could reproduce it. 

I'll apply your patch and give it a shot on my system here and let you know how things go.

Cheers

Chris
Comment 26 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-16 16:35:43 UTC
Created attachment 198228 [details]
Updated fix for issue.

Updated the patch a bit with support for full duplex.
Comment 27 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-16 17:13:43 UTC
Created attachment 198229 [details]
Updated fix for issue (v2)
Comment 28 commit-hook freebsd_committer freebsd_triage 2018-10-16 18:47:33 UTC
A commit references this bug:

Author: hselasky
Date: Tue Oct 16 18:47:13 UTC 2018
New revision: 339388
URL: https://svnweb.freebsd.org/changeset/base/339388

Log:
  Fix for reception of large full speed isochronous frames via the transaction
  translator, when using the DWC OTG USB controller driver. Make sure to re-try
  getting the complete split packets until a DATA0 packet is received. Larger
  isochronous frames may be split into multiple MDATA packets terminated
  by a single DATA0 packet.

  PR:			230434
  MFC after:		3 days
  Approved by:		re (gjb)
  Sponsored by:		Mellanox Technologies

Changes:
  head/sys/dev/usb/controller/dwc_otg.c
Comment 29 commit-hook freebsd_committer freebsd_triage 2018-10-19 08:38:40 UTC
A commit references this bug:

Author: hselasky
Date: Fri Oct 19 08:38:34 UTC 2018
New revision: 339442
URL: https://svnweb.freebsd.org/changeset/base/339442

Log:
  MFC r339388:
  Fix for reception of large full speed isochronous frames via the transaction
  translator, when using the DWC OTG USB controller driver. Make sure to re-try
  getting the complete split packets until a DATA0 packet is received. Larger
  isochronous frames may be split into multiple MDATA packets terminated
  by a single DATA0 packet.

  PR:			230434
  Sponsored by:		Mellanox Technologies

Changes:
_U  stable/11/
  stable/11/sys/dev/usb/controller/dwc_otg.c
Comment 30 commit-hook freebsd_committer freebsd_triage 2018-10-19 08:40:43 UTC
A commit references this bug:

Author: hselasky
Date: Fri Oct 19 08:40:26 UTC 2018
New revision: 339443
URL: https://svnweb.freebsd.org/changeset/base/339443

Log:
  MFC r339388:
  Fix for reception of large full speed isochronous frames via the transaction
  translator, when using the DWC OTG USB controller driver. Make sure to re-try
  getting the complete split packets until a DATA0 packet is received. Larger
  isochronous frames may be split into multiple MDATA packets terminated
  by a single DATA0 packet.

  PR:			230434
  Sponsored by:		Mellanox Technologies

Changes:
_U  stable/10/
  stable/10/sys/dev/usb/controller/dwc_otg.c
Comment 31 Hans Petter Selasky freebsd_committer freebsd_triage 2018-10-19 08:49:11 UTC
Let me know if this is still an issue.