Losing interrupts

[Lee Revell]

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


-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/