* More RTC issues with Win2k3
@ 2013-09-03 13:37 Andrew Cooper
2013-09-04 9:38 ` Jan Beulich
0 siblings, 1 reply; 7+ messages in thread
From: Andrew Cooper @ 2013-09-03 13:37 UTC (permalink / raw)
To: Jan Beulich; +Cc: Xen-devel List
[-- Attachment #1: Type: text/plain, Size: 1143 bytes --]
Hello,
Sorry to be the bearer of bad news, but there is further fallout from
the RTC changes in Xen 4.3 and Win2k3 guests.
Since updating to Xen 4.3 in XenServer trunk, we have been seeing these
issues a handful of times on each nightly test. We are currently
running stable-4.3 with no relevant patches in this area.
The issue exists solely with Win2k3 Enterprise Edition SP2 64bit, and
occurs sporadically in a simple reboot loop of the VM.
The VM sits at 100% CPU performing:
d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
d98v0 io write port 70 val c
d98v0 vmentry cycles 1944
d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
d98v0 io read port 71 val c0
d98v0 vmentry cycles 3120
I am attempting to narrow down which conditions cause it to fall into
this loop, but am really picking blindly at factors. One possibility is
the domain time offset being set to -24 seconds, but I cant immediately
see why that would have an effect.
I have attached xen-hvmctx from the affected domain, and do have one
example of a VM in this loop so can poke for other state, if there are
any sensible suggestions
~Andrew
[-- Attachment #2: hvmctx-98.log --]
[-- Type: text/x-log, Size: 11427 bytes --]
HVM save record for domain 98
Entry 0: type 1 instance 0, length 24
Header: magic 0x54381286, version 1
Xen changeset 0
CPUID[0][%eax] 0x000206d6
gtsc_khz 2300056
Entry 1: type 2 instance 0, length 1024
CPU: rax 0x000000000000000c rbx 0xfffff800013e66e1
rcx 0xfffff8000083f300 rdx 0x0000000000000070
rbp 0xfffff80000347440 rsi 0xfffff8000083f300
rdi 0xfffff80000092e10 rsp 0xfffff800003473b8
r8 0xfffff80001104720 r9 0xfffffadfe7b24248
r10 0x0000000000000001 r11 0x0000000000000002
r12 0x0000000000000100 r13 0x0000000000000021
r14 0x0000000000000001 r15 0x000000000000fffe
rip 0xfffff80000814177 rflags 0x0000000000000286
cr0 0x0000000080050031 cr2 0xfffffa8000001000
cr3 0x0000000000373000 cr4 0x00000000000006b8
dr0 0x0000000000000000 dr1 0x0000000000000000
dr2 0x0000000000000000 dr3 0x0000000000000000
dr6 0x00000000ffff0ff0 dr7 0x0000000000000400
cs 0x00000010 (0x0000000000000000 + 0x00000000 / 0x0029b)
ds 0x0000002b (0x0000000000000000 + 0xffffffff / 0x00cf3)
es 0x0000002b (0x0000000000000000 + 0xffffffff / 0x00cf3)
fs 0x00000053 (0x0000000000000000 + 0x00000fff / 0x004f3)
gs 0x00000000 (0xfffff80001177000 + 0x0000ffff / 0x00093)
ss 0x00000018 (0x0000000000000000 + 0xffffffff / 0x00c93)
tr 0x00000040 (0xfffff80000341070 + 0x00000068 / 0x0008b)
ldtr 0x00000000 (0x0000000000000000 + 0xffffffff / 0x00c00)
idtr (0xfffff80000340070 + 0x00000fff)
gdtr (0xfffff80000340000 + 0x0000006f)
sysenter cs 0x00000000 eip 0x0000000000000000 esp 0x0000000000000000
shadow gs 0xfffff80001177000
MSR flags 0x0000000000000007 lstar 0xfffff80001040f40
star 0x0023001000000000 cstar 0xfffff80001040cc0
sfmask 0x0000000000014700 efer 0x0000000000000d01
tsc 0x000051b50ead5129
event 0x00000000 error 0x00000000
FPU: fcw 0x037f fsw 0x0000
ftw 0x00 (0x00) fop 0x0000
fpuip 0x0000000000000000 fpudp 0x0000000000000000
mxcsr 0x00001f80 mask 0x0000ffff
mm0 0x00000000000000000000 (0x000000000000)
mm1 0x00000000000000000000 (0x000000000000)
mm2 0x00000000000000000000 (0x000000000000)
mm3 0x00000000000000000000 (0x000000000000)
mm4 0x00000000000000000000 (0x000000000000)
mm5 0x00000000000000000000 (0x000000000000)
mm6 0x00000000000000000000 (0x000000000000)
mm7 0x00000000000000000000 (0x000000000000)
xmm00 0x000000030000000000005f7d0000000b
xmm01 0x00000000000000000000000000000000
xmm02 0x00000000000000000000000000000000
xmm03 0x00000000000000000000000000000000
xmm04 0x00000000000000000000000000000000
xmm05 0x00000000000000000000000000000000
xmm06 0x050ee0e4050ee22c001b0004ffffffff
xmm07 0x776b3b90050ee5f400000000777b5a67
xmm08 0x00000000000000000000000000000000
xmm09 0x00000000000000000000000000000000
xmm10 0x00000000000000000000000000000000
xmm11 0x00000000000000000000000000000000
xmm12 0x00000000000000000000000000000000
xmm13 0x00000000000000000000000000000000
xmm14 0x00000000000000000000000000000000
xmm15 0x00000000000000000000000000000000
(0x00000000000000000000000000000000)
(0x00000000000000000000000000000000)
(0x00000000000000000000000000000000)
(0x00000000000000000000000000000000)
(0x00000000000000000000000000000000)
(0x04000000000000000000000000000000)
Entry 2: type 3 instance 0, length 8
PIC: IRQ base 0x30, irr 0x2, imr 0xff, isr 0
init_state 0, priority_add 0, readsel_isr 0, poll 0
auto_eoi 0, rotate_on_auto_eoi 0
special_fully_nested_mode 0, special_mask_mode 0
is_master 1, elcr 0x24, int_output 0
Entry 3: type 3 instance 1, length 8
PIC: IRQ base 0x38, irr 0x1, imr 0xff, isr 0
init_state 0, priority_add 0, readsel_isr 0, poll 0
auto_eoi 0, rotate_on_auto_eoi 0
special_fully_nested_mode 0, special_mask_mode 0
is_master 0, elcr 0xc, int_output 0
Entry 4: type 4 instance 0, length 400
IOAPIC: base_address 0xfec00000, ioregsel 0x20 id 0x1
pin 00: 0x00000000000107ff
pin 01: 0x00000000000100ff
pin 02: 0x00000000000100ff
pin 03: 0x00000000000100ff
pin 04: 0x00000000000100ff
pin 05: 0x00000000000100ff
pin 06: 0x00000000000100ff
pin 07: 0x00000000000100ff
pin 08: 0xff000000000000d1
pin 09: 0x00000000000100ff
pin 10: 0x00000000000100ff
pin 11: 0x00000000000100ff
pin 12: 0x00000000000100ff
pin 13: 0x00000000000100ff
pin 14: 0x00000000000100ff
pin 15: 0x00000000000100ff
pin 16: 0x00000000000100ff
pin 17: 0x00000000000100ff
pin 18: 0x00000000000100ff
pin 19: 0x00000000000100ff
pin 20: 0x00000000000100ff
pin 21: 0x00000000000100ff
pin 22: 0x00000000000100ff
pin 23: 0x00000000000100ff
pin 24: 0x00000000000100ff
pin 25: 0x00000000000100ff
pin 26: 0x00000000000100ff
pin 27: 0x00000000000100ff
pin 28: 0x00000000000100ff
pin 29: 0x00000000000100ff
pin 30: 0x00000000000100ff
pin 31: 0x00000000000100ff
pin 32: 0x00000000000100ff
pin 33: 0x00000000000100ff
pin 34: 0x00000000000100ff
pin 35: 0x00000000000100ff
pin 36: 0x00000000000100ff
pin 37: 0x00000000000100ff
pin 38: 0x00000000000100ff
pin 39: 0x00000000000100ff
pin 40: 0x00000000000100ff
pin 41: 0x00000000000100ff
pin 42: 0x00000000000100ff
pin 43: 0x00000000000100ff
pin 44: 0x00000000000100ff
pin 45: 0x00000000000100ff
pin 46: 0x00000000000100ff
pin 47: 0x00000000000100ff
Entry 5: type 5 instance 0, length 24
LAPIC: base_msr 0xfee00900, disabled 0, timer_divisor 0x1
Entry 6: type 6 instance 0, length 1024
LAPIC registers:
0x0000: 0x0000000000000000 0x0010: 0x0000000000000000
0x0020: 0x0000000000000000 0x0030: 0x0000000000050014
0x0040: 0x0000000000000000 0x0050: 0x0000000000000000
0x0060: 0x0000000000000000 0x0070: 0x0000000000000000
0x0080: 0x00000000000000d0 0x0090: 0x0000000000000000
0x00a0: 0x0000000000000000 0x00b0: 0x0000000000000000
0x00c0: 0x0000000000000000 0x00d0: 0x0000000001000000
0x00e0: 0x00000000ffffffff 0x00f0: 0x000000000000013f
0x0100: 0x0000000000000000 0x0110: 0x0000000000000000
0x0120: 0x0000000000000000 0x0130: 0x0000000000000000
0x0140: 0x0000000000000000 0x0150: 0x0000000000000000
0x0160: 0x0000000000020000 0x0170: 0x0000000000000000
0x0180: 0x0000000000000000 0x0190: 0x0000000000000000
0x01a0: 0x0000000000000000 0x01b0: 0x0000000000000000
0x01c0: 0x0000000000000000 0x01d0: 0x0000000000000000
0x01e0: 0x0000000000000000 0x01f0: 0x0000000000000000
0x0200: 0x0000000000000000 0x0210: 0x0000000000000000
0x0220: 0x0000000000000000 0x0230: 0x0000000000000000
0x0240: 0x0000000000000000 0x0250: 0x0000000000000000
0x0260: 0x0000000000020000 0x0270: 0x0000000000000000
0x0280: 0x0000000000000000 0x0290: 0x0000000000000000
0x02a0: 0x0000000000000000 0x02b0: 0x0000000000000000
0x02c0: 0x0000000000000000 0x02d0: 0x0000000000000000
0x02e0: 0x0000000000000000 0x02f0: 0x0000000000000000
0x0300: 0x0000000000088500 0x0310: 0x0000000000000000
0x0320: 0x00000000000300fd 0x0330: 0x0000000000010000
0x0340: 0x00000000000100fe 0x0350: 0x000000000001003f
0x0360: 0x00000000000184ff 0x0370: 0x00000000000000e3
0x0380: 0x0000000005f5e100 0x0390: 0x0000000000000000
0x03a0: 0x0000000000000000 0x03b0: 0x0000000000000000
0x03c0: 0x0000000000000000 0x03d0: 0x0000000000000000
0x03e0: 0x000000000000000b 0x03f0: 0x0000000000000000
Entry 7: type 7 instance 0, length 16
PCI IRQs: 0x00000000000000000000000000000000
Entry 8: type 8 instance 0, length 8
ISA IRQs: 0x0103
Entry 9: type 9 instance 0, length 8
PCI LINK: 5 10 11 5
Entry 10: type 10 instance 0, length 56
PIT: speaker off
ch 0: count 0xe90b, latched_count 0, count_latched 0
status 0, status_latched 0
rd_state 0x3, wr_state 0x3, wr_latch 0xb, rw_mode 0x3
mode 0x2, bcd 0, gate 0x1
ch 1: count 0x10000, latched_count 0, count_latched 0
status 0, status_latched 0
rd_state 0, wr_state 0, wr_latch 0, rw_mode 0
mode 0xff, bcd 0, gate 0x1
Entry 11: type 11 instance 0, length 16
RTC: regs 0x57 0x00 0x26 0x00 0x10 0x00 0x02 0x03
0x09 0x13 0xaa 0x42 0xc0 0x80, index 0x0c
Entry 12: type 12 instance 0, length 1048
HPET: capability 0xf424008086a201 config 0
isr 0 counter 0x238ae42679b
timer0 config 0xf0000000000030 cmp 0
timer0 period 0 fsb 0
timer1 config 0xf0000000000030 cmp 0
timer1 period 0 fsb 0
timer2 config 0xf0000000000030 cmp 0
timer2 period 0 fsb 0
Entry 13: type 13 instance 0, length 8
ACPI PM: TMR_VAL 0xffffffff, PM1a_STS 0x1, PM1a_EN 0x0
Entry 14: type 14 instance 0, length 240
MTRR: PAT 0x7010600070106, cap 0x508, default 0xc06
var 0 0x00000000f0000000 0x00003ffff8000800
var 1 0x00000000f8000000 0x00003ffffc000800
var 2 0x0000000000000000 0x0000000000000000
var 3 0x0000000000000000 0x0000000000000000
var 4 0x0000000000000000 0x0000000000000000
var 5 0x0000000000000000 0x0000000000000000
var 6 0x0000000000000000 0x0000000000000000
var 7 0x0000000000000000 0x0000000000000000
fixed 00 0x0606060606060606
fixed 01 0x0606060606060606
fixed 02 0x0101010101010101
fixed 03 0x0606060606060606
fixed 04 0x0606060606060606
fixed 05 0x0606060606060606
fixed 06 0x0606060606060606
fixed 07 0x0606060606060606
fixed 08 0x0606060606060606
fixed 09 0x0606060606060606
fixed 10 0x0606060606060606
Entry 15: type 15 instance 0, length 16
VIRIDIAN_DOMAIN: hypercall gpa 0x0, guest_os_id 0x0
Entry 16: type 17 instance 0, length 8
VIRIDIAN_VCPU: apic_assist 0x0
Entry 17: type 18 instance 0, length 24
VMCE_VCPU: caps 1000c02
VMCE_VCPU: bank0 mci_ctl2 0
VMCE_VCPU: bank1 mci_ctl2 0
Entry 18: type 19 instance 0, length 8
TSC_ADJUST: tsc_adjust ffe447c212ff9b35
Entry 19: type 0 instance 0, length 0
[-- Attachment #3: Type: text/plain, Size: 126 bytes --]
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: More RTC issues with Win2k3
2013-09-03 13:37 More RTC issues with Win2k3 Andrew Cooper
@ 2013-09-04 9:38 ` Jan Beulich
2013-09-04 12:34 ` Andrew Cooper
0 siblings, 1 reply; 7+ messages in thread
From: Jan Beulich @ 2013-09-04 9:38 UTC (permalink / raw)
To: Andrew Cooper; +Cc: Xen-devel List
>>> On 03.09.13 at 15:37, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> Since updating to Xen 4.3 in XenServer trunk, we have been seeing these
> issues a handful of times on each nightly test. We are currently
> running stable-4.3 with no relevant patches in this area.
>
> The issue exists solely with Win2k3 Enterprise Edition SP2 64bit, and
> occurs sporadically in a simple reboot loop of the VM.
>
> The VM sits at 100% CPU performing:
>
> d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> d98v0 io write port 70 val c
> d98v0 vmentry cycles 1944
> d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> d98v0 io read port 71 val c0
> d98v0 vmentry cycles 3120
>
> I am attempting to narrow down which conditions cause it to fall into
> this loop, but am really picking blindly at factors. One possibility is
> the domain time offset being set to -24 seconds, but I cant immediately
> see why that would have an effect.
So based on my code inspection last time I'd expect this to be a
tight loop in the RTC interrupt handler, waiting for REG_C to read
as zero.
Which raises two questions: Does that specific version of Windows
not honor the WAET flags saying that REG_C reads are unnecessary?
Or does this only occur during very early boot (where iirc a first,
temporary RTC interrupt handler gets installed for a very brief period
of time that doesn't pay attention to the WAET flag)?
> I have attached xen-hvmctx from the affected domain, and do have one
> example of a VM in this loop so can poke for other state, if there are
> any sensible suggestions
The REG_A value says 64Hz for the periodic interrupt if I'm not
mistaken, so RTC_PF getting re-set between two iterations would
first of all hint at a significantly overcommitted system (such that
no two iterations of the loop can complete within 1/64 second).
Jan
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: More RTC issues with Win2k3
2013-09-04 9:38 ` Jan Beulich
@ 2013-09-04 12:34 ` Andrew Cooper
2013-09-04 12:44 ` Jan Beulich
0 siblings, 1 reply; 7+ messages in thread
From: Andrew Cooper @ 2013-09-04 12:34 UTC (permalink / raw)
To: Jan Beulich; +Cc: Xen-devel List
On 04/09/13 10:38, Jan Beulich wrote:
>>>> On 03.09.13 at 15:37, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>> Since updating to Xen 4.3 in XenServer trunk, we have been seeing these
>> issues a handful of times on each nightly test. We are currently
>> running stable-4.3 with no relevant patches in this area.
>>
>> The issue exists solely with Win2k3 Enterprise Edition SP2 64bit, and
>> occurs sporadically in a simple reboot loop of the VM.
>>
>> The VM sits at 100% CPU performing:
>>
>> d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
>> d98v0 io write port 70 val c
>> d98v0 vmentry cycles 1944
>> d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
>> d98v0 io read port 71 val c0
>> d98v0 vmentry cycles 3120
>>
>> I am attempting to narrow down which conditions cause it to fall into
>> this loop, but am really picking blindly at factors. One possibility is
>> the domain time offset being set to -24 seconds, but I cant immediately
>> see why that would have an effect.
> So based on my code inspection last time I'd expect this to be a
> tight loop in the RTC interrupt handler, waiting for REG_C to read
> as zero.
The timing data and samples of %eip from xentrace would agree with your
expectation.
>
> Which raises two questions: Does that specific version of Windows
> not honor the WAET flags saying that REG_C reads are unnecessary?
> Or does this only occur during very early boot (where iirc a first,
> temporary RTC interrupt handler gets installed for a very brief period
> of time that doesn't pay attention to the WAET flag)?
When the VM falls into the loop, it is still in text mode with "Starting
windows..." and a block progress bar which is full. This means that
ntldr has finished loading the base drivers using int 13h. From
Xentrace, we do see that it is in 64 bit mode, so execution is probably
right at the beginning of the kernel, even before switching the VGA mode.
>
>> I have attached xen-hvmctx from the affected domain, and do have one
>> example of a VM in this loop so can poke for other state, if there are
>> any sensible suggestions
> The REG_A value says 64Hz for the periodic interrupt if I'm not
> mistaken, so RTC_PF getting re-set between two iterations would
> first of all hint at a significantly overcommitted system (such that
> no two iterations of the loop can complete within 1/64 second).
>
> Jan
>
This is part of our automatic testing. There are two VMs (32 and 64bit
variants) running the same set of tests, being basic lifecycle/migrate
etc loops. The hosts are not overcommitted in the slightest.
~Andrew
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: More RTC issues with Win2k3
2013-09-04 12:34 ` Andrew Cooper
@ 2013-09-04 12:44 ` Jan Beulich
2013-09-04 13:37 ` Andrew Cooper
0 siblings, 1 reply; 7+ messages in thread
From: Jan Beulich @ 2013-09-04 12:44 UTC (permalink / raw)
To: Andrew Cooper; +Cc: Xen-devel List
>>> On 04.09.13 at 14:34, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> On 04/09/13 10:38, Jan Beulich wrote:
>> Which raises two questions: Does that specific version of Windows
>> not honor the WAET flags saying that REG_C reads are unnecessary?
>> Or does this only occur during very early boot (where iirc a first,
>> temporary RTC interrupt handler gets installed for a very brief period
>> of time that doesn't pay attention to the WAET flag)?
>
> When the VM falls into the loop, it is still in text mode with "Starting
> windows..." and a block progress bar which is full. This means that
> ntldr has finished loading the base drivers using int 13h. From
> Xentrace, we do see that it is in 64 bit mode, so execution is probably
> right at the beginning of the kernel, even before switching the VGA mode.
So that might then be the early probing interrupt handler that I
had found they install transiently.
>>> I have attached xen-hvmctx from the affected domain, and do have one
>>> example of a VM in this loop so can poke for other state, if there are
>>> any sensible suggestions
>> The REG_A value says 64Hz for the periodic interrupt if I'm not
>> mistaken, so RTC_PF getting re-set between two iterations would
>> first of all hint at a significantly overcommitted system (such that
>> no two iterations of the loop can complete within 1/64 second).
>
> This is part of our automatic testing. There are two VMs (32 and 64bit
> variants) running the same set of tests, being basic lifecycle/migrate
> etc loops. The hosts are not overcommitted in the slightest.
In which case, unless there's some scheduler anomaly involved, I
see no explanation for the behavior.
Not knowing what precise data Xentrace produces - does that include
any timing information? If so, what's the smallest delta between two
of these REG_C reads?
Jan
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: More RTC issues with Win2k3
2013-09-04 12:44 ` Jan Beulich
@ 2013-09-04 13:37 ` Andrew Cooper
2013-09-04 14:13 ` Jan Beulich
2013-09-04 15:09 ` George Dunlap
0 siblings, 2 replies; 7+ messages in thread
From: Andrew Cooper @ 2013-09-04 13:37 UTC (permalink / raw)
To: Jan Beulich; +Cc: George Dunlap, Xen-devel List
On 04/09/13 13:44, Jan Beulich wrote:
>>>> On 04.09.13 at 14:34, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>> On 04/09/13 10:38, Jan Beulich wrote:
>>> Which raises two questions: Does that specific version of Windows
>>> not honor the WAET flags saying that REG_C reads are unnecessary?
>>> Or does this only occur during very early boot (where iirc a first,
>>> temporary RTC interrupt handler gets installed for a very brief period
>>> of time that doesn't pay attention to the WAET flag)?
>> When the VM falls into the loop, it is still in text mode with "Starting
>> windows..." and a block progress bar which is full. This means that
>> ntldr has finished loading the base drivers using int 13h. From
>> Xentrace, we do see that it is in 64 bit mode, so execution is probably
>> right at the beginning of the kernel, even before switching the VGA mode.
> So that might then be the early probing interrupt handler that I
> had found they install transiently.
>
>>>> I have attached xen-hvmctx from the affected domain, and do have one
>>>> example of a VM in this loop so can poke for other state, if there are
>>>> any sensible suggestions
>>> The REG_A value says 64Hz for the periodic interrupt if I'm not
>>> mistaken, so RTC_PF getting re-set between two iterations would
>>> first of all hint at a significantly overcommitted system (such that
>>> no two iterations of the loop can complete within 1/64 second).
>> This is part of our automatic testing. There are two VMs (32 and 64bit
>> variants) running the same set of tests, being basic lifecycle/migrate
>> etc loops. The hosts are not overcommitted in the slightest.
> In which case, unless there's some scheduler anomaly involved, I
> see no explanation for the behavior.
>
> Not knowing what precise data Xentrace produces - does that include
> any timing information? If so, what's the smallest delta between two
> of these REG_C reads?
>
> Jan
>
Yes. Here is a larger sample:
] 2.862018629 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
2.862018629 d98v0 io write port 70 val c
] 2.862019461 d98v0 vmentry cycles 1996
] 2.862019936 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
2.862019936 d98v0 io read port 71 val c0
] 2.862021275 d98v0 vmentry cycles 3214
] 2.862021752 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
2.862021752 d98v0 io write port 70 val c
] 2.862022560 d98v0 vmentry cycles 1938
] 2.862023068 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
2.862023068 d98v0 io read port 71 val c0
] 2.862024410 d98v0 vmentry cycles 3220
] 2.862024886 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
2.862024886 d98v0 io write port 70 val c
] 2.862025735 d98v0 vmentry cycles 2037
] 2.862026207 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
2.862026207 d98v0 io read port 71 val c0
] 2.862027537 d98v0 vmentry cycles 3190
] 2.862028012 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
2.862028012 d98v0 io write port 70 val c
] 2.862028854 d98v0 vmentry cycles 2021
] 2.862029322 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
2.862029322 d98v0 io read port 71 val c0
] 2.862030668 d98v0 vmentry cycles 3232
] 2.862031145 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
2.862031145 d98v0 io write port 70 val c
] 2.862031954 d98v0 vmentry cycles 1941
] 2.862032462 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
2.862032462 d98v0 io read port 71 val c0
] 2.862033762 d98v0 vmentry cycles 3118
] 2.862034233 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
2.862034233 d98v0 io write port 70 val c
] 2.862035082 d98v0 vmentry cycles 2036
] 2.862035558 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
2.862035558 d98v0 io read port 71 val c0
] 2.862036937 d98v0 vmentry cycles 3309
George will know for certain, but as far as I am aware, the timestamp
column is calculated from raw TSC counter values embedded in the trace
records.
Either way, it is on the order of 2 microseconds difference around
iterations of the loops, with a substantial proportion of that being
vmextry/vmexit.
As an easy starting point of reference, I will completely disable
writing the WAET table to see whether that makes a difference.
~Andrew
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: More RTC issues with Win2k3
2013-09-04 13:37 ` Andrew Cooper
@ 2013-09-04 14:13 ` Jan Beulich
2013-09-04 15:09 ` George Dunlap
1 sibling, 0 replies; 7+ messages in thread
From: Jan Beulich @ 2013-09-04 14:13 UTC (permalink / raw)
To: Andrew Cooper; +Cc: George Dunlap, Xen-devel List
>>> On 04.09.13 at 15:37, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
> On 04/09/13 13:44, Jan Beulich wrote:
>> Not knowing what precise data Xentrace produces - does that include
>> any timing information? If so, what's the smallest delta between two
>> of these REG_C reads?
>
> Yes. Here is a larger sample:
>
> ] 2.862018629 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862018629 d98v0 io write port 70 val c
> ] 2.862019461 d98v0 vmentry cycles 1996
> ] 2.862019936 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862019936 d98v0 io read port 71 val c0
> ] 2.862021275 d98v0 vmentry cycles 3214
> ] 2.862021752 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862021752 d98v0 io write port 70 val c
> ] 2.862022560 d98v0 vmentry cycles 1938
> ] 2.862023068 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862023068 d98v0 io read port 71 val c0
> ] 2.862024410 d98v0 vmentry cycles 3220
> ] 2.862024886 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862024886 d98v0 io write port 70 val c
> ] 2.862025735 d98v0 vmentry cycles 2037
> ] 2.862026207 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862026207 d98v0 io read port 71 val c0
> ] 2.862027537 d98v0 vmentry cycles 3190
> ] 2.862028012 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862028012 d98v0 io write port 70 val c
> ] 2.862028854 d98v0 vmentry cycles 2021
> ] 2.862029322 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862029322 d98v0 io read port 71 val c0
> ] 2.862030668 d98v0 vmentry cycles 3232
> ] 2.862031145 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862031145 d98v0 io write port 70 val c
> ] 2.862031954 d98v0 vmentry cycles 1941
> ] 2.862032462 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862032462 d98v0 io read port 71 val c0
> ] 2.862033762 d98v0 vmentry cycles 3118
> ] 2.862034233 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862034233 d98v0 io write port 70 val c
> ] 2.862035082 d98v0 vmentry cycles 2036
> ] 2.862035558 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862035558 d98v0 io read port 71 val c0
> ] 2.862036937 d98v0 vmentry cycles 3309
>
> George will know for certain, but as far as I am aware, the timestamp
> column is calculated from raw TSC counter values embedded in the trace
> records.
Given how close the entries are, it doesn't even matter whether
that's TSC ticks or nanoseconds - they're definitely way too close
together to represent a state that should be permitted to get
into with a periodic timer tick of 64Hz.
> As an easy starting point of reference, I will completely disable
> writing the WAET table to see whether that makes a difference.
That's going to be fruitless afaict - as said before, the early RTC
interrupt handler they install doesn't even look at the WAET info.
What you will want to check is the rate at which
rtc_periodic_interrupt() gets invoked in this case, as that's the only
place that can set RTC_PF (which you observe constantly set), and
how this (presumably) ends up being much faster than intended
(i.e. presumably some issue in pt_update_irq()).
Jan
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: More RTC issues with Win2k3
2013-09-04 13:37 ` Andrew Cooper
2013-09-04 14:13 ` Jan Beulich
@ 2013-09-04 15:09 ` George Dunlap
1 sibling, 0 replies; 7+ messages in thread
From: George Dunlap @ 2013-09-04 15:09 UTC (permalink / raw)
To: Andrew Cooper; +Cc: Jan Beulich, Xen-devel List
On 04/09/13 14:37, Andrew Cooper wrote:
> On 04/09/13 13:44, Jan Beulich wrote:
>>>>> On 04.09.13 at 14:34, Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>>> On 04/09/13 10:38, Jan Beulich wrote:
>>>> Which raises two questions: Does that specific version of Windows
>>>> not honor the WAET flags saying that REG_C reads are unnecessary?
>>>> Or does this only occur during very early boot (where iirc a first,
>>>> temporary RTC interrupt handler gets installed for a very brief period
>>>> of time that doesn't pay attention to the WAET flag)?
>>> When the VM falls into the loop, it is still in text mode with "Starting
>>> windows..." and a block progress bar which is full. This means that
>>> ntldr has finished loading the base drivers using int 13h. From
>>> Xentrace, we do see that it is in 64 bit mode, so execution is probably
>>> right at the beginning of the kernel, even before switching the VGA mode.
>> So that might then be the early probing interrupt handler that I
>> had found they install transiently.
>>
>>>>> I have attached xen-hvmctx from the affected domain, and do have one
>>>>> example of a VM in this loop so can poke for other state, if there are
>>>>> any sensible suggestions
>>>> The REG_A value says 64Hz for the periodic interrupt if I'm not
>>>> mistaken, so RTC_PF getting re-set between two iterations would
>>>> first of all hint at a significantly overcommitted system (such that
>>>> no two iterations of the loop can complete within 1/64 second).
>>> This is part of our automatic testing. There are two VMs (32 and 64bit
>>> variants) running the same set of tests, being basic lifecycle/migrate
>>> etc loops. The hosts are not overcommitted in the slightest.
>> In which case, unless there's some scheduler anomaly involved, I
>> see no explanation for the behavior.
>>
>> Not knowing what precise data Xentrace produces - does that include
>> any timing information? If so, what's the smallest delta between two
>> of these REG_C reads?
>>
>> Jan
>>
> Yes. Here is a larger sample:
>
> ] 2.862018629 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862018629 d98v0 io write port 70 val c
> ] 2.862019461 d98v0 vmentry cycles 1996
> ] 2.862019936 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862019936 d98v0 io read port 71 val c0
> ] 2.862021275 d98v0 vmentry cycles 3214
> ] 2.862021752 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862021752 d98v0 io write port 70 val c
> ] 2.862022560 d98v0 vmentry cycles 1938
> ] 2.862023068 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862023068 d98v0 io read port 71 val c0
> ] 2.862024410 d98v0 vmentry cycles 3220
> ] 2.862024886 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862024886 d98v0 io write port 70 val c
> ] 2.862025735 d98v0 vmentry cycles 2037
> ] 2.862026207 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862026207 d98v0 io read port 71 val c0
> ] 2.862027537 d98v0 vmentry cycles 3190
> ] 2.862028012 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862028012 d98v0 io write port 70 val c
> ] 2.862028854 d98v0 vmentry cycles 2021
> ] 2.862029322 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862029322 d98v0 io read port 71 val c0
> ] 2.862030668 d98v0 vmentry cycles 3232
> ] 2.862031145 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862031145 d98v0 io write port 70 val c
> ] 2.862031954 d98v0 vmentry cycles 1941
> ] 2.862032462 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862032462 d98v0 io read port 71 val c0
> ] 2.862033762 d98v0 vmentry cycles 3118
> ] 2.862034233 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814176
> 2.862034233 d98v0 io write port 70 val c
> ] 2.862035082 d98v0 vmentry cycles 2036
> ] 2.862035558 d98v0 vmexit exit_reason IO_INSTRUCTION eip fffff80000814177
> 2.862035558 d98v0 io read port 71 val c0
> ] 2.862036937 d98v0 vmentry cycles 3309
>
> George will know for certain, but as far as I am aware, the timestamp
> column is calculated from raw TSC counter values embedded in the trace
> records.
Yes, with the following caveats:
1. Not all records have timestamps; if a record does not have a
timestamp, the processing engine will use the most recent timestamp
available. vmexit and vmentry have timestamps, but records about
handling (such as the io record above) typically don't.
2. In order for the conversion from cycles to seconds to be accurate,
you have to specify the cpu hz of the processor on which the trace ran
when running xenalyze. If you don't specify anything, it will default
to 2GHz. This will produce results within 2x of being correct, and
therefore *qualitatively* similar.
If Andy has not specified the cpu hz, then the actual delta between
reads may be 0.5-2x what the trace shows, but still way too short for 64Hz.
-George
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2013-09-04 15:09 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-09-03 13:37 More RTC issues with Win2k3 Andrew Cooper
2013-09-04 9:38 ` Jan Beulich
2013-09-04 12:34 ` Andrew Cooper
2013-09-04 12:44 ` Jan Beulich
2013-09-04 13:37 ` Andrew Cooper
2013-09-04 14:13 ` Jan Beulich
2013-09-04 15:09 ` George Dunlap
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).