Re: More RTC issues with Win2k3

[George Dunlap <george.dunlap@eu.citrix.com>]

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