On 10/15/12 15:28, Gleb Natapov wrote:
> On Mon, Oct 15, 2012 at 11:13:05AM +0200, Laszlo Ersek wrote:
>> The "hang" is not actually a hang; the VM is active. I ftraced kvm in
>> the epsilon-neighborhood of "point X", both under #6 (which hangs at X)
>> and under SeaBIOS (which advances beyond X), and compared the traces.
>> They are structurally similar (almost identical). Addresses seem to be
>> "parallel", ie. offset by constant-looking values. Unfortunately I'm
>> unable to identify the root cause from the few structural (and many
>> address) differences.
>>
> Yes, Windows randomizes its address space which makes it harder to
> debug. Can you provide example trace when VM "hangs".

http://people.redhat.com/~lersek/ovmf_win2k8r2sp1_debug/ftrace.tar.xz

The command line was "trace-cmd record -b 20000 -e kvm". I lowered the
number of VCPUs to 1 in the VM config.

I made three attempts; the first two are about 2 seconds long each and
"surround" the hang, while the third one is approx. 1 second long and
was made firmly after the hang ensued.

The third trace looks like a loop with the following body, iterations
being cca. 15 msecs apart:

    qemu-kvm-1086  [001] 25169.909638: kvm_set_irq:          gsi 8 level 1 
source 0
    qemu-kvm-1086  [001] 25169.909641: kvm_pic_set_irq:      chip 1 pin 0 
(edge|masked)
    qemu-kvm-1086  [001] 25169.909643: kvm_apic_accept_irq:  apicid 0 vec 209 
(Fixed|edge)
    qemu-kvm-1086  [001] 25169.909647: kvm_ioapic_set_irq:   pin 8 dst 1 
vec=209 (Fixed|logical|edge)
    qemu-kvm-1108  [002] 25169.909698: kvm_inj_virq:         irq 209
    qemu-kvm-1108  [002] 25169.909700: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909703: kvm_exit:             reason 
EXCEPTION_NMI rip 0xfffff8000e4e1a6e
    qemu-kvm-1108  [002] 25169.909706: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909708: kvm_exit:             reason 
IO_INSTRUCTION rip 0xfffff8000e4300b9
    qemu-kvm-1108  [002] 25169.909709: kvm_pio:              pio_write at 0x70 
size 1 count 1
    qemu-kvm-1108  [002] 25169.909724: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909725: kvm_exit:             reason 
IO_INSTRUCTION rip 0xfffff8000e4300bf
    qemu-kvm-1108  [002] 25169.909726: kvm_pio:              pio_read at 0x71 
size 1 count 1
    qemu-kvm-1108  [002] 25169.909731: kvm_set_irq:          gsi 8 level 0 
source 0
    qemu-kvm-1108  [002] 25169.909732: kvm_pic_set_irq:      chip 1 pin 0 
(edge|masked)
    qemu-kvm-1108  [002] 25169.909732: kvm_ioapic_set_irq:   pin 8 dst 1 
vec=209 (Fixed|logical|edge)
    qemu-kvm-1108  [002] 25169.909736: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909737: kvm_exit:             reason 
IO_INSTRUCTION rip 0xfffff8000e4300c0
    qemu-kvm-1108  [002] 25169.909738: kvm_pio:              pio_read at 0x71 
size 1 count 1
    qemu-kvm-1108  [002] 25169.909741: kvm_set_irq:          gsi 8 level 0 
source 0
    qemu-kvm-1108  [002] 25169.909741: kvm_pic_set_irq:      chip 1 pin 0 
(edge|masked)
    qemu-kvm-1108  [002] 25169.909741: kvm_ioapic_set_irq:   pin 8 dst 1 
vec=209 (Fixed|logical|edge)
    qemu-kvm-1108  [002] 25169.909744: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909747: kvm_exit:             reason APIC_ACCESS 
rip 0xfffff8000e439a70
    qemu-kvm-1108  [002] 25169.909753: kvm_mmio:             mmio write len 4 
gpa 0xfee000b0 val 0x0
    qemu-kvm-1108  [002] 25169.909753: kvm_apic:             apic_write 
APIC_EOI = 0x0
    qemu-kvm-1108  [002] 25169.909754: kvm_ack_irq:          irqchip IOAPIC pin 
8
    qemu-kvm-1108  [002] 25169.909755: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909757: kvm_exit:             reason 
EXCEPTION_NMI rip 0xfffff8000e4e1cfc
    qemu-kvm-1108  [002] 25169.909759: kvm_entry:            vcpu 0
    qemu-kvm-1108  [002] 25169.909769: kvm_exit:             reason HLT rip 
0xfffff8000e4397d1

with

    qemu-kvm-1108  [000] 25169.925098: kvm_entry:            vcpu 0
    qemu-kvm-1108  [000] 25169.925116: kvm_exit:             reason 
EXTERNAL_INTERRUPT rip 0xfffff9600021c279

optionally / randomly mixed into some iterations (the rip varies).

0x70/0x71 seem to correspond to the CMOS RTC. 0xfee000b0 falls into the
1MB LAPIC range @ 0xFEE00000.

Thank you, Gleb!
Laszlo

------------------------------------------------------------------------------
Don't let slow site performance ruin your business. Deploy New Relic APM
Deploy New Relic app performance management and know exactly
what is happening inside your Ruby, Python, PHP, Java, and .NET app
Try New Relic at no cost today and get our sweet Data Nerd shirt too!
http://p.sf.net/sfu/newrelic-dev2dev
_______________________________________________
edk2-devel mailing list
edk2-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/edk2-devel

Reply via email to