Losing interrupts

It seems that interrupts are being disabled for long periods, resulting in the soundcard interrupt being lost. I hacked the ALSA emu10k1 driver to keep track in the interrupt handler of the number of CPU cycles elapsed since the last time it ran. I am using a period that corresponds to 666 microseconds between interrupts, or ~400000 cycles on my 600Mhz CPU. As you can see the average jitter is *extremely* low - 50-400 CPU cycles of per interrupt. I hardcoded it to printk if the jitter is more than 15000 (only happens every 5-10 seconds), and error if it's really big. As you can see, something is disabling interrupts for a long time. This is a completely different issue from an XRUN, improving the scheduler latency will not solve this.

Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  392256 cycles, jitter = 15387
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  392353 cycles, jitter = 15603
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  391461 cycles, jitter = 16916
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  818180 cycles, jitter = 418547
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  818180 cycles, jitter = 418547 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -26, max jitter = 32): wrong interrupt
 acknowledge?
Jul 14 18:06:08 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+664125/3558647] snd_pcm_period_elapsed+0x1a7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+729917/3558647] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel:  [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 14 18:06:08 mindpipe kernel:  [do_IRQ+277/368] do_IRQ+0x115/0x170
Jul 14 18:06:08 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel: 
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 1, delta: -4, max jitter = 32): wrong interrupt 
acknowledge?
Jul 14 18:06:08 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+664125/3558647] snd_pcm_period_elapsed+0x1a7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+729303/3558647] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel:  [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 14 18:06:08 mindpipe kernel:  [do_IRQ+277/368] do_IRQ+0x115/0x170
Jul 14 18:06:08 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel: 
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 14 18:06:08 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+664413/3558647] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+729303/3558647] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel:  [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel: 
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  4964265 cycles, jitter = 4146085
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  4964265 cycles, jitter = 4146085 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -14, max jitter = 32): wrong interrupt
 acknowledge?
Jul 14 18:06:08 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+664125/3558647] snd_pcm_period_elapsed+0x1a7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel:  [__crc_totalram_pages+729917/3558647] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel:  [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel: 
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  1055689 cycles, jitter = 3908576
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  1055689 cycles, jitter = 3908576 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  362752 cycles, jitter = 692937
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  362752 cycles, jitter = 692937 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  399829 cycles, jitter = 37077
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  413648 cycles, jitter = 15319
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  387686 cycles, jitter = 25962
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  450250 cycles, jitter = 51838
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  349918 cycles, jitter = 100332
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  400891 cycles, jitter = 50973
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  386404 cycles, jitter = 26320
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  453172 cycles, jitter = 54183
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  347573 cycles, jitter = 105599
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  401149 cycles, jitter = 53576
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  386633 cycles, jitter = 26209
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  449097 cycles, jitter = 49093
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  351560 cycles, jitter = 97537
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  397671 cycles, jitter = 46111
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  389595 cycles, jitter = 21606
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  451106 cycles, jitter = 51236
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  350349 cycles, jitter = 100757
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  400588 cycles, jitter = 50239
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  386300 cycles, jitter = 25946
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  448680 cycles, jitter = 49155
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  351876 cycles, jitter = 96804
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  400708 cycles, jitter = 48832
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  385443 cycles, jitter = 28488
Jul 14 18:06:08 mindpipe kernel: IRQ: delay =  400482 cycles, jitter = 15039
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  387947 cycles, jitter = 23589
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391951 cycles, jitter = 16855
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  388987 cycles, jitter = 21825
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  392021 cycles, jitter = 16017
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  390522 cycles, jitter = 20142
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391896 cycles, jitter = 17595
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  388017 cycles, jitter = 23648
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391085 cycles, jitter = 18631
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  390518 cycles, jitter = 17585
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  390227 cycles, jitter = 18928
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  389163 cycles, jitter = 20901
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  389526 cycles, jitter = 19946
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  389876 cycles, jitter = 19494
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391128 cycles, jitter = 17707
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391987 cycles, jitter = 16681
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  390271 cycles, jitter = 18691
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  388294 cycles, jitter = 21678
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  389929 cycles, jitter = 19020
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  390888 cycles, jitter = 18574
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  387801 cycles, jitter = 22866
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  390384 cycles, jitter = 20683
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391604 cycles, jitter = 17213
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  392076 cycles, jitter = 15074
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  392304 cycles, jitter = 15524
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  388990 cycles, jitter = 20218
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391993 cycles, jitter = 16200
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391055 cycles, jitter = 17245
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391652 cycles, jitter = 15653
Jul 14 18:06:09 mindpipe kernel: IRQ: delay =  391095 cycles, jitter = 17794
Jul 14 18:06:10 mindpipe kernel: IRQ: delay =  392424 cycles, jitter = 15108

The problem is with the video driver (Via CastleRock integrated, AGP4x). By dragging certain windows around slowly in X, I can reliably cause interrupts to be completely disabled for tens of milliseconds.

There was an issue several years ago where Matrox figured out they could get slightly better benchmark scores by not checking whether a FIFO on the video card was full before writing to it, which would cause the PCI bus to completely freeze until the FIFO had drained. Lots of vendors followed suit until one of the audio software vendors figred it out and called them on it, at which point they fixed their drivers. The effects (massive audio drouputs) and the steps to reproduce (drag a window around the screen slowly) were identical.

I will contact the maintainer.

Lee

There's an XF86Config incantation which is supposed to prevent this: if you set it, the driver will poll the FIFO-full bit before actually reading the FIFO.

hm, according to http://www.xfree86.org/3.3.6/3DLabs3.html, the pci_retry option _causes_ the bad behaviour, rather than avoiding it.

Oh, well. Have a play with that.

The problem is with the video driver (Via CastleRock integrated, AGP4x). By dragging a window in X more quickly than the machine can keep up with, I can reliably cause interrupts to be completely disabled for tens or hundreds of milliseconds.

There was an issue several years ago where Matrox figured out they could get slightly better benchmark scores by not checking whether a FIFO on the video card was full before writing to it, which would cause the PCI bus to completely freeze until the FIFO had drained. Lots of vendors followed suit until one of the audio software vendors figred it out and called them on it, at which point they fixed their drivers. The effects (massive audio drouputs) and the steps to reproduce (drag a window around the screen) were identical.

Is it possible for the XFree86 DRI module to cause this, or would it have to be in the kernel?

Here is the lspci output:

0000:01:00.0 VGA compatible controller: VIA Technologies, Inc. VT8623 [Apollo CLE266] integrated CastleRock graphics (rev 03) (prog-if 00 [VGA])
Subsystem: VIA Technologies, Inc. VT8623 [Apollo CLE266] integrated CastleRock graphics
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32 (500ns min)
Interrupt: pin A routed to IRQ 11
Region 0: Memory at e4000000 (32-bit, prefetchable) [size=64M]
Region 1: Memory at e8000000 (32-bit, non-prefetchable) [size=16M]
Capabilities: [60] Power Management version 2
Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-
Capabilities: [70] AGP version 2.0
Status: RQ=32 Iso- ArqSz=0 Cal=0 SBA+ ITACoh- GART64- HTrans- 64bit- FW- AGP3- Rate=x1,x2,x4
Command: RQ=1 ArqSz=0 Cal=0 SBA- AGP- GART64- 64bit- FW- Rate=<none>

Lee