From owner-freebsd-current@FreeBSD.ORG Wed Jun 22 12:09:01 2005 Return-Path: X-Original-To: freebsd-current@freebsd.org Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 32E6916A548 for ; Wed, 22 Jun 2005 12:09:01 +0000 (GMT) (envelope-from zazubrik@mail.ru) Received: from mx3.mail.ru (mx3.mail.ru [194.67.23.149]) by mx1.FreeBSD.org (Postfix) with ESMTP id B16AD43D55 for ; Wed, 22 Jun 2005 12:09:00 +0000 (GMT) (envelope-from zazubrik@mail.ru) Received: from [195.149.104.100] (port=30483 helo=[10.13.66.8]) by mx3.mail.ru with esmtp id 1Dl42N-0001MP-00 for freebsd-current@freebsd.org; Wed, 22 Jun 2005 16:08:59 +0400 Mime-Version: 1.0 (Apple Message framework v730) To: freebsd-current@freebsd.org Message-Id: <51A402CE-C1A2-48EB-B0B7-80448B91B422@mail.ru> Content-Type: multipart/mixed; boundary=Apple-Mail-2--598985748 From: Artem Ignatiev Date: Wed, 22 Jun 2005 16:08:54 +0400 X-Mailer: Apple Mail (2.730) Subject: lock problems with uaudio full-duplex X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 22 Jun 2005 12:09:01 -0000 --Apple-Mail-2--598985748 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=US-ASCII; delsp=yes; format=flowed Hi, I'm trying to get usb sound working in full-duplex, but still no success. Once it worked (on 5.3 with patches from appropriate PRs), and then it began to fail. I've tried to use that at 5.4, then at 6.0-CURRENT - that, with GENERIC kernel produced some interesting kernel output (on 5.3 and 5.4 I didn't used KDB, WITNESS and INVARIANTS). The machine is cvsupped just before build, and `uname -a` produces: FreeBSD pager.int.connecto.tv 6.0-CURRENT FreeBSD 6.0-CURRENT #1: Tue Jun 14 16:43:54 MSD 2005 root@pager.int.connecto.tv:/usr/obj/usr/ src/sys/GENERIC i386 I've got following: Jun 14 18:56:03 pager kernel: Sleeping on "usbsyn" with the following non-sleepable locks held: kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/sound/sound/../../../dev/ sound/pcm/dsp.c:145 Jun 14 18:56:03 pager kernel: malloc(M_WAITOK) of "512", forcing M_NOWAIT with the following non-sleepable locks held: Jun 14 18:56:03 pager kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/ sound/sound/../../../dev/sound/pcm/dsp.c:145 Jun 14 18:56:07 pager kernel: Sleeping on "usbdly" with the following non-sleepable locks held: Jun 14 18:56:07 pager kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/ sound/sound/../../../dev/sound/pcm/dsp.c:363 sample code to reproduce, dmesg and kernel logs are attached. Few word about kernel logs: Start message were sent to syslog via logger just before program was executed. ``Now will shutdown'' message were sent just before signaling to program. Program had done some cycles before this message. --Apple-Mail-2--598985748 Content-Transfer-Encoding: 7bit Content-Type: application/octet-stream; x-unix-mode=0644; name="dmesg" Content-Disposition: attachment; filename=dmesg Copyright (c) 1992-2005 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD 6.0-CURRENT #1: Tue Jun 14 16:43:54 MSD 2005 root@pager.int.connecto.tv:/usr/obj/usr/src/sys/GENERIC WARNING: WITNESS option enabled, expect reduced performance. Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: Intel(R) Pentium(R) 4 CPU 2.60GHz (2593.51-MHz 686-class CPU) Origin = "GenuineIntel" Id = 0xf29 Stepping = 9 Features=0xbfebfbff Features2=0x4400> Hyperthreading: 2 logical CPUs real memory = 1073152000 (1023 MB) avail memory = 1041215488 (992 MB) ACPI APIC Table: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs cpu0 (BSP): APIC ID: 0 cpu1 (AP): APIC ID: 1 ioapic0 irqs 0-23 on motherboard ioapic1 irqs 24-47 on motherboard npx0: [FAST] npx0: on motherboard npx0: INT 16 interface acpi0: on motherboard acpi0: Power Button (fixed) pci_link0: irq 10 on acpi0 pci_link1: irq 10 on acpi0 pci_link2: irq 5 on acpi0 pci_link3: irq 11 on acpi0 pci_link4: irq 0 on acpi0 pci_link5: irq 10 on acpi0 pci_link6: irq 0 on acpi0 pci_link7: irq 11 on acpi0 Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0 cpu0: on acpi0 acpi_throttle0: on cpu0 cpu1: on acpi0 acpi_throttle1: on cpu1 acpi_throttle1: failed to attach P_CNT device_attach: acpi_throttle1 attach returned 6 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 pcib1: at device 3.0 on pci0 pci2: on pcib1 em0: port 0x2000-0x201f mem 0xe8100000-0xe811ffff irq 18 at device 1.0 on pci2 em0: Ethernet address: 00:0d:61:46:33:f6 em0: Speed:N/A Duplex:N/A pcib2: at device 28.0 on pci0 pci3: on pcib2 uhci0: port 0x1400-0x141f irq 16 at device 29.0 on pci0 uhci0: [GIANT-LOCKED] usb0: on uhci0 usb0: USB revision 1.0 uhub0: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub0: 2 ports with 2 removable, self powered uhci1: port 0x1420-0x143f irq 19 at device 29.1 on pci0 uhci1: [GIANT-LOCKED] usb1: on uhci1 usb1: USB revision 1.0 uhub1: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub1: 2 ports with 2 removable, self powered pci0: at device 29.4 (no driver attached) pci0: at device 29.5 (no driver attached) ehci0: mem 0xe8000400-0xe80007ff irq 23 at device 29.7 on pci0 ehci0: [GIANT-LOCKED] usb2: EHCI version 1.0 usb2: companion controllers, 2 ports each: usb0 usb1 usb2: on ehci0 usb2: USB revision 2.0 uhub2: Intel EHCI root hub, class 9/0, rev 2.00/1.00, addr 1 uhub2: 4 ports with 4 removable, self powered pcib3: at device 30.0 on pci0 pci4: on pcib3 pci4: at device 0.0 (no driver attached) pci4: at device 5.0 (no driver attached) em1: port 0x3400-0x343f mem 0xe8300000-0xe831ffff irq 16 at device 10.0 on pci4 em1: Ethernet address: 00:0d:61:46:33:f7 em1: Speed:N/A Duplex:N/A isab0: at device 31.0 on pci0 isa0: on isab0 atapci0: port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x1460-0x146f at device 31.1 on pci0 ata0: on atapci0 ata1: on atapci0 pci0: at device 31.3 (no driver attached) acpi_tz0: on acpi0 acpi_button0: on acpi0 atkbdc0: port 0x60,0x64 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] psm0: irq 12 on atkbdc0 psm0: [GIANT-LOCKED] psm0: model IntelliMouse, device ID 3 sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 sio0: type 16550A sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0 sio1: type 16550A ppc0: port 0x378-0x37f irq 7 drq 1 on acpi0 ppc0: Generic chipset (ECP/PS2/NIBBLE) in COMPATIBLE mode ppc0: FIFO with 16/16/16 bytes threshold ppbus0: on ppc0 plip0: on ppbus0 lpt0: on ppbus0 lpt0: Interrupt-driven port ppi0: on ppbus0 fdc0: port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0 fdc0: [FAST] pmtimer0 on isa0 orm0: at iomem 0xc0000-0xc7fff,0xc8000-0xcbfff,0xcc000-0xccfff,0xcd000-0xcdfff on isa0 sc0: at flags 0x100 on isa0 sc0: VGA <16 virtual consoles, flags=0x300> vga0: at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 uaudio0: Silicon Portals. Y@pPhone - The way to chat., rev 1.00/1.00, addr 2 uaudio0: audio rev 1.00 pcm0: on uaudio0 uhid0: Silicon Portals. Y@pPhone - The way to chat., rev 1.00/1.00, addr 2, iclass 1/1 Timecounters tick every 1.000 msec ad0: 38166MB at ata0-master UDMA100 acd0: DVDROM at ata1-slave UDMA33 ATA PseudoRAID loaded SMP: AP CPU #1 Launched! Trying to mount root from ufs:/dev/ad0s1a em0: link state changed to UP --Apple-Mail-2--598985748 Content-Transfer-Encoding: 7bit Content-Type: application/octet-stream; x-unix-mode=0644; name="snd_test.c" Content-Disposition: attachment; filename=snd_test.c #include #include #include #include #include #include #include #define DEVICE_NAME "/dev/dsp0.0" #define BUF_SIZE (160) int main(void) { uint8_t audio_buffer[BUF_SIZE], audio_buffer2[BUF_SIZE]; int raw_fd, audio_fd; int speed = SRATE; int format = AFMT_S16_LE; int i; int frag; audio_buf_info info; int stereo = 0; if ((audio_fd = open(DEVICE_NAME, O_RDWR, 0)) == -1) { /* Opening device failed */ perror(DEVICE_NAME); return 1; } while(1) { i = read(audio_fd, audio_buffer, BUF_SIZE); ioctl(audio_fd, SNDCTL_DSP_POST, 0); if (i > 0) { i = write(audio_fd, audio_buffer, BUF_SIZE); if (i == -1) perror("write()"); } else perror("read"); } } --Apple-Mail-2--598985748 Content-Transfer-Encoding: 7bit Content-Type: application/octet-stream; x-unix-mode=0644; name="ua_log" Content-Disposition: attachment; filename=ua_log Jun 14 18:55:21 pager timon: Start Jun 14 18:56:03 pager kernel: Sleeping on "usbsyn" with the following non-sleepable locks held: kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/sound/sound/../../../dev/sound/pcm/dsp.c:145 kernel: KDB: stack backtrace: kernel: kdb_backtrace(1,c25e8400,c2360a80,0,e50eaa78) at kdb_backtrace+0x29 kernel: witness_warn(5,0,c084f4c3,c0845d73) at witness_warn+0x18e kernel: msleep(c2633400,0,4c,c0845d73,0) at msleep+0x42 kernel: usbd_transfer(c2633400,e50eaad8,c05d3a71,c2633400,c2360a80) at usbd_transfer+0x121 kernel: usbd_sync_transfer(c2633400,c2360a80,c1052458,c1052420,c247abb8) at usbd_sync_transfer+0x11 kernel: usbd_do_request_flags_pipe(c247b000,c247ae80,e50eab30,0,0) at usbd_do_request_flags_pipe+0x5d kernel: usbd_do_request_flags(c247b000,e50eab30,0,0,0) at usbd_do_request_flags+0x20 kernel: usbd_do_request(c247b000,e50eab30,0,10b01,2) at usbd_do_request+0x1a kernel: usbd_set_interface(c247abb8,1,88,e50eab78,c0a76ff4) at usbd_set_interface+0x75 kernel: uaudio_chan_open(0,c247a8ac,1,e50eaba0,c0a799f5) at uaudio_chan_open+0x4a kernel: uaudio_trigger_input(c247ae00,c247a8ac,c2492090,e50eabc0,c0a8858b) at uaudio_trigger_input+0x53 kernel: ua_chan_trigger(c2492090,c247a8ac,1,c247a700,c2496400) at ua_chan_trigger+0x45 kernel: chn_trigger(c247a700,1,c2496400,1,10000000) at chn_trigger+0x57 kernel: chn_start(c247a700,0,c2496300,e50eac18,10000000) at chn_start+0x69 kernel: chn_read(c247a700,e50eac78,c247a700,c247a780,0) at chn_read+0x1ce kernel: dsp_read(c2496700,e50eac78,0,a0,c2496700) at dsp_read+0x3f kernel: devfs_read_f(c26379d8,e50eac78,c249de00,0,c2360a80) at devfs_read_f+0x87 kernel: dofileread(c2360a80,c26379d8,3,bfbfec70,a0) at dofileread+0xad kernel: read(c2360a80,e50ead04,3,2,213) at read+0x3b kernel: syscall(3b,3b,3b,bfbfec70,3) at syscall+0x22f kernel: Xint0x80_syscall() at Xint0x80_syscall+0x1f Jun 14 18:56:03 pager kernel: --- syscall (3, FreeBSD ELF32, read), eip = 0x280b667b, esp = 0xbfbfeb8c, ebp = 0xbfbfed28 --- Jun 14 18:56:03 pager kernel: malloc(M_WAITOK) of "512", forcing M_NOWAIT with the following non-sleepable locks held: Jun 14 18:56:03 pager kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/sound/sound/../../../dev/sound/pcm/dsp.c:145 Jun 14 18:56:03 pager kernel: KDB: stack backtrace: kernel: kdb_backtrace(1,200,c1052b00,5,e50eaa6c) at kdb_backtrace+0x29 kernel: witness_warn(5,0,c086924c,c0824965,200) at witness_warn+0x18e kernel: uma_zalloc_arg(c1052b00,0,2) at uma_zalloc_arg+0x41 kernel: malloc(200,c08aa7e0,2,88,2) at malloc+0xae kernel: uhci_setup_isoc(c29dda00,c29dda00,c247b000,e50eaae8,c05d22a2) at uhci_setup_isoc+0x40 kernel: uhci_open(c29dda00,c2473a88,c2492340,c247abb8,e50eab1c) at uhci_open+0x165 kernel: usbd_setup_pipe(c247b000,c247abb8,c2492340,ffffffff,e50eab0c) at usbd_setup_pipe+0x72 kernel: usbd_open_pipe_ival(c247abb8,88,0,c2428aa0,ffffffff) at usbd_open_pipe_ival+0x70 kernel: usbd_open_pipe(c247abb8,88,0,c2428aa0,88) at usbd_open_pipe+0x1a kernel: uaudio_chan_open(0,c247a8ac,1,e50eaba0,c0a799f5) at uaudio_chan_open+0xc5 kernel: uaudio_trigger_input(c247ae00,c247a8ac,c2492090,e50eabc0,c0a8858b) at uaudio_trigger_input+0x53 kernel: ua_chan_trigger(c2492090,c247a8ac,1,c247a700,c2496400) at ua_chan_trigger+0x45 kernel: chn_trigger(c247a700,1,c2496400,1,10000000) at chn_trigger+0x57 kernel: chn_start(c247a700,0,c2496300,e50eac18,10000000) at chn_start+0x69 kernel: chn_read(c247a700,e50eac78,c247a700,c247a780,0) at chn_read+0x1ce kernel: dsp_read(c2496700,e50eac78,0,a0,c2496700) at dsp_read+0x3f kernel: devfs_read_f(c26379d8,e50eac78,c249de00,0,c2360a80) at devfs_read_f+0x87 kernel: dofileread(c2360a80,c26379d8,3,bfbfec70,a0) at dofileread+0xad kernel: read(c2360a80,e50ead04,3,2,213) at read+0x3b kernel: syscall(3b,3b,3b,bfbfec70,3) at syscall+0x22f kernel: Xint0x80_syscall() at Xint0x80_syscall+0x1f Jun 14 18:56:03 pager kernel: --- syscall (3, FreeBSD ELF32, read), eip = 0x280b667b, esp = 0xbfbfeb8c, ebp = 0xbfbfed28 --- Jun 14 18:56:03 pager kernel: Sleeping on "usbsyn" with the following non-sleepable locks held: Jun 14 18:56:03 pager kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/sound/sound/../../../dev/sound/pcm/dsp.c:145 Jun 14 18:56:03 pager kernel: KDB: stack backtrace: kernel: kdb_backtrace(1,c25e8400,c2360a80,0,e50eaa04) at kdb_backtrace+0x29 kernel: witness_warn(5,0,c084f4c3,c0845d73) at witness_warn+0x18e kernel: msleep(c2633400,0,4c,c0845d73,0) at msleep+0x42 kernel: usbd_transfer(c2633400,e50eaa64,c05d3a71,c2633400,c063ea33) at usbd_transfer+0x121 kernel: usbd_sync_transfer(c2633400,c063ea33,c0917400,2,c29dda00) at usbd_sync_transfer+0x11 kernel: usbd_do_request_flags_pipe(c247b000,c247ae80,e50eaac0,0,0) at usbd_do_request_flags_pipe+0x5d kernel: usbd_do_request_flags(c247b000,e50eaac0,0,0,0) at usbd_do_request_flags+0x20 kernel: usbd_do_request(c247b000,e50eaac0,0,c29dda00,102) at usbd_do_request+0x1a kernel: usbd_clear_endpoint_stall(c29dda00,c2473a88,c2492340,c247abb8,e50eab1c) at usbd_clear_endpoint_stall+0x48 kernel: usbd_setup_pipe(c247b000,c247abb8,c2492340,ffffffff,e50eab0c) at usbd_setup_pipe+0x9a kernel: usbd_open_pipe_ival(c247abb8,88,0,c2428aa0,ffffffff) at usbd_open_pipe_ival+0x70 kernel: usbd_open_pipe(c247abb8,88,0,c2428aa0,88) at usbd_open_pipe+0x1a kernel: uaudio_chan_open(0,c247a8ac,1,e50eaba0,c0a799f5) at uaudio_chan_open+0xc5 kernel: uaudio_trigger_input(c247ae00,c247a8ac,c2492090,e50eabc0,c0a8858b) at uaudio_trigger_input+0x53 kernel: ua_chan_trigger(c2492090,c247a8ac,1,c247a700,c2496400) at ua_chan_trigger+0x45 kernel: chn_trigger(c247a700,1,c2496400,1,10000000) at chn_trigger+0x57 kernel: chn_start(c247a700,0,c2496300,e50eac18,10000000) at chn_start+0x69 kernel: chn_read(c247a700,e50eac78,c247a700,c247a780,0) at chn_read+0x1ce kernel: dsp_read(c2496700,e50eac78,0,a0,c2496700) at dsp_read+0x3f kernel: devfs_read_f(c26379d8,e50eac78,c249de00,0,c2360a80) at devfs_read_f+0x87 kernel: dofileread(c2360a80,c26379d8,3,bfbfec70,a0) at dofileread+0xad kernel: read(c2360a80,e50ead04,3,2,213) at read+0x3b kernel: syscall(3b,3b,3b,bfbfec70,3) at syscall+0x22f kernel: Xint0x80_syscall() at Xint0x80_syscall+0x1f Jun 14 18:56:03 pager kernel: --- syscall (3, FreeBSD ELF32, read), eip = 0x280b667b, esp = 0xbfbfeb8c, ebp = 0xbfbfed28 --- Jun 14 18:56:05 pager timon: Now will shutdown Jun 14 18:56:07 pager kernel: Sleeping on "usbdly" with the following non-sleepable locks held: Jun 14 18:56:07 pager kernel: exclusive sleep mutex pcm0:record:0 (pcm record channel) r = 0 (0xc2494840) locked @ /usr/src/sys/modules/sound/sound/../../../dev/sound/pcm/dsp.c:363 Jun 14 18:56:07 pager kernel: KDB: stack backtrace: kernel: kdb_backtrace(1,c25e8400,c2360a80,c23f9000,e50ea918) at kdb_backtrace+0x29 kernel: witness_warn(5,0,c084f4c3,c0845bd1) at witness_warn+0x18e kernel: msleep(e50ea940,0,4c,c0845bd1,3) at msleep+0x42 kernel: usb_delay_ms(c23f9000,2) at usb_delay_ms+0x67 kernel: uhci_device_isoc_close(c29dda00) at uhci_device_isoc_close+0x32 kernel: usbd_close_pipe(c29dda00,c29dda00,c2428a9c,e50ea984,c0a7790b) at usbd_close_pipe+0x44 kernel: uaudio_chan_close(fffffffe,c247a8ac,e50ea998,c0a799e5,c247ae00) at uaudio_chan_close+0x7e kernel: uaudio_halt_in_dma(c247ae00,c247a8ac,c2492090,e50ea9b8,c0a8858b) at uaudio_halt_in_dma+0x43 kernel: ua_chan_trigger(c2492090,c247a8ac,ffffffff,c2496300,c247a700) at ua_chan_trigger+0x35 kernel: chn_trigger(c247a700,ffffffff,c247a700,c2496700,c247a780) at chn_trigger+0x57 kernel: chn_abort(c247a700,c2494840,0,c0a90acc,16b) at chn_abort+0x35 kernel: dsp_close(c2496700,3,2000,c2360a80,c0917440) at dsp_close+0x150 kernel: devfs_close(e50eaa6c) at devfs_close+0x2f1 kernel: VOP_CLOSE_APV(c08ab9e0,e50eaa6c) at VOP_CLOSE_APV+0x7e kernel: vn_close(c29b2000,3,c249de00,c2360a80,c084bc84) at vn_close+0x8b kernel: vn_closefile(c26379d8,c2360a80,e50eab24,c06129a4,c26379d8) at vn_closefile+0xca kernel: devfs_close_f(c26379d8,c2360a80) at devfs_close_f+0xf kernel: fdrop_locked(c26379d8,c2360a80,c2298114,0,c084bc84) at fdrop_locked+0x88 kernel: fdrop(c26379d8,c2360a80,e50eab70,c064ec5c,c084bc84) at fdrop+0x24 kernel: closef(c26379d8,c2360a80) at closef+0x35f kernel: fdfree(c2360a80,c25e854c,6ac,c0964dcc,e50eac68) at fdfree+0x473 kernel: exit1(c2360a80,2,a1,c2360a80,c2aad000) at exit1+0x3f6 kernel: sigexit(c2360a80,2,c2aadaa8,0,c084f0b4) at sigexit+0xdf kernel: postsig(2) at postsig+0x131 kernel: ast(e50ead38) at ast+0x35e kernel: doreti_ast() at doreti_ast+0x17 Jun 14 18:56:19 pager timon: shut down --Apple-Mail-2--598985748--