[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [Xen-devel] More RTC issues with Win2k3



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@xxxxxxxxxx> 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

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel


 


Rackspace

Lists.xenproject.org is hosted with RackSpace, monitoring our
servers 24x7x365 and backed by RackSpace's Fanatical Support®.