[Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Matt Lupfer]

Hello,

After upgrading to QEMU 1.7.0, CentOS 5.x guests often fail to boot
with the following kernel apic=debug output:

 > ACPI: Core revision 20060707
 > enabled ExtINT on CPU#0
 > ENABLING IO-APIC IRQs
 > ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
 > ..MP-BIOS bug: 8254 timer not connected to IO-APIC
 > ...trying to set up timer (IRQ0) through the 8259A ...  failed.
 > ...trying to set up timer as Virtual Wire IRQ... failed.
 > ...trying to set up timer as ExtINT IRQ... failed .
 > Kernel panic - not syncing: IO-APIC + timer doesn't work! Try using the 'noapic' kernel parameter

This happens greater than 50% of the time in my configuration.

Adding the noapic or no_timer_check parameter causes the guest to boot
properly.  I'd like to find a way to restore the previous behavior, which
didn't require these guest kernel parameters.

Host is a fully updated Fedora 20, kernel 3.12.10-300.fc20.x86_64 with an Intel
Core i5-2500 CPU. Guest is a fully updated base install of CentOS 5.10, kernel
2.6.18-371.4.1.el5.x86_64 (installed with "noapic", but booted with default
parameters).

QEMU invocation:
./x86_64-softmmu/qemu-system-x86_64 -m 4096 -cpu host -enable-kvm -drive file=~/ddn-001.img,cache=off -serial telnet:0.0.0.0:4444,server,nowait

A git bisect points to this commit as the culprit:

b1bbfe7 aio / timers: On timer modification, qemu_notify or aio_notify

which was part of the Aug 2013 timer rewrite.  Reverting this hunk in
particular makes the issue go away:

 > @@ -522,9 +531,7 @@ void qemu_mod_timer_ns(QEMUTimer *ts, int64_t expire_time)
 >          }
 >          /* Interrupt execution to force deadline recalculation.  */
 >          qemu_clock_warp(ts->timer_list->clock);
 > -        if (use_icount) {
 > -            timerlist_notify(ts->timer_list);
 > -        }
 > +        timerlist_notify(ts->timer_list);
 >      }
 >  }

(Note this was later refactored into timerlist_rearm() in 1.7.0, so I
mean that I modified timerlist_rearm() in 1.7.0 to read as that hunk
did before the b1bbfe7 commit.)

This doesn't appear to be a solution, because with the timer rewrite, QEMU
moves its periodic (1 ms) qemu_notify_event() call to break out of
the main event loop from a SIGALRM handler to the rearm of a QEMU timer.
Presumably QEMU is counting on these generic callbacks.

It appears that in QEMU 1.7.0, QEMU/KVM doesn't inject timer interrupts, or
alternatively the guest doesn't handle them, quickly enough to pass
the timer check in the guest kernel reliably.

I've found that if I suppress the first 20ms of calls to timerlist_notify()
in timerlist_rearm() by timers on the QEMU_CLOCK_VIRTUAL, the system is
able to boot successfully and remains stable.  Not calling
qemu_notify_event() on the first 20 ticks of QEMU_CLOCK_VIRTUAL seems to
alter the timings enough to produce a reliable result.  I tried this after
realizing that the guest kernel enables the HPET, which enables the QEMU
virtual clock, immediately before the guest timer check occurs.  I also
observed that the kernel boots fine with the "nohpet" parameter, and
I suspected that this could be a source of resource contention.

Finally, the QEMU options to disable KVM PIT IRQ reinjection and to disable
the kvm kernel irqchip altogether result in less frequent panics, but the
guest still panics within 100 boots.

Thanks for any assistance you can provide.

Matt

Re: [Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Paolo Bonzini]

Il 21/02/2014 05:34, Matt Lupfer ha scritto:
>
> This doesn't appear to be a solution, because with the timer rewrite, QEMU
> moves its periodic (1 ms) qemu_notify_event() call to break out of
> the main event loop from a SIGALRM handler to the rearm of a QEMU timer.
> Presumably QEMU is counting on these generic callbacks.

Thanks for the report, I'll try to reproduce.

Paolo

Re: [Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Alex Bligh]

On 21 Feb 2014, at 04:34, Matt Lupfer wrote:

> A git bisect points to this commit as the culprit:
> 
> b1bbfe7 aio / timers: On timer modification, qemu_notify or aio_notify
> 
> which was part of the Aug 2013 timer rewrite.  Reverting this hunk in
> particular makes the issue go away:
> 
> > @@ -522,9 +531,7 @@ void qemu_mod_timer_ns(QEMUTimer *ts, int64_t expire_time)
> >          }
> >          /* Interrupt execution to force deadline recalculation.  */
> >          qemu_clock_warp(ts->timer_list->clock);
> > -        if (use_icount) {
> > -            timerlist_notify(ts->timer_list);
> > -        }
> > +        timerlist_notify(ts->timer_list);
> >      }
> >  }
> 
> (Note this was later refactored into timerlist_rearm() in 1.7.0, so I
> mean that I modified timerlist_rearm() in 1.7.0 to read as that hunk
> did before the b1bbfe7 commit.)
> 
> This doesn't appear to be a solution, because with the timer rewrite, QEMU
> moves its periodic (1 ms) qemu_notify_event() call to break out of
> the main event loop from a SIGALRM handler to the rearm of a QEMU timer.
> Presumably QEMU is counting on these generic callbacks.

This is somewhat bizarre as the code you are reverting causes the main loop
to be broken out of *more*.

It's also happening only when someone calls qemu_mod_timer_ns. I'm
not sure what precisely the kernel is doing there, but perhaps it
is modifying a timer repeatedly and checking it fires within a given
time?

> It appears that in QEMU 1.7.0, QEMU/KVM doesn't inject timer interrupts, or
> alternatively the guest doesn't handle them, quickly enough to pass
> the timer check in the guest kernel reliably.

Yes that would suggest a latency type thing. The other thing that may
have happened is that the work done is being reprioritised, so rather
than respond to timer events immediately it's off doing some disk I/O
or similar, though frankly that's hard to understand when the kernel
is booting.

> 
> I've found that if I suppress the first 20ms of calls to timerlist_notify()
> in timerlist_rearm() by timers on the QEMU_CLOCK_VIRTUAL, the system is
> able to boot successfully and remains stable.  Not calling
> qemu_notify_event() on the first 20 ticks of QEMU_CLOCK_VIRTUAL seems to
> alter the timings enough to produce a reliable result.

Right but this isn't on the clock ticks, it's on a timer mod.

>  I tried this after
> realizing that the guest kernel enables the HPET, which enables the QEMU
> virtual clock, immediately before the guest timer check occurs.  I also
> observed that the kernel boots fine with the "nohpet" parameter, and
> I suspected that this could be a source of resource contention.
> 
> Finally, the QEMU options to disable KVM PIT IRQ reinjection and to disable
> the kvm kernel irqchip altogether result in less frequent panics, but the
> guest still panics within 100 boots.
> 
> Thanks for any assistance you can provide.

-- 
Alex Bligh

Re: [Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Matt Lupfer]

On 02/21/2014 06:27 AM, Alex Bligh wrote:
> 
> On 21 Feb 2014, at 04:34, Matt Lupfer wrote:
>
>>
>> This doesn't appear to be a solution, because with the timer rewrite, QEMU
>> moves its periodic (1 ms) qemu_notify_event() call to break out of
>> the main event loop from a SIGALRM handler to the rearm of a QEMU timer.
>> Presumably QEMU is counting on these generic callbacks.
> 
> This is somewhat bizarre as the code you are reverting causes the main loop
> to be broken out of *more*.
> 
> It's also happening only when someone calls qemu_mod_timer_ns. I'm
> not sure what precisely the kernel is doing there, but perhaps it
> is modifying a timer repeatedly and checking it fires within a given
> time?
> 

Thanks for the response.  The hpet_timer() callback calls timer_mod()
every 1 ms.  That timerlist has no notify callback so it in turn calls
qemu_notify_event().

The guest kernel is only enabling the HPET timer and looking for
timer interrupts.

>> It appears that in QEMU 1.7.0, QEMU/KVM doesn't inject timer interrupts, or
>> alternatively the guest doesn't handle them, quickly enough to pass
>> the timer check in the guest kernel reliably.
> 
> Yes that would suggest a latency type thing. The other thing that may
> have happened is that the work done is being reprioritised, so rather
> than respond to timer events immediately it's off doing some disk I/O
> or similar, though frankly that's hard to understand when the kernel
> is booting.
> 

I did some more debugging and found the problem was elsewhere.  This
different timer behavior is exposing a bug in the HPET implementation.

It's possible for the QEMU timer underlying the HPET to call the hpet_timer()
callback between when the timer is created and when the HPET device is
enabled (both actions initiated by the guest writing to HPET registers).
When this happens, the QEMU timer is rearmed to an expiration
time based on uninitialized values.  That's preventing the system timer
interrupt from ticking in the guest during the timer check at boot.

The changes to the timer implementation just makes this a lot more likely
to happen on CentOS 5.x kernels.

The fix looks straightforward.  I'll send a patch to the list.

Matt

Re: [Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Alex Bligh]

On 22 Feb 2014, at 00:57, Matt Lupfer wrote:

> I did some more debugging and found the problem was elsewhere.  This
> different timer behavior is exposing a bug in the HPET implementation.
> 
> It's possible for the QEMU timer underlying the HPET to call the hpet_timer()
> callback between when the timer is created and when the HPET device is
> enabled (both actions initiated by the guest writing to HPET registers).
> When this happens, the QEMU timer is rearmed to an expiration
> time based on uninitialized values.  That's preventing the system timer
> interrupt from ticking in the guest during the timer check at boot.
> 
> The changes to the timer implementation just makes this a lot more likely
> to happen on CentOS 5.x kernels.

Thanks for debugging this. The timer changes for better or for worse
seem to be quite good at uncovering bugs elsewhere.

-- 
Alex Bligh

Re: [Qemu-devel] CentOS 5.x intermittently fails to boot on QEMU 1.7.0

[Paolo Bonzini]

Il 22/02/2014 01:57, Matt Lupfer ha scritto:
> Thanks for the response.  The hpet_timer() callback calls timer_mod()
> every 1 ms.  That timerlist has no notify callback so it in turn calls
> qemu_notify_event().
>
> The guest kernel is only enabling the HPET timer and looking for
> timer interrupts.

FWIW, the HPET implementation is not very high precision (it has a large 
latency because it is implemented in userspace) and it is also very 
slow.  I suggest running always with -no-hpet.

Paolo