"Unexpected hw_pointer value - wrong interrupt acknowledge?" with emu10k1

"Unexpected hw_pointer value - wrong interrupt acknowledge?" with emu10k1

[Lee Revell]

> On Sun, 2004-07-11 at 01:25, Andrew Morton wrote:
> > What we need to do is to encourage audio testers to use ALSA drivers, to
> > enable CONFIG_SND_DEBUG in the kernel build and to set
> > /proc/asound/*/*/xrun_debug and to send us the traces which result from
> > underruns.
> > 
> 
> OK, here goes.  The following traces result from running JACK overnight
> like so, on an otherwise idle system.  Hardware is a VIA EPIA 6000, with
> a 600Mhz C3 processor.  Kernel is 2.6.7 + volunatary_preempt patch. 
> voluntary_preempt and kernel_preemption are both on.
> 
> jackd -v --realtime -d alsa --outchannels 2 --rate 48000 --shorts
> --playback --period 32  --nperiods 2
> 
> These settings require less than 666 microseconds scheduler latency. 
> The average performance is quite good - 5-20 *microseconds*!
> 

While running the above test, I also noticed these messages from the
ALSA driver.  These messages did not occur during the overnight test;
they began when I sat down at the console to check the results.

Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -16, max jitter = 32): wrong interrupt acknowledge?
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+1386981/5353478] snd_pcm_period_elapsed+0x1af/0x410 [snd_pcm]
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:31:43 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:31:43 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:31:43 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:31:43 mindpipe kernel:  [__do_softirq+48/144] __do_softirq+0x30/0x90
Jul 12 17:31:43 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 17:31:43 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 17:31:43 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:31:43 mindpipe kernel:
Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -31, max jitter = 32): wrong interrupt acknowledge?
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+1386981/5353478] snd_pcm_period_elapsed+0x1af/0x410 [snd_pcm]
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:31:43 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:31:43 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:31:43 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:31:43 mindpipe kernel:
Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -25, max jitter = 32): wrong interrupt acknowledge?
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+1386981/5353478] snd_pcm_period_elapsed+0x1af/0x410 [snd_pcm]
Jul 12 17:31:43 mindpipe kernel:  [do_timer+254/272] do_timer+0xfe/0x110
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+1455070/5353478] snd_emu10k1_interrupt+0x3c8/0x480 [snd_emu10k1]
Jul 12 17:31:43 mindpipe kernel:  [handle_IRQ_event+49/96] handle_IRQ_event+0x31/0x60
Jul 12 17:31:43 mindpipe kernel:  [do_IRQ+155/352] do_IRQ+0x9b/0x160
Jul 12 17:31:43 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+696339/5353478] rhine_timer+0x8d/0x130 [via_rhine]
Jul 12 17:31:43 mindpipe kernel:  [__crc_totalram_pages+696198/5353478] rhine_timer+0x0/0x130 [via_rhine]
Jul 12 17:31:43 mindpipe kernel:  [run_timer_softirq+201/416] run_timer_softirq+0xc9/0x1a0
Jul 12 17:31:43 mindpipe kernel:  [__do_softirq+131/144] __do_softirq+0x83/0x90
Jul 12 17:31:43 mindpipe kernel:  [do_softirq+53/64] do_softirq+0x35/0x40
Jul 12 17:31:43 mindpipe kernel:  [do_IRQ+261/352] do_IRQ+0x105/0x160
Jul 12 17:31:43 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 12 17:31:43 mindpipe kernel:

Lee




-------------------------------------------------------
This SF.Net email sponsored by Black Hat Briefings & Training.
Attend Black Hat Briefings & Training, Las Vegas July 24-29 - 
digital self defense, top technical experts, no vendor pitches, 
unmatched networking opportunities. Visit www.blackhat.com

Re: "Unexpected hw_pointer value - wrong interrupt acknowledge?" with emu10k1

[Takashi Iwai]

At Mon, 12 Jul 2004 20:38:05 -0400,
Lee Revell wrote:
> 
> > On Sun, 2004-07-11 at 01:25, Andrew Morton wrote:
> > > What we need to do is to encourage audio testers to use ALSA drivers, to
> > > enable CONFIG_SND_DEBUG in the kernel build and to set
> > > /proc/asound/*/*/xrun_debug and to send us the traces which result from
> > > underruns.
> > > 
> > 
> > OK, here goes.  The following traces result from running JACK overnight
> > like so, on an otherwise idle system.  Hardware is a VIA EPIA 6000, with
> > a 600Mhz C3 processor.  Kernel is 2.6.7 + volunatary_preempt patch. 
> > voluntary_preempt and kernel_preemption are both on.
> > 
> > jackd -v --realtime -d alsa --outchannels 2 --rate 48000 --shorts
> > --playback --period 32  --nperiods 2
> > 
> > These settings require less than 666 microseconds scheduler latency. 
> > The average performance is quite good - 5-20 *microseconds*!
> > 
> 
> While running the above test, I also noticed these messages from the
> ALSA driver.  These messages did not occur during the overnight test;
> they began when I sat down at the console to check the results.
> 
> Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -16, max jitter = 32): wrong interrupt acknowledge?

The message appears when an unexpected DMA pointer is read in the
interrupt handler.  Either the handling of irq was delayed more than
the buffer size, an irq is issued at the wrong timing, or the DMA
pointer reigster is somehow screwed up.

Since you're using quite small buffer, I guess the former case.


Takashi



-------------------------------------------------------
This SF.Net email sponsored by Black Hat Briefings & Training.
Attend Black Hat Briefings & Training, Las Vegas July 24-29 - 
digital self defense, top technical experts, no vendor pitches, 
unmatched networking opportunities. Visit www.blackhat.com

Re: "Unexpected hw_pointer value - wrong interrupt acknowledge?" with emu10k1

[Lee Revell]

On Tue, 2004-07-13 at 12:26, Takashi Iwai wrote:
> At Mon, 12 Jul 2004 20:38:05 -0400,
> Lee Revell wrote:
> > 
> > > On Sun, 2004-07-11 at 01:25, Andrew Morton wrote:
> > > > What we need to do is to encourage audio testers to use ALSA drivers, to
> > > > enable CONFIG_SND_DEBUG in the kernel build and to set
> > > > /proc/asound/*/*/xrun_debug and to send us the traces which result from
> > > > underruns.
> > > > 
> > > 
> > > OK, here goes.  The following traces result from running JACK overnight
> > > like so, on an otherwise idle system.  Hardware is a VIA EPIA 6000, with
> > > a 600Mhz C3 processor.  Kernel is 2.6.7 + volunatary_preempt patch. 
> > > voluntary_preempt and kernel_preemption are both on.
> > > 
> > > jackd -v --realtime -d alsa --outchannels 2 --rate 48000 --shorts
> > > --playback --period 32  --nperiods 2
> > > 
> > > These settings require less than 666 microseconds scheduler latency. 
> > > The average performance is quite good - 5-20 *microseconds*!
> > > 
> > 
> > While running the above test, I also noticed these messages from the
> > ALSA driver.  These messages did not occur during the overnight test;
> > they began when I sat down at the console to check the results.
> > 
> > Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -16, max jitter = 32): wrong interrupt acknowledge?
> 
> The message appears when an unexpected DMA pointer is read in the
> interrupt handler.  Either the handling of irq was delayed more than
> the buffer size, an irq is issued at the wrong timing, or the DMA
> pointer reigster is somehow screwed up.
> 
> Since you're using quite small buffer, I guess the former case.
> 

I thought this was what an XRUN was, when the handling of the irq is
delayed more than the buffer size.  Sometimes these messages are
associated with XRUNs, sometimes not.

Is this a kernel issue, ALSA midlevel issue, or driver issue?

Lee




-------------------------------------------------------
This SF.Net email sponsored by Black Hat Briefings & Training.
Attend Black Hat Briefings & Training, Las Vegas July 24-29 - 
digital self defense, top technical experts, no vendor pitches, 
unmatched networking opportunities. Visit www.blackhat.com

Re: "Unexpected hw_pointer value - wrong interrupt

[Giuliano Pochini]

On 13-Jul-2004 Lee Revell wrote:

>> > Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199:
>> > Unexpected hw_pointer value [1] (stream = 0, delta: -16, max jitter = 32): wrong interrupt acknowledge?
>>
>> The message appears when an unexpected DMA pointer is read in the
>> interrupt handler.  Either the handling of irq was delayed more than
>> the buffer size, an irq is issued at the wrong timing, or the DMA
>> pointer reigster is somehow screwed up.
>>
>> Since you're using quite small buffer, I guess the former case.
>>
>
> I thought this was what an XRUN was, when the handling of the irq is
> delayed more than the buffer size.  Sometimes these messages are
> associated with XRUNs, sometimes not.
>
> Is this a kernel issue, ALSA midlevel issue, or driver issue?

It is associated with an xrun when it is the cause of the xrun,
most likely, and it happens more frequently if you're using a
short buffer formed by two periods only.

A lot of things can cause it. The most common are: Some code path
in the kernel keeps interrupts disabled too long or the hardware
does not send the IRQ quickly enough or the dma counter is not up
to date when the driver reads it.

For example my driver had that problem until I figured out that
the IRQ is delivered only at addresses aligned to the lenght of
32 frames. I fixed it placing a _constaint_step() on the period
size and on the buffer size.


--
Giuliano.


-------------------------------------------------------
This SF.Net email is sponsored by BEA Weblogic Workshop
FREE Java Enterprise J2EE developer tools!
Get your free copy of BEA WebLogic Workshop 8.1 today.
http://ads.osdn.com/?ad_id=4721&alloc_id=10040&op=click

Re: "Unexpected hw_pointer value - wrong interrupt

[Lee Revell]

On Thu, 2004-07-15 at 06:41, Giuliano Pochini wrote:
> On 13-Jul-2004 Lee Revell wrote:
> 
> >> > Jul 12 17:31:43 mindpipe kernel: ALSA /usr/src/alsa-cvs-1.0.5/alsa-driver/alsa-kernel/core/pcm_lib.c:199:
> >> > Unexpected hw_pointer value [1] (stream = 0, delta: -16, max jitter = 32): wrong interrupt acknowledge?
> >>
> >> The message appears when an unexpected DMA pointer is read in the
> >> interrupt handler.  Either the handling of irq was delayed more than
> >> the buffer size, an irq is issued at the wrong timing, or the DMA
> >> pointer reigster is somehow screwed up.
> >>
> >> Since you're using quite small buffer, I guess the former case.
> >>
> >
> > I thought this was what an XRUN was, when the handling of the irq is
> > delayed more than the buffer size.  Sometimes these messages are
> > associated with XRUNs, sometimes not.
> >
> > Is this a kernel issue, ALSA midlevel issue, or driver issue?
> 
> It is associated with an xrun when it is the cause of the xrun,
> most likely, and it happens more frequently if you're using a
> short buffer formed by two periods only.
> 
> A lot of things can cause it. The most common are: Some code path
> in the kernel keeps interrupts disabled too long or the hardware
> does not send the IRQ quickly enough or the dma counter is not up
> to date when the driver reads it.
> 
> For example my driver had that problem until I figured out that
> the IRQ is delivered only at addresses aligned to the lenght of
> 32 frames. I fixed it placing a _constaint_step() on the period
> size and on the buffer size.

The problem seems to be with the Via CastleRock video driver.  By slowly
dragging certain windows around in X (the gmplayer splash screen is the
easiest to replicate with), I can cause interrupts to be completely
disabled for tens of milliseconds.  The symptoms seem identical to the
issue several years ago where video card vendors figured out they could
get slightly better benchmark scores by not checking whether there is
space in the video card FIFO before writing to it. The effect of this
was to completely lock up the PCI bus until the FIFO drained.

More details are on LKML (the 'Losing interrupts' thread).

Lee

 



-------------------------------------------------------
This SF.Net email is sponsored by BEA Weblogic Workshop
FREE Java Enterprise J2EE developer tools!
Get your free copy of BEA WebLogic Workshop 8.1 today.
http://ads.osdn.com/?ad_id=4721&alloc_id=10040&op=click