xen 4.11.4 incorrect (~3x) cpu frequency reported

xen 4.11.4 incorrect (~3x) cpu frequency reported

[James Dingwall]

Hi,

We have a system which intermittently starts up and reports an incorrect cpu frequency:

# grep -i mhz /var/log/kern.log 
Jul 14 17:47:47 dom0 kernel: [    0.000475] tsc: Detected 2194.846 MHz processor
Jul 14 22:03:37 dom0 kernel: [    0.000476] tsc: Detected 2194.878 MHz processor
Jul 14 23:05:13 dom0 kernel: [    0.000478] tsc: Detected 2194.848 MHz processor
Jul 14 23:20:47 dom0 kernel: [    0.000474] tsc: Detected 2194.856 MHz processor
Jul 14 23:57:39 dom0 kernel: [    0.000476] tsc: Detected 2194.906 MHz processor
Jul 15 01:04:09 dom0 kernel: [    0.000476] tsc: Detected 2194.858 MHz processor
Jul 15 01:27:15 dom0 kernel: [    0.000482] tsc: Detected 2194.870 MHz processor
Jul 15 02:00:13 dom0 kernel: [    0.000481] tsc: Detected 2194.924 MHz processor
Jul 15 03:09:23 dom0 kernel: [    0.000475] tsc: Detected 2194.892 MHz processor
Jul 15 03:32:50 dom0 kernel: [    0.000482] tsc: Detected 2194.856 MHz processor
Jul 15 04:05:27 dom0 kernel: [    0.000480] tsc: Detected 2194.886 MHz processor
Jul 15 05:00:38 dom0 kernel: [    0.000473] tsc: Detected 2194.914 MHz processor
Jul 15 05:59:33 dom0 kernel: [    0.000480] tsc: Detected 2194.924 MHz processor
Jul 15 06:22:31 dom0 kernel: [    0.000474] tsc: Detected 2194.910 MHz processor
Jul 15 17:52:57 dom0 kernel: [    0.000474] tsc: Detected 2194.854 MHz processor
Jul 15 18:51:36 dom0 kernel: [    0.000474] tsc: Detected 2194.900 MHz processor
Jul 15 19:07:26 dom0 kernel: [    0.000478] tsc: Detected 2194.902 MHz processor
Jul 15 19:43:56 dom0 kernel: [    0.000154] tsc: Detected 6895.384 MHz processor

The xen 's' debug output:

(XEN) TSC marked as reliable, warp = 0 (count=4)
(XEN) dom1: mode=0,ofs=0x1d1ac8bf8e,khz=6895385,inc=1
(XEN) dom2: mode=0,ofs=0x28bc24c746,khz=6895385,inc=1
(XEN) dom3: mode=0,ofs=0x345696b138,khz=6895385,inc=1
(XEN) dom4: mode=0,ofs=0x34f2635f31,khz=6895385,inc=1
(XEN) dom5: mode=0,ofs=0x3581618a7d,khz=6895385,inc=1
(XEN) dom6: mode=0,ofs=0x3627ca68b2,khz=6895385,inc=1
(XEN) dom7: mode=0,ofs=0x36dd491860,khz=6895385,inc=1
(XEN) dom8: mode=0,ofs=0x377a57ea1a,khz=6895385,inc=1
(XEN) dom9: mode=0,ofs=0x381eb175ce,khz=6895385,inc=1
(XEN) dom10: mode=0,ofs=0x38cab2e260,khz=6895385,inc=1
(XEN) dom11: mode=0,ofs=0x397fc47387,khz=6895385,inc=1
(XEN) dom12: mode=0,ofs=0x3a552762a0,khz=6895385,inc=1

A processor from /proc/cpuinfo in dom0:

processor       : 3
vendor_id       : GenuineIntel
cpu family      : 6
model           : 85
model name      : Intel(R) Xeon(R) D-2123IT CPU @ 2.20GHz
stepping        : 4
microcode       : 0x2000065
cpu MHz         : 6895.384
cache size      : 8448 KB
physical id     : 0
siblings        : 4
core id         : 0
cpu cores       : 1
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu de tsc msr pae mce cx8 apic sep mca cmov pat clflush acpi mmx fxsr sse sse2 ss ht syscall nx lm constant_tsc rep_good nopl nonstop_tsc cpuid pni pclmulqdq monitor est ssse3 fma cx16 sse4_1 sse4_2 movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch intel_ppin ssbd ibrs ibpb stibp fsgsbase bmi1 hle avx2 bmi2 erms rtm avx512f avx512dq rdseed adx clflushopt clwb avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 md_clear
bugs            : null_seg cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs taa itlb_multihit
bogomips        : 13790.76
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

Xen has been built at 310ab79875cb705cc2c7daddff412b5a4899f8c9 from the stable-4.12 branch.  The system is a supermicro server, model X11SDV-4C-TP8F.  I'm not sure if the incorrect value has been read from hardware or Xen has miscalculated the frequency so any pointers on things to examine would be welcome.

Thanks,
James

Re: xen 4.11.4 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 21.07.2021 11:29, James Dingwall wrote:
> We have a system which intermittently starts up and reports an incorrect cpu frequency:
> 
> # grep -i mhz /var/log/kern.log 
> Jul 14 17:47:47 dom0 kernel: [    0.000475] tsc: Detected 2194.846 MHz processor
> Jul 14 22:03:37 dom0 kernel: [    0.000476] tsc: Detected 2194.878 MHz processor
> Jul 14 23:05:13 dom0 kernel: [    0.000478] tsc: Detected 2194.848 MHz processor
> Jul 14 23:20:47 dom0 kernel: [    0.000474] tsc: Detected 2194.856 MHz processor
> Jul 14 23:57:39 dom0 kernel: [    0.000476] tsc: Detected 2194.906 MHz processor
> Jul 15 01:04:09 dom0 kernel: [    0.000476] tsc: Detected 2194.858 MHz processor
> Jul 15 01:27:15 dom0 kernel: [    0.000482] tsc: Detected 2194.870 MHz processor
> Jul 15 02:00:13 dom0 kernel: [    0.000481] tsc: Detected 2194.924 MHz processor
> Jul 15 03:09:23 dom0 kernel: [    0.000475] tsc: Detected 2194.892 MHz processor
> Jul 15 03:32:50 dom0 kernel: [    0.000482] tsc: Detected 2194.856 MHz processor
> Jul 15 04:05:27 dom0 kernel: [    0.000480] tsc: Detected 2194.886 MHz processor
> Jul 15 05:00:38 dom0 kernel: [    0.000473] tsc: Detected 2194.914 MHz processor
> Jul 15 05:59:33 dom0 kernel: [    0.000480] tsc: Detected 2194.924 MHz processor
> Jul 15 06:22:31 dom0 kernel: [    0.000474] tsc: Detected 2194.910 MHz processor
> Jul 15 17:52:57 dom0 kernel: [    0.000474] tsc: Detected 2194.854 MHz processor
> Jul 15 18:51:36 dom0 kernel: [    0.000474] tsc: Detected 2194.900 MHz processor
> Jul 15 19:07:26 dom0 kernel: [    0.000478] tsc: Detected 2194.902 MHz processor
> Jul 15 19:43:56 dom0 kernel: [    0.000154] tsc: Detected 6895.384 MHz processor

Well, this is output from Dom0. What we'd need to see (in addition)
is the corresponding hypervisor log at maximum verbosity (loglvl=all).

> The xen 's' debug output:
> 
> (XEN) TSC marked as reliable, warp = 0 (count=4)
> (XEN) dom1: mode=0,ofs=0x1d1ac8bf8e,khz=6895385,inc=1
> (XEN) dom2: mode=0,ofs=0x28bc24c746,khz=6895385,inc=1
> (XEN) dom3: mode=0,ofs=0x345696b138,khz=6895385,inc=1
> (XEN) dom4: mode=0,ofs=0x34f2635f31,khz=6895385,inc=1
> (XEN) dom5: mode=0,ofs=0x3581618a7d,khz=6895385,inc=1
> (XEN) dom6: mode=0,ofs=0x3627ca68b2,khz=6895385,inc=1
> (XEN) dom7: mode=0,ofs=0x36dd491860,khz=6895385,inc=1
> (XEN) dom8: mode=0,ofs=0x377a57ea1a,khz=6895385,inc=1
> (XEN) dom9: mode=0,ofs=0x381eb175ce,khz=6895385,inc=1
> (XEN) dom10: mode=0,ofs=0x38cab2e260,khz=6895385,inc=1
> (XEN) dom11: mode=0,ofs=0x397fc47387,khz=6895385,inc=1
> (XEN) dom12: mode=0,ofs=0x3a552762a0,khz=6895385,inc=1
> 
> A processor from /proc/cpuinfo in dom0:
> 
> processor       : 3
> vendor_id       : GenuineIntel
> cpu family      : 6
> model           : 85
> model name      : Intel(R) Xeon(R) D-2123IT CPU @ 2.20GHz
> stepping        : 4
> microcode       : 0x2000065
> cpu MHz         : 6895.384
> [...]
> 
> Xen has been built at 310ab79875cb705cc2c7daddff412b5a4899f8c9 from the stable-4.12 branch.

While this contradicts the title, both 4.11 and 4.12 are out of general
support. Hence it would be more helpful if you could obtain respective
logs with a more modern version of Xen - ideally from the master branch,
or else the most recent stable one (4.15). Provided of course the issue
continues to exist there in the first place.

Jan

Re: xen 4.11.4 incorrect (~3x) cpu frequency reported

[James Dingwall]

Hi Jan,

Thank you for taking the time to reply.

On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:
> On 21.07.2021 11:29, James Dingwall wrote:
> > We have a system which intermittently starts up and reports an incorrect cpu frequency:
> > 
> > # grep -i mhz /var/log/kern.log 
> > Jul 14 17:47:47 dom0 kernel: [    0.000475] tsc: Detected 2194.846 MHz processor
> > Jul 14 22:03:37 dom0 kernel: [    0.000476] tsc: Detected 2194.878 MHz processor
> > Jul 14 23:05:13 dom0 kernel: [    0.000478] tsc: Detected 2194.848 MHz processor
> > Jul 14 23:20:47 dom0 kernel: [    0.000474] tsc: Detected 2194.856 MHz processor
> > Jul 14 23:57:39 dom0 kernel: [    0.000476] tsc: Detected 2194.906 MHz processor
> > Jul 15 01:04:09 dom0 kernel: [    0.000476] tsc: Detected 2194.858 MHz processor
> > Jul 15 01:27:15 dom0 kernel: [    0.000482] tsc: Detected 2194.870 MHz processor
> > Jul 15 02:00:13 dom0 kernel: [    0.000481] tsc: Detected 2194.924 MHz processor
> > Jul 15 03:09:23 dom0 kernel: [    0.000475] tsc: Detected 2194.892 MHz processor
> > Jul 15 03:32:50 dom0 kernel: [    0.000482] tsc: Detected 2194.856 MHz processor
> > Jul 15 04:05:27 dom0 kernel: [    0.000480] tsc: Detected 2194.886 MHz processor
> > Jul 15 05:00:38 dom0 kernel: [    0.000473] tsc: Detected 2194.914 MHz processor
> > Jul 15 05:59:33 dom0 kernel: [    0.000480] tsc: Detected 2194.924 MHz processor
> > Jul 15 06:22:31 dom0 kernel: [    0.000474] tsc: Detected 2194.910 MHz processor
> > Jul 15 17:52:57 dom0 kernel: [    0.000474] tsc: Detected 2194.854 MHz processor
> > Jul 15 18:51:36 dom0 kernel: [    0.000474] tsc: Detected 2194.900 MHz processor
> > Jul 15 19:07:26 dom0 kernel: [    0.000478] tsc: Detected 2194.902 MHz processor
> > Jul 15 19:43:56 dom0 kernel: [    0.000154] tsc: Detected 6895.384 MHz processor
> 
> Well, this is output from Dom0. What we'd need to see (in addition)
> is the corresponding hypervisor log at maximum verbosity (loglvl=all).

This was just to illustrate that the dom0 usually reports the correct speed.  I'll update the xen boot options with loglvl=all and try to collect the boot messages for each case.

> 
> > The xen 's' debug output:
> > 
> > (XEN) TSC marked as reliable, warp = 0 (count=4)
> > (XEN) dom1: mode=0,ofs=0x1d1ac8bf8e,khz=6895385,inc=1
> > (XEN) dom2: mode=0,ofs=0x28bc24c746,khz=6895385,inc=1
> > (XEN) dom3: mode=0,ofs=0x345696b138,khz=6895385,inc=1
> > (XEN) dom4: mode=0,ofs=0x34f2635f31,khz=6895385,inc=1
> > (XEN) dom5: mode=0,ofs=0x3581618a7d,khz=6895385,inc=1
> > (XEN) dom6: mode=0,ofs=0x3627ca68b2,khz=6895385,inc=1
> > (XEN) dom7: mode=0,ofs=0x36dd491860,khz=6895385,inc=1
> > (XEN) dom8: mode=0,ofs=0x377a57ea1a,khz=6895385,inc=1
> > (XEN) dom9: mode=0,ofs=0x381eb175ce,khz=6895385,inc=1
> > (XEN) dom10: mode=0,ofs=0x38cab2e260,khz=6895385,inc=1
> > (XEN) dom11: mode=0,ofs=0x397fc47387,khz=6895385,inc=1
> > (XEN) dom12: mode=0,ofs=0x3a552762a0,khz=6895385,inc=1
> > 
> > A processor from /proc/cpuinfo in dom0:
> > 
> > processor       : 3
> > vendor_id       : GenuineIntel
> > cpu family      : 6
> > model           : 85
> > model name      : Intel(R) Xeon(R) D-2123IT CPU @ 2.20GHz
> > stepping        : 4
> > microcode       : 0x2000065
> > cpu MHz         : 6895.384
> > [...]
> > 
> > Xen has been built at 310ab79875cb705cc2c7daddff412b5a4899f8c9 from the stable-4.12 branch.
> 
> While this contradicts the title, both 4.11 and 4.12 are out of general
> support. Hence it would be more helpful if you could obtain respective
> logs with a more modern version of Xen - ideally from the master branch,
> or else the most recent stable one (4.15). Provided of course the issue
> continues to exist there in the first place.

That was my error, I meant the stable-4.11 branch.  We have a development environment based around 4.14.2 which I can test.  My assumption had been that xen reads or calculates this frequency and provides it to the dom0 since it is reported in the hypervisor log before dom0 is started.

Regards,
James

Re: xen 4.11.4 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 26.07.2021 14:33, James Dingwall wrote:
> Hi Jan,
> 
> Thank you for taking the time to reply.
> 
> On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:
>> On 21.07.2021 11:29, James Dingwall wrote:
>>> We have a system which intermittently starts up and reports an incorrect cpu frequency:
>>>
>>> # grep -i mhz /var/log/kern.log 
>>> Jul 14 17:47:47 dom0 kernel: [    0.000475] tsc: Detected 2194.846 MHz processor
>>> Jul 14 22:03:37 dom0 kernel: [    0.000476] tsc: Detected 2194.878 MHz processor
>>> Jul 14 23:05:13 dom0 kernel: [    0.000478] tsc: Detected 2194.848 MHz processor
>>> Jul 14 23:20:47 dom0 kernel: [    0.000474] tsc: Detected 2194.856 MHz processor
>>> Jul 14 23:57:39 dom0 kernel: [    0.000476] tsc: Detected 2194.906 MHz processor
>>> Jul 15 01:04:09 dom0 kernel: [    0.000476] tsc: Detected 2194.858 MHz processor
>>> Jul 15 01:27:15 dom0 kernel: [    0.000482] tsc: Detected 2194.870 MHz processor
>>> Jul 15 02:00:13 dom0 kernel: [    0.000481] tsc: Detected 2194.924 MHz processor
>>> Jul 15 03:09:23 dom0 kernel: [    0.000475] tsc: Detected 2194.892 MHz processor
>>> Jul 15 03:32:50 dom0 kernel: [    0.000482] tsc: Detected 2194.856 MHz processor
>>> Jul 15 04:05:27 dom0 kernel: [    0.000480] tsc: Detected 2194.886 MHz processor
>>> Jul 15 05:00:38 dom0 kernel: [    0.000473] tsc: Detected 2194.914 MHz processor
>>> Jul 15 05:59:33 dom0 kernel: [    0.000480] tsc: Detected 2194.924 MHz processor
>>> Jul 15 06:22:31 dom0 kernel: [    0.000474] tsc: Detected 2194.910 MHz processor
>>> Jul 15 17:52:57 dom0 kernel: [    0.000474] tsc: Detected 2194.854 MHz processor
>>> Jul 15 18:51:36 dom0 kernel: [    0.000474] tsc: Detected 2194.900 MHz processor
>>> Jul 15 19:07:26 dom0 kernel: [    0.000478] tsc: Detected 2194.902 MHz processor
>>> Jul 15 19:43:56 dom0 kernel: [    0.000154] tsc: Detected 6895.384 MHz processor
>>
>> Well, this is output from Dom0. What we'd need to see (in addition)
>> is the corresponding hypervisor log at maximum verbosity (loglvl=all).
> 
> This was just to illustrate that the dom0 usually reports the correct speed.  I'll update the xen boot options with loglvl=all and try to collect the boot messages for each case.
> 
>>
>>> The xen 's' debug output:
>>>
>>> (XEN) TSC marked as reliable, warp = 0 (count=4)
>>> (XEN) dom1: mode=0,ofs=0x1d1ac8bf8e,khz=6895385,inc=1
>>> (XEN) dom2: mode=0,ofs=0x28bc24c746,khz=6895385,inc=1
>>> (XEN) dom3: mode=0,ofs=0x345696b138,khz=6895385,inc=1
>>> (XEN) dom4: mode=0,ofs=0x34f2635f31,khz=6895385,inc=1
>>> (XEN) dom5: mode=0,ofs=0x3581618a7d,khz=6895385,inc=1
>>> (XEN) dom6: mode=0,ofs=0x3627ca68b2,khz=6895385,inc=1
>>> (XEN) dom7: mode=0,ofs=0x36dd491860,khz=6895385,inc=1
>>> (XEN) dom8: mode=0,ofs=0x377a57ea1a,khz=6895385,inc=1
>>> (XEN) dom9: mode=0,ofs=0x381eb175ce,khz=6895385,inc=1
>>> (XEN) dom10: mode=0,ofs=0x38cab2e260,khz=6895385,inc=1
>>> (XEN) dom11: mode=0,ofs=0x397fc47387,khz=6895385,inc=1
>>> (XEN) dom12: mode=0,ofs=0x3a552762a0,khz=6895385,inc=1
>>>
>>> A processor from /proc/cpuinfo in dom0:
>>>
>>> processor       : 3
>>> vendor_id       : GenuineIntel
>>> cpu family      : 6
>>> model           : 85
>>> model name      : Intel(R) Xeon(R) D-2123IT CPU @ 2.20GHz
>>> stepping        : 4
>>> microcode       : 0x2000065
>>> cpu MHz         : 6895.384
>>> [...]
>>>
>>> Xen has been built at 310ab79875cb705cc2c7daddff412b5a4899f8c9 from the stable-4.12 branch.
>>
>> While this contradicts the title, both 4.11 and 4.12 are out of general
>> support. Hence it would be more helpful if you could obtain respective
>> logs with a more modern version of Xen - ideally from the master branch,
>> or else the most recent stable one (4.15). Provided of course the issue
>> continues to exist there in the first place.
> 
> That was my error, I meant the stable-4.11 branch.  We have a development environment based around 4.14.2 which I can test.

I'm sorry to ask, but have you got around to actually doing that? Or
else is resolving this no longer of interest?

Jan

Re: xen 4.11.4 incorrect (~3x) cpu frequency reported

[James Dingwall]

Hi Jan,

On Fri, Nov 05, 2021 at 01:50:04PM +0100, Jan Beulich wrote:
> On 26.07.2021 14:33, James Dingwall wrote:
> > Hi Jan,
> > 
> > Thank you for taking the time to reply.
> > 
> > On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:
> >> On 21.07.2021 11:29, James Dingwall wrote:
> >>> We have a system which intermittently starts up and reports an incorrect cpu frequency:
> >>>
> >>> # grep -i mhz /var/log/kern.log 
> >>> Jul 14 17:47:47 dom0 kernel: [    0.000475] tsc: Detected 2194.846 MHz processor
> >>> Jul 14 22:03:37 dom0 kernel: [    0.000476] tsc: Detected 2194.878 MHz processor
> >>> Jul 14 23:05:13 dom0 kernel: [    0.000478] tsc: Detected 2194.848 MHz processor
> >>> Jul 14 23:20:47 dom0 kernel: [    0.000474] tsc: Detected 2194.856 MHz processor
> >>> Jul 14 23:57:39 dom0 kernel: [    0.000476] tsc: Detected 2194.906 MHz processor
> >>> Jul 15 01:04:09 dom0 kernel: [    0.000476] tsc: Detected 2194.858 MHz processor
> >>> Jul 15 01:27:15 dom0 kernel: [    0.000482] tsc: Detected 2194.870 MHz processor
> >>> Jul 15 02:00:13 dom0 kernel: [    0.000481] tsc: Detected 2194.924 MHz processor
> >>> Jul 15 03:09:23 dom0 kernel: [    0.000475] tsc: Detected 2194.892 MHz processor
> >>> Jul 15 03:32:50 dom0 kernel: [    0.000482] tsc: Detected 2194.856 MHz processor
> >>> Jul 15 04:05:27 dom0 kernel: [    0.000480] tsc: Detected 2194.886 MHz processor
> >>> Jul 15 05:00:38 dom0 kernel: [    0.000473] tsc: Detected 2194.914 MHz processor
> >>> Jul 15 05:59:33 dom0 kernel: [    0.000480] tsc: Detected 2194.924 MHz processor
> >>> Jul 15 06:22:31 dom0 kernel: [    0.000474] tsc: Detected 2194.910 MHz processor
> >>> Jul 15 17:52:57 dom0 kernel: [    0.000474] tsc: Detected 2194.854 MHz processor
> >>> Jul 15 18:51:36 dom0 kernel: [    0.000474] tsc: Detected 2194.900 MHz processor
> >>> Jul 15 19:07:26 dom0 kernel: [    0.000478] tsc: Detected 2194.902 MHz processor
> >>> Jul 15 19:43:56 dom0 kernel: [    0.000154] tsc: Detected 6895.384 MHz processor
> >>
> >> Well, this is output from Dom0. What we'd need to see (in addition)
> >> is the corresponding hypervisor log at maximum verbosity (loglvl=all).
> > 
> > This was just to illustrate that the dom0 usually reports the correct speed.  I'll update the xen boot options with loglvl=all and try to collect the boot messages for each case.
> > 
> >>
> >>> The xen 's' debug output:
> >>>
> >>> (XEN) TSC marked as reliable, warp = 0 (count=4)
> >>> (XEN) dom1: mode=0,ofs=0x1d1ac8bf8e,khz=6895385,inc=1
> >>> (XEN) dom2: mode=0,ofs=0x28bc24c746,khz=6895385,inc=1
> >>> (XEN) dom3: mode=0,ofs=0x345696b138,khz=6895385,inc=1
> >>> (XEN) dom4: mode=0,ofs=0x34f2635f31,khz=6895385,inc=1
> >>> (XEN) dom5: mode=0,ofs=0x3581618a7d,khz=6895385,inc=1
> >>> (XEN) dom6: mode=0,ofs=0x3627ca68b2,khz=6895385,inc=1
> >>> (XEN) dom7: mode=0,ofs=0x36dd491860,khz=6895385,inc=1
> >>> (XEN) dom8: mode=0,ofs=0x377a57ea1a,khz=6895385,inc=1
> >>> (XEN) dom9: mode=0,ofs=0x381eb175ce,khz=6895385,inc=1
> >>> (XEN) dom10: mode=0,ofs=0x38cab2e260,khz=6895385,inc=1
> >>> (XEN) dom11: mode=0,ofs=0x397fc47387,khz=6895385,inc=1
> >>> (XEN) dom12: mode=0,ofs=0x3a552762a0,khz=6895385,inc=1
> >>>
> >>> A processor from /proc/cpuinfo in dom0:
> >>>
> >>> processor       : 3
> >>> vendor_id       : GenuineIntel
> >>> cpu family      : 6
> >>> model           : 85
> >>> model name      : Intel(R) Xeon(R) D-2123IT CPU @ 2.20GHz
> >>> stepping        : 4
> >>> microcode       : 0x2000065
> >>> cpu MHz         : 6895.384
> >>> [...]
> >>>
> >>> Xen has been built at 310ab79875cb705cc2c7daddff412b5a4899f8c9 from the stable-4.12 branch.
> >>
> >> While this contradicts the title, both 4.11 and 4.12 are out of general
> >> support. Hence it would be more helpful if you could obtain respective
> >> logs with a more modern version of Xen - ideally from the master branch,
> >> or else the most recent stable one (4.15). Provided of course the issue
> >> continues to exist there in the first place.
> > 
> > That was my error, I meant the stable-4.11 branch.  We have a development environment based around 4.14.2 which I can test.
> 
> I'm sorry to ask, but have you got around to actually doing that? Or
> else is resolving this no longer of interest?

We have recorded a couple of other occurences on 4.11 but it is happening so
infrequently (probably once every few hundred boots) that further investigation
is low on a long list of tasks.  We are also moving to 4.14.3 and so far have
no occurences with that version.

Thanks,
James

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[James Dingwall]

[-- Attachment #1: Type: text/plain, Size: 1949 bytes --]

Hi Jan,

> > On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:                                                                            
> >> On 21.07.2021 11:29, James Dingwall wrote:                                                                                             
> >>> We have a system which intermittently starts up and reports an incorrect cpu frequency:                                               
...
> > I'm sorry to ask, but have you got around to actually doing that? Or
> > else is resolving this no longer of interest?

We have experienced an occurence of this issue on 4.14.3 with 'loglvl=all'
present on the xen command line.  I have attached the 'xl dmesg' output for
the fast MHz boot, the diff from the normal case is small so I've not added
that log separately:

--- normal-mhz/xl-dmesg.txt     2022-01-06 14:13:47.231465234 +0000
+++ funny-mhz/xl-dmesg.txt      2022-01-06 13:45:43.825148510 +0000
@@ -211,7 +211,7 @@
 (XEN)  cap enforcement granularity: 10ms
 (XEN) load tracking window length 1073741824 ns
 (XEN) Platform timer is 24.000MHz HPET
-(XEN) Detected 2294.639 MHz processor.
+(XEN) Detected 7623.412 MHz processor.
 (XEN) EFI memory map:
 (XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
 (XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f
@@ -616,6 +616,7 @@
 (XEN) PCI add device 0000:b7:00.1
 (XEN) PCI add device 0000:b7:00.2
 (XEN) PCI add device 0000:b7:00.3
+(XEN) Platform timer appears to have unexpectedly wrapped 10 or more times.
 (XEN) [VT-D]d0:PCIe: unmap 0000:65:00.2
 (XEN) [VT-D]d32753:PCIe: map 0000:65:00.2
 (XEN) [VT-D]d0:PCIe: unmap 0000:65:00.1

I also have the dom0 kernel dmesg available if that would be useful but I've
left it off initially because the log is quite large.  I don't see much in
the diff between boots except where speed/times are reported and where things
are initialised in a slightly different order.

Thanks,
James

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: xl-dmesg.txt --]
[-- Type: text/plain; charset=utf-8, Size: 28503 bytes --]

(XEN) parameter "basevideo" unknown!
 Xen 4.14.3
(XEN) Xen version 4.14.3 (@) (gcc (Ubuntu 10.3.0-1ubuntu1~20.04) 10.3.0) debug=n  Fri Dec 10 16:11:21 UTC 2021
(XEN) Latest ChangeSet: Fri Dec 10 16:10:15 2021 +0000 git:a598336409-dirty
(XEN) build-id: 7b441504c9977229a3c6779041ea6493
(XEN) Bootloader: EFI
(XEN) Command line: console=vga,com2 com2=115200,8n1 basevideo dom0_max_vcpus=4 dom0_mem=min:6144,max:65536m iommu=on,required,intpost,verbose,debug sched=credit2 flask=enforcing gnttab_max_frames=128 xpti=off smt=on loglvl=all
(XEN) Xen image load base address: 0x5d400000
(XEN) Video information:
(XEN)  VGA is graphics mode 1024x768, 32 bpp
(XEN) Disc information:
(XEN)  Found 0 MBR signatures
(XEN)  Found 2 EDD information structures
(XEN) CPU Vendor: Intel, Family 6 (0x6), Model 85 (0x55), Stepping 4 (raw 00050654)
(XEN) EFI RAM map:
(XEN)  [0000000000000000, 000000000009ffff] (usable)
(XEN)  [00000000000a0000, 00000000000fffff] (reserved)
(XEN)  [0000000000100000, 000000006965efff] (usable)
(XEN)  [000000006965f000, 000000006bee5fff] (reserved)
(XEN)  [000000006bee6000, 000000006c0a6fff] (usable)
(XEN)  [000000006c0a7000, 000000006ca43fff] (ACPI NVS)
(XEN)  [000000006ca44000, 000000006ed16fff] (reserved)
(XEN)  [000000006ed17000, 000000006fffffff] (usable)
(XEN)  [0000000070000000, 000000008fffffff] (reserved)
(XEN)  [00000000fd000000, 00000000fe7fffff] (reserved)
(XEN)  [00000000fed20000, 00000000fed44fff] (reserved)
(XEN)  [00000000ff000000, 00000000ffffffff] (reserved)
(XEN)  [0000000100000000, 000000207fffffff] (usable)
(XEN) ACPI: RSDP 6C0A7000, 0024 (r2 SUPERM)
(XEN) ACPI: XSDT 6C0A70C8, 0114 (r1 SUPERM   SUPERM  1072009 AMI     10013)
(XEN) ACPI: FACP 6C0E9D78, 0114 (r6 SUPERM SMCI--MB  1072009 INTL 20091013)
(XEN) ACPI: DSDT 6C0A7278, 42AFC (r2 SUPERM SMCI--MB  1072009 INTL 20091013)
(XEN) ACPI: FACS 6CA42080, 0040
(XEN) ACPI: FPDT 6C0E9E90, 0044 (r1                  1072009 AMI     10013)
(XEN) ACPI: FIDT 6C0E9ED8, 009C (r1 SUPERM SMCI--MB  1072009 AMI     10013)
(XEN) ACPI: SPMI 6C0E9F78, 0041 (r5 SUPERM SMCI--MB        0 AMI.        0)
(XEN) ACPI: UEFI 6C0E9FC0, 0048 (r1 SUPERM SMCI--MB  1072009       1000013)
(XEN) ACPI: UEFI 6C0EA008, 005C (r1  INTEL RstUefiV        0             0)
(XEN) ACPI: MCFG 6C0EA068, 003C (r1 SUPERM SMCI--MB  1072009 MSFT       97)
(XEN) ACPI: HPET 6C0EA0A8, 0038 (r1 SUPERM SMCI--MB        1 INTL 20091013)
(XEN) ACPI: APIC 6C0EA0E0, 071E (r3 SUPERM SMCI--MB        0 INTL 20091013)
(XEN) ACPI: MIGT 6C0EA800, 0040 (r1 SUPERM SMCI--MB        0 INTL 20091013)
(XEN) ACPI: MSCT 6C0EA840, 004E (r1 SUPERM SMCI--MB        1 INTL 20091013)
(XEN) ACPI: PCAT 6C0EA890, 0068 (r2 SUPERM SMCI--MB        2 INTL 20091013)
(XEN) ACPI: PCCT 6C0EA8F8, 006E (r1 SUPERM SMCI--MB        2 INTL 20091013)
(XEN) ACPI: RASF 6C0EA968, 0030 (r1 SUPERM SMCI--MB        1 INTL 20091013)
(XEN) ACPI: SLIT 6C0EA998, 002D (r1 SUPERM SMCI--MB        1 INTL 20091013)
(XEN) ACPI: SRAT 6C0EA9C8, 0A30 (r3 SUPERM SMCI--MB        2 INTL 20091013)
(XEN) ACPI: SVOS 6C0EB3F8, 0032 (r1 SUPERM SMCI--MB        0 INTL 20091013)
(XEN) ACPI: WDDT 6C0EB430, 0040 (r1 SUPERM SMCI--MB        0 INTL 20091013)
(XEN) ACPI: OEM4 6C0EB470, 28A0C (r2  INTEL CPU  CST     3000 INTL 20140828)
(XEN) ACPI: OEM1 6C113E80, A8CC (r2  INTEL CPU EIST     3000 INTL 20140828)
(XEN) ACPI: SSDT 6C11E750, CEB8 (r2  INTEL SSDT  PM     4000 INTL 20140828)
(XEN) ACPI: SSDT 6C12B608, 065B (r2 SUPERM SMCI--MB        0 INTL 20091013)
(XEN) ACPI: BGRT 6C12BC68, 0038 (r1 SUPERM SMCI--MB  1072009 AMI     10013)
(XEN) ACPI: SSDT 6C12BCA0, 1368 (r2  INTEL SpsNm           2 INTL 20140828)
(XEN) ACPI: DMAR 6C12D008, 0138 (r1 SUPERM SMCI--MB        1 INTL 20091013)
(XEN) ACPI: HEST 6C12D140, 00A8 (r1 SUPERM SMCI--MB        1 INTL        1)
(XEN) ACPI: BERT 6C12D1E8, 0030 (r1 SUPERM SMCI--MB        1 INTL        1)
(XEN) ACPI: ERST 6C12D218, 0230 (r1 SUPERM SMCI--MB        1 INTL        1)
(XEN) ACPI: EINJ 6C12D448, 0150 (r1 SUPERM SMCI--MB        1 INTL        1)
(XEN) ACPI: WSMT 6C12D598, 0028 (r1     ën           1072009 AMI     10013)
(XEN) System RAM: 130730MB (133868196kB)
(XEN) SRAT: PXM 0 -> APIC 00000000 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000002 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000004 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000006 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000008 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 0000000a -> Node 0
(XEN) SRAT: PXM 0 -> APIC 0000000c -> Node 0
(XEN) SRAT: PXM 0 -> APIC 0000000e -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000001 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000003 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000005 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000007 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 00000009 -> Node 0
(XEN) SRAT: PXM 0 -> APIC 0000000b -> Node 0
(XEN) SRAT: PXM 0 -> APIC 0000000d -> Node 0
(XEN) SRAT: PXM 0 -> APIC 0000000f -> Node 0
(XEN) SRAT: Node 0 PXM 0 0-80000000
(XEN) SRAT: Node 0 PXM 0 100000000-2080000000
(XEN) NUMA: Using 20 for the hash shift.
(XEN) Domain heap initialised
(XEN) vesafb: framebuffer at 0x00000000a9000000, mapped to 0xffff82c000201000, using 3072k, total 3072k
(XEN) vesafb: mode is 1024x768x32, linelength=4096, font 8x14
(XEN) vesafb: Truecolor: size=8:8:8:8, shift=24:16:8:0
(XEN) SMBIOS 3.1 present.
(XEN) x2APIC mode is already enabled by BIOS.
(XEN) Using APIC driver x2apic_cluster
(XEN) XSM Framework v1.0.0 initialized
(XEN) Policy len 0x33a8, start at ffff83207fffc000.
(XEN) Flask: 128 avtab hash slots, 454 rules.
(XEN) Flask: 128 avtab hash slots, 454 rules.
(XEN) Flask:  4 users, 3 roles, 45 types, 2 bools
(XEN) Flask:  13 classes, 454 rules
(XEN) Flask:  Starting in enforcing mode.
(XEN) ACPI: PM-Timer IO Port: 0x508 (24 bits)
(XEN) ACPI: v5 SLEEP INFO: control[0:0], status[0:0]
(XEN) ACPI: SLEEP INFO: pm1x_cnt[1:504,1:0], pm1x_evt[1:500,1:0]
(XEN) ACPI: 32/64X FACS address mismatch in FADT - 6ca42080/0000000000000000, using 32
(XEN) ACPI:             wakeup_vec[6ca4208c], vec_size[20]
(XEN) ACPI: Local APIC address 0xfee00000
(XEN) ACPI: X2APIC (apic_id[0x00] uid[0x00] enabled)
(XEN) ACPI: X2APIC (apic_id[0x02] uid[0x02] enabled)
(XEN) ACPI: X2APIC (apic_id[0x04] uid[0x04] enabled)
(XEN) ACPI: X2APIC (apic_id[0x06] uid[0x06] enabled)
(XEN) ACPI: X2APIC (apic_id[0x08] uid[0x08] enabled)
(XEN) ACPI: X2APIC (apic_id[0x0a] uid[0x0a] enabled)
(XEN) ACPI: X2APIC (apic_id[0x0c] uid[0x0c] enabled)
(XEN) ACPI: X2APIC (apic_id[0x0e] uid[0x0e] enabled)
(XEN) ACPI: X2APIC (apic_id[0x01] uid[0x01] enabled)
(XEN) ACPI: X2APIC (apic_id[0x03] uid[0x03] enabled)
(XEN) ACPI: X2APIC (apic_id[0x05] uid[0x05] enabled)
(XEN) ACPI: X2APIC (apic_id[0x07] uid[0x07] enabled)
(XEN) ACPI: X2APIC (apic_id[0x09] uid[0x09] enabled)
(XEN) ACPI: X2APIC (apic_id[0x0b] uid[0x0b] enabled)
(XEN) ACPI: X2APIC (apic_id[0x0d] uid[0x0d] enabled)
(XEN) ACPI: X2APIC (apic_id[0x0f] uid[0x0f] enabled)
(XEN) ACPI: LAPIC_NMI (acpi_id[0xff] high level lint[0x1])
(XEN) ACPI: X2APIC_NMI (uid[0xffffffff] high level lint[0x1])
(XEN) ACPI: IOAPIC (id[0x08] address[0xfec00000] gsi_base[0])
(XEN) IOAPIC[0]: apic_id 8, version 32, address 0xfec00000, GSI 0-23
(XEN) ACPI: IOAPIC (id[0x09] address[0xfec01000] gsi_base[24])
(XEN) IOAPIC[1]: apic_id 9, version 32, address 0xfec01000, GSI 24-31
(XEN) ACPI: IOAPIC (id[0x0a] address[0xfec08000] gsi_base[32])
(XEN) IOAPIC[2]: apic_id 10, version 32, address 0xfec08000, GSI 32-39
(XEN) ACPI: IOAPIC (id[0x0b] address[0xfec10000] gsi_base[40])
(XEN) IOAPIC[3]: apic_id 11, version 32, address 0xfec10000, GSI 40-47
(XEN) ACPI: IOAPIC (id[0x0c] address[0xfec18000] gsi_base[48])
(XEN) IOAPIC[4]: apic_id 12, version 32, address 0xfec18000, GSI 48-55
(XEN) ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
(XEN) ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
(XEN) ACPI: IRQ0 used by override.
(XEN) ACPI: IRQ2 used by override.
(XEN) ACPI: IRQ9 used by override.
(XEN) ACPI: HPET id: 0x8086a701 base: 0xfed00000
(XEN) PCI: MCFG configuration 0: base 80000000 segment 0000 buses 00 - ff
(XEN) PCI: MCFG area at 80000000 reserved in E820
(XEN) PCI: Using MCFG for segment 0000 bus 00-ff
(XEN) [VT-D]Host address width 46
(XEN) [VT-D]found ACPI_DMAR_DRHD:
(XEN) [VT-D]  dmaru->address = c5ffc000
(XEN) [VT-D]drhd->address = c5ffc000 iommu->reg = ffff82c00051e000
(XEN) [VT-D]cap = 8d2078c106f0466 ecap = f020df
(XEN) [VT-D] IOAPIC: 0000:16:05.4
(XEN) [VT-D]found ACPI_DMAR_DRHD:
(XEN) [VT-D]  dmaru->address = e0ffc000
(XEN) [VT-D]drhd->address = e0ffc000 iommu->reg = ffff82c000520000
(XEN) [VT-D]cap = 8d2078c106f0466 ecap = f020df
(XEN) [VT-D] IOAPIC: 0000:64:05.4
(XEN) [VT-D] bridge: 0000:64:03.0 start=64 sec=65 sub=65
(XEN) [VT-D]found ACPI_DMAR_DRHD:
(XEN) [VT-D]  dmaru->address = fbffc000
(XEN) [VT-D]drhd->address = fbffc000 iommu->reg = ffff82c000522000
(XEN) [VT-D]cap = 8d2078c106f0466 ecap = f020df
(XEN) [VT-D] IOAPIC: 0000:b2:05.4
(XEN) [VT-D] bridge: 0000:b2:00.0 start=b2 sec=b3 sub=b7
(XEN) [VT-D]found ACPI_DMAR_DRHD:
(XEN) [VT-D]  dmaru->address = aaffc000
(XEN) [VT-D]drhd->address = aaffc000 iommu->reg = ffff82c000524000
(XEN) [VT-D]cap = 8d2078c106f0466 ecap = f020df
(XEN) [VT-D] IOAPIC: 0000:f0:1f.0
(XEN) [VT-D] IOAPIC: 0000:00:05.4
(XEN) [VT-D] MSI HPET: 0000:00:1f.0
(XEN) [VT-D]  flags: INCLUDE_ALL
(XEN) [VT-D]found ACPI_DMAR_RMRR:
(XEN) [VT-D] endpoint: 0000:00:14.0
(XEN) [VT-D]found ACPI_DMAR_ATSR:
(XEN) [VT-D]  atsru->all_ports: 0
(XEN) [VT-D] bridge: 0000:64:03.0 start=64 sec=65 sub=65
(XEN) [VT-D] bridge: 0000:b2:00.0 start=b2 sec=b3 sub=b7
(XEN) [VT-D]found ACPI_DMAR_RHSA:
(XEN) [VT-D]  rhsau->address: aaffc000 rhsau->proximity_domain: 0
(XEN) [VT-D]found ACPI_DMAR_RHSA:
(XEN) [VT-D]  rhsau->address: c5ffc000 rhsau->proximity_domain: 0
(XEN) [VT-D]found ACPI_DMAR_RHSA:
(XEN) [VT-D]  rhsau->address: e0ffc000 rhsau->proximity_domain: 0
(XEN) [VT-D]found ACPI_DMAR_RHSA:
(XEN) [VT-D]  rhsau->address: fbffc000 rhsau->proximity_domain: 0
(XEN) Xen ERST support is initialized.
(XEN) HEST: Table parsing has been initialized
(XEN) ACPI: BGRT: invalidating v1 image at 0x6401e018
(XEN) Using ACPI (MADT) for SMP configuration information
(XEN) SMP: Allowing 72 CPUs (56 hotplug CPUs)
(XEN) IRQ limits: 56 GSI, 3272 MSI/MSI-X
(XEN) CPU0: TSC: ratio: 184 / 2
(XEN) CPU0: bus: 100 MHz base: 2300 MHz max: 3000 MHz
(XEN) CPU0: 1000 ... 2300 MHz
(XEN) xstate: size: 0xa88 and states: 0x2ff
(XEN) CMCI: threshold 0x2 too large for CPU0 bank 6, using 0x1
(XEN) CMCI: threshold 0x2 too large for CPU0 bank 9, using 0x1
(XEN) CMCI: threshold 0x2 too large for CPU0 bank 10, using 0x1
(XEN) CMCI: threshold 0x2 too large for CPU0 bank 11, using 0x1
(XEN) CPU0: Intel machine check reporting enabled
(XEN) Speculative mitigation facilities:
(XEN)   Hardware features: IBRS/IBPB STIBP L1D_FLUSH SSBD MD_CLEAR
(XEN)   Compiled-in support: INDIRECT_THUNK SHADOW_PAGING
(XEN)   Xen settings: BTI-Thunk JMP, SPEC_CTRL: IBRS+ SSBD-, Other: IBPB L1D_FLUSH VERW BRANCH_HARDEN
(XEN)   L1TF: believed vulnerable, maxphysaddr L1D 46, CPUID 46, Safe address 300000000000
(XEN)   Support for HVM VMs: MSR_SPEC_CTRL RSB EAGER_FPU MD_CLEAR
(XEN)   Support for PV VMs: MSR_SPEC_CTRL RSB EAGER_FPU MD_CLEAR
(XEN)   XPTI (64-bit PV only): Dom0 disabled, DomU disabled (with PCID)
(XEN)   PV L1TF shadowing: Dom0 disabled, DomU enabled
(XEN) Using scheduler: SMP Credit Scheduler rev2 (credit2)
(XEN) Initializing Credit2 scheduler
(XEN)  load_precision_shift: 18
(XEN)  load_window_shift: 30
(XEN)  underload_balance_tolerance: 0
(XEN)  overload_balance_tolerance: -3
(XEN)  runqueues arrangement: socket
(XEN)  cap enforcement granularity: 10ms
(XEN) load tracking window length 1073741824 ns
(XEN) Platform timer is 24.000MHz HPET
(XEN) Detected 7623.412 MHz processor.
(XEN) EFI memory map:
(XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
(XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f
(XEN)  000000003d000-000000003efff type=2 attr=000000000000000f
(XEN)  000000003f000-000000003ffff type=4 attr=000000000000000f
(XEN)  0000000040000-000000009ffff type=3 attr=000000000000000f
(XEN)  0000000100000-00000574f5fff type=7 attr=000000000000000f
(XEN)  00000574f6000-000005b1cffff type=2 attr=000000000000000f
(XEN)  000005b1d0000-000005b2cffff type=4 attr=000000000000000f
(XEN)  000005b2d0000-000005c8e2fff type=7 attr=000000000000000f
(XEN)  000005c8e3000-000005d20afff type=2 attr=000000000000000f
(XEN)  000005d20b000-000005d20bfff type=7 attr=000000000000000f
(XEN)  000005d20c000-000005d20cfff type=2 attr=000000000000000f
(XEN)  000005d20d000-000005e40cfff type=1 attr=000000000000000f
(XEN)  000005e40d000-000006899bfff type=4 attr=000000000000000f
(XEN)  000006899c000-0000068c28fff type=7 attr=000000000000000f
(XEN)  0000068c29000-000006965efff type=3 attr=000000000000000f
(XEN)  000006965f000-000006bee5fff type=0 attr=000000000000000f
(XEN)  000006bee6000-000006c0a6fff type=7 attr=000000000000000f
(XEN)  000006c0a7000-000006ca43fff type=10 attr=000000000000000f
(XEN)  000006ca44000-000006eb6bfff type=6 attr=800000000000000f
(XEN)  000006eb6c000-000006ed16fff type=5 attr=800000000000000f
(XEN)  000006ed17000-000006ee98fff type=4 attr=000000000000000f
(XEN)  000006ee99000-000006eeb7fff type=3 attr=000000000000000f
(XEN)  000006eeb8000-000006eee7fff type=4 attr=000000000000000f
(XEN)  000006eee8000-000006eeedfff type=3 attr=000000000000000f
(XEN)  000006eeee000-000006f0f5fff type=4 attr=000000000000000f
(XEN)  000006f0f6000-000006f108fff type=3 attr=000000000000000f
(XEN)  000006f109000-000006f12cfff type=4 attr=000000000000000f
(XEN)  000006f12d000-000006f143fff type=3 attr=000000000000000f
(XEN)  000006f144000-000006f16bfff type=4 attr=000000000000000f
(XEN)  000006f16c000-000006f1a3fff type=3 attr=000000000000000f
(XEN)  000006f1a4000-000006f1cbfff type=4 attr=000000000000000f
(XEN)  000006f1cc000-000006fffffff type=7 attr=000000000000000f
(XEN)  0000100000000-000207fffffff type=7 attr=000000000000000f
(XEN)  00000000a0000-00000000fffff type=0 attr=0000000000000000
(XEN)  0000070000000-000007fffffff type=0 attr=0000000000000000
(XEN)  0000080000000-000008fffffff type=11 attr=8000000000000001
(XEN)  00000fd000000-00000fe7fffff type=11 attr=800000000000100d
(XEN)  00000fed20000-00000fed44fff type=11 attr=800000000000100d
(XEN)  00000ff000000-00000ffffffff type=11 attr=800000000000100d
(XEN) alt table ffff82d0406822b0 -> ffff82d04068d30e
(XEN) Intel VT-d iommu 2 supported page sizes: 4kB, 2MB, 1GB
(XEN) Intel VT-d iommu 1 supported page sizes: 4kB, 2MB, 1GB
(XEN) Intel VT-d iommu 0 supported page sizes: 4kB, 2MB, 1GB
(XEN) Intel VT-d iommu 3 supported page sizes: 4kB, 2MB, 1GB
(XEN) Intel VT-d Snoop Control enabled.
(XEN) Intel VT-d Dom0 DMA Passthrough not enabled.
(XEN) Intel VT-d Queued Invalidation enabled.
(XEN) Intel VT-d Interrupt Remapping enabled.
(XEN) Intel VT-d Posted Interrupt enabled.
(XEN) Intel VT-d Shared EPT tables enabled.
(XEN) I/O virtualisation enabled
(XEN)  - Dom0 mode: Relaxed
(XEN) Interrupt remapping enabled
(XEN) nr_sockets: 5
(XEN) Enabled directed EOI with ioapic_ack_old on!
(XEN) ENABLING IO-APIC IRQs
(XEN)  -> Using old ACK method
(XEN) ..TIMER: vector=0xF0 apic1=0 pin1=2 apic2=-1 pin2=-1
(XEN) TSC deadline timer enabled
(XEN) Allocated console ring of 128 KiB.
(XEN) mwait-idle: MWAIT substates: 0x2020
(XEN) mwait-idle: v0.4.1 model 0x55
(XEN) mwait-idle: lapic_timer_reliable_states 0xffffffff
(XEN) VMX: Supported advanced features:
(XEN)  - APIC MMIO access virtualisation
(XEN)  - APIC TPR shadow
(XEN)  - Extended Page Tables (EPT)
(XEN)  - Virtual-Processor Identifiers (VPID)
(XEN)  - Virtual NMI
(XEN)  - MSR direct-access bitmap
(XEN)  - Unrestricted Guest
(XEN)  - APIC Register Virtualization
(XEN)  - Virtual Interrupt Delivery
(XEN)  - Posted Interrupt Processing
(XEN)  - VMCS shadowing
(XEN)  - VM Functions
(XEN)  - Virtualisation Exceptions
(XEN)  - Page Modification Logging
(XEN)  - TSC Scaling
(XEN) HVM: ASIDs enabled.
(XEN) VMX: Disabling executable EPT superpages due to CVE-2018-12207
(XEN) HVM: VMX enabled
(XEN) HVM: Hardware Assisted Paging (HAP) detected
(XEN) HVM: HAP page sizes: 4kB, 2MB, 1GB
(XEN) alt table ffff82d0406822b0 -> ffff82d04068d30e
(XEN) Brought up 16 CPUs
(XEN) Scheduling granularity: cpu, 1 CPU per sched-resource
(XEN) Adding cpu 0 to runqueue 0
(XEN)  First cpu on runqueue, activating
(XEN) Adding cpu 1 to runqueue 0
(XEN) Adding cpu 2 to runqueue 0
(XEN) Adding cpu 3 to runqueue 0
(XEN) Adding cpu 4 to runqueue 0
(XEN) Adding cpu 5 to runqueue 0
(XEN) Adding cpu 6 to runqueue 0
(XEN) Adding cpu 7 to runqueue 0
(XEN) Adding cpu 8 to runqueue 0
(XEN) Adding cpu 9 to runqueue 0
(XEN) Adding cpu 10 to runqueue 0
(XEN) Adding cpu 11 to runqueue 0
(XEN) Adding cpu 12 to runqueue 0
(XEN) Adding cpu 13 to runqueue 0
(XEN) Adding cpu 14 to runqueue 0
(XEN) Adding cpu 15 to runqueue 0
(XEN) mcheck_poll: Machine check polling timer started.
(XEN) NX (Execute Disable) protection active
(XEN) Dom0 has maximum 888 PIRQs
(XEN) *** Building a PV Dom0 ***
(XEN)  Xen  kernel: 64-bit, lsb, compat32
(XEN)  Dom0 kernel: 64-bit, PAE, lsb, paddr 0x1000000 -> 0x3600000
(XEN) PHYSICAL MEMORY ARRANGEMENT:
(XEN)  Dom0 alloc.:   000000201c000000->0000002020000000 (16745254 pages to be allocated)
(XEN)  Init. ramdisk: 000000207c322000->000000207fffba7a
(XEN) VIRTUAL MEMORY ARRANGEMENT:
(XEN)  Loaded kernel: ffffffff81000000->ffffffff83600000
(XEN)  Init. ramdisk: 0000000000000000->0000000000000000
(XEN)  Phys-Mach map: 0000008000000000->0000008008000000
(XEN)  Start info:    ffffffff83600000->ffffffff836004b8
(XEN)  Xenstore ring: 0000000000000000->0000000000000000
(XEN)  Console ring:  0000000000000000->0000000000000000
(XEN)  Page tables:   ffffffff83601000->ffffffff83620000
(XEN)  Boot stack:    ffffffff83620000->ffffffff83621000
(XEN)  TOTAL:         ffffffff80000000->ffffffff83800000
(XEN)  ENTRY ADDRESS: ffffffff8289f180
(XEN) Dom0 has maximum 4 VCPUs
(XEN) [VT-D]d0:Hostbridge: skip 0000:00:00.0 map
(XEN) [VT-D]d0:PCIe: map 0000:00:04.0
(XEN) [VT-D]d0:PCIe: map 0000:00:04.1
(XEN) [VT-D]d0:PCIe: map 0000:00:04.2
(XEN) [VT-D]d0:PCIe: map 0000:00:04.3
(XEN) [VT-D]d0:PCIe: map 0000:00:04.4
(XEN) [VT-D]d0:PCIe: map 0000:00:04.5
(XEN) [VT-D]d0:PCIe: map 0000:00:04.6
(XEN) [VT-D]d0:PCIe: map 0000:00:04.7
(XEN) [VT-D]d0:PCIe: map 0000:00:05.0
(XEN) [VT-D]d0:PCIe: map 0000:00:05.2
(XEN) [VT-D]d0:PCIe: map 0000:00:05.4
(XEN) [VT-D]d0:PCIe: map 0000:00:08.0
(XEN) [VT-D]d0:PCI: map 0000:00:08.1
(XEN) [VT-D]d0:PCIe: map 0000:00:08.2
(XEN) [VT-D]d0:PCI: map 0000:00:11.0
(XEN) [VT-D]d0:PCI: map 0000:00:11.1
(XEN) [VT-D]d0:PCI: map 0000:00:11.5
(XEN) [VT-D]d0:PCI: map 0000:00:14.0
(XEN) [VT-D]d0:PCI: map 0000:00:14.2
(XEN) [VT-D]d0:PCI: map 0000:00:16.0
(XEN) [VT-D]d0:PCI: map 0000:00:16.1
(XEN) [VT-D]d0:PCI: map 0000:00:16.4
(XEN) [VT-D]d0:PCI: map 0000:00:17.0
(XEN) [VT-D]d0:PCI: map 0000:00:1f.0
(XEN) [VT-D]d0:PCI: map 0000:00:1f.2
(XEN) [VT-D]d0:PCI: map 0000:00:1f.4
(XEN) [VT-D]d0:PCI: map 0000:00:1f.5
(XEN) [VT-D]d0:PCI: map 0000:03:00.0
(XEN) [VT-D]d0:PCIe: map 0000:16:05.0
(XEN) [VT-D]d0:PCIe: map 0000:16:05.2
(XEN) [VT-D]d0:PCIe: map 0000:16:05.4
(XEN) [VT-D]d0:PCI: map 0000:16:08.0
(XEN) [VT-D]d0:PCI: map 0000:16:08.1
(XEN) [VT-D]d0:PCI: map 0000:16:08.2
(XEN) [VT-D]d0:PCI: map 0000:16:08.3
(XEN) [VT-D]d0:PCI: map 0000:16:08.4
(XEN) [VT-D]d0:PCI: map 0000:16:08.5
(XEN) [VT-D]d0:PCI: map 0000:16:08.6
(XEN) [VT-D]d0:PCI: map 0000:16:08.7
(XEN) [VT-D]d0:PCI: map 0000:16:09.0
(XEN) [VT-D]d0:PCI: map 0000:16:09.1
(XEN) [VT-D]d0:PCI: map 0000:16:09.2
(XEN) [VT-D]d0:PCI: map 0000:16:09.3
(XEN) [VT-D]d0:PCI: map 0000:16:09.4
(XEN) [VT-D]d0:PCI: map 0000:16:09.5
(XEN) [VT-D]d0:PCI: map 0000:16:09.6
(XEN) [VT-D]d0:PCI: map 0000:16:09.7
(XEN) [VT-D]d0:PCI: map 0000:16:0a.0
(XEN) [VT-D]d0:PCI: map 0000:16:0a.1
(XEN) [VT-D]d0:PCI: map 0000:16:0e.0
(XEN) [VT-D]d0:PCI: map 0000:16:0e.1
(XEN) [VT-D]d0:PCI: map 0000:16:0e.2
(XEN) [VT-D]d0:PCI: map 0000:16:0e.3
(XEN) [VT-D]d0:PCI: map 0000:16:0e.4
(XEN) [VT-D]d0:PCI: map 0000:16:0e.5
(XEN) [VT-D]d0:PCI: map 0000:16:0e.6
(XEN) [VT-D]d0:PCI: map 0000:16:0e.7
(XEN) [VT-D]d0:PCI: map 0000:16:0f.0
(XEN) [VT-D]d0:PCI: map 0000:16:0f.1
(XEN) [VT-D]d0:PCI: map 0000:16:0f.2
(XEN) [VT-D]d0:PCI: map 0000:16:0f.3
(XEN) [VT-D]d0:PCI: map 0000:16:0f.4
(XEN) [VT-D]d0:PCI: map 0000:16:0f.5
(XEN) [VT-D]d0:PCI: map 0000:16:0f.6
(XEN) [VT-D]d0:PCI: map 0000:16:0f.7
(XEN) [VT-D]d0:PCI: map 0000:16:10.0
(XEN) [VT-D]d0:PCI: map 0000:16:10.1
(XEN) [VT-D]d0:PCI: map 0000:16:1d.0
(XEN) [VT-D]d0:PCI: map 0000:16:1d.1
(XEN) [VT-D]d0:PCI: map 0000:16:1d.2
(XEN) [VT-D]d0:PCI: map 0000:16:1d.3
(XEN) [VT-D]d0:PCI: map 0000:16:1e.0
(XEN) [VT-D]d0:PCI: map 0000:16:1e.1
(XEN) [VT-D]d0:PCI: map 0000:16:1e.2
(XEN) [VT-D]d0:PCI: map 0000:16:1e.3
(XEN) [VT-D]d0:PCI: map 0000:16:1e.4
(XEN) [VT-D]d0:PCI: map 0000:16:1e.5
(XEN) [VT-D]d0:PCI: map 0000:16:1e.6
(XEN) [VT-D]d0:PCIe: map 0000:64:05.0
(XEN) [VT-D]d0:PCIe: map 0000:64:05.2
(XEN) [VT-D]d0:PCIe: map 0000:64:05.4
(XEN) [VT-D]d0:PCIe: map 0000:64:08.0
(XEN) [VT-D]d0:PCIe: map 0000:64:09.0
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.0
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.1
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.2
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.3
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.4
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.5
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.6
(XEN) [VT-D]d0:PCIe: map 0000:64:0a.7
(XEN) [VT-D]d0:PCIe: map 0000:64:0b.0
(XEN) [VT-D]d0:PCIe: map 0000:64:0b.1
(XEN) [VT-D]d0:PCIe: map 0000:64:0b.2
(XEN) [VT-D]d0:PCIe: map 0000:64:0b.3
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.0
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.1
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.2
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.3
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.4
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.5
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.6
(XEN) [VT-D]d0:PCIe: map 0000:64:0c.7
(XEN) [VT-D]d0:PCIe: map 0000:64:0d.0
(XEN) [VT-D]d0:PCIe: map 0000:64:0d.1
(XEN) [VT-D]d0:PCIe: map 0000:64:0d.2
(XEN) [VT-D]d0:PCIe: map 0000:64:0d.3
(XEN) [VT-D]d0:PCIe: map 0000:65:00.0
(XEN) [VT-D]d0:PCIe: map 0000:65:00.1
(XEN) [VT-D]d0:PCIe: map 0000:65:00.2
(XEN) [VT-D]d0:PCIe: map 0000:65:00.3
(XEN) [VT-D]d0:PCIe: map 0000:b2:05.0
(XEN) [VT-D]d0:PCIe: map 0000:b2:05.2
(XEN) [VT-D]d0:PCIe: map 0000:b2:05.4
(XEN) [VT-D]d0:PCIe: map 0000:b2:12.0
(XEN) [VT-D]d0:PCI: map 0000:b2:12.1
(XEN) [VT-D]d0:PCI: map 0000:b2:12.2
(XEN) [VT-D]d0:PCI: map 0000:b2:15.0
(XEN) [VT-D]d0:PCI: map 0000:b2:16.0
(XEN) [VT-D]d0:PCI: map 0000:b2:16.4
(XEN) [VT-D]d0:PCI: map 0000:b2:17.0
(XEN) [VT-D]d0:PCIe: map 0000:b5:00.0
(XEN) [VT-D]d0:PCIe: map 0000:b6:00.0
(XEN) [VT-D]d0:PCIe: map 0000:b7:00.0
(XEN) [VT-D]d0:PCIe: map 0000:b7:00.1
(XEN) [VT-D]d0:PCIe: map 0000:b7:00.2
(XEN) [VT-D]d0:PCIe: map 0000:b7:00.3
(XEN) [VT-D]iommu_enable_translation: iommu->reg = ffff82c000522000
(XEN) [VT-D]iommu_enable_translation: iommu->reg = ffff82c000520000
(XEN) [VT-D]iommu_enable_translation: iommu->reg = ffff82c00051e000
(XEN) [VT-D]iommu_enable_translation: iommu->reg = ffff82c000524000
(XEN) Initial low memory virq threshold set at 0x4000 pages.
(XEN) Scrubbing Free RAM in background
(XEN) Std. Loglevel: All
(XEN) Guest Loglevel: Nothing (Rate-limited: Errors and warnings)
(XEN) Xen is relinquishing VGA console.
(XEN) *** Serial input to DOM0 (type 'CTRL-a' three times to switch input)
(XEN) Freed 2048kB init memory
(XEN) PCI add device 0000:00:00.0
(XEN) PCI add device 0000:00:04.0
(XEN) PCI add device 0000:00:04.1
(XEN) PCI add device 0000:00:04.2
(XEN) PCI add device 0000:00:04.3
(XEN) PCI add device 0000:00:04.4
(XEN) PCI add device 0000:00:04.5
(XEN) PCI add device 0000:00:04.6
(XEN) PCI add device 0000:00:04.7
(XEN) PCI add device 0000:00:05.0
(XEN) PCI add device 0000:00:05.2
(XEN) PCI add device 0000:00:05.4
(XEN) PCI add device 0000:00:08.0
(XEN) PCI add device 0000:00:08.1
(XEN) PCI add device 0000:00:08.2
(XEN) PCI add device 0000:00:11.0
(XEN) PCI add device 0000:00:11.1
(XEN) PCI add device 0000:00:11.5
(XEN) PCI add device 0000:00:14.0
(XEN) PCI add device 0000:00:14.2
(XEN) PCI add device 0000:00:16.0
(XEN) PCI add device 0000:00:16.1
(XEN) PCI add device 0000:00:16.4
(XEN) PCI add device 0000:00:17.0
(XEN) PCI add device 0000:00:1c.0
(XEN) PCI add device 0000:00:1c.4
(XEN) PCI add device 0000:00:1d.0
(XEN) PCI add device 0000:00:1f.0
(XEN) PCI add device 0000:00:1f.2
(XEN) PCI add device 0000:00:1f.4
(XEN) PCI add device 0000:00:1f.5
(XEN) PCI add device 0000:02:00.0
(XEN) PCI add device 0000:03:00.0
(XEN) PCI add device 0000:16:05.0
(XEN) PCI add device 0000:16:05.2
(XEN) PCI add device 0000:16:05.4
(XEN) PCI add device 0000:16:08.0
(XEN) PCI add device 0000:16:08.1
(XEN) PCI add device 0000:16:08.2
(XEN) PCI add device 0000:16:08.3
(XEN) PCI add device 0000:16:08.4
(XEN) PCI add device 0000:16:08.5
(XEN) PCI add device 0000:16:08.6
(XEN) PCI add device 0000:16:08.7
(XEN) PCI add device 0000:16:09.0
(XEN) PCI add device 0000:16:09.1
(XEN) PCI add device 0000:16:09.2
(XEN) PCI add device 0000:16:09.3
(XEN) PCI add device 0000:16:09.4
(XEN) PCI add device 0000:16:09.5
(XEN) PCI add device 0000:16:09.6
(XEN) PCI add device 0000:16:09.7
(XEN) PCI add device 0000:16:0a.0
(XEN) PCI add device 0000:16:0a.1
(XEN) PCI add device 0000:16:0e.0
(XEN) PCI add device 0000:16:0e.1
(XEN) PCI add device 0000:16:0e.2
(XEN) PCI add device 0000:16:0e.3
(XEN) PCI add device 0000:16:0e.4
(XEN) PCI add device 0000:16:0e.5
(XEN) PCI add device 0000:16:0e.6
(XEN) PCI add device 0000:16:0e.7
(XEN) PCI add device 0000:16:0f.0
(XEN) PCI add device 0000:16:0f.1
(XEN) PCI add device 0000:16:0f.2
(XEN) PCI add device 0000:16:0f.3
(XEN) PCI add device 0000:16:0f.4
(XEN) PCI add device 0000:16:0f.5
(XEN) PCI add device 0000:16:0f.6
(XEN) PCI add device 0000:16:0f.7
(XEN) PCI add device 0000:16:10.0
(XEN) PCI add device 0000:16:10.1
(XEN) PCI add device 0000:16:1d.0
(XEN) PCI add device 0000:16:1d.1
(XEN) PCI add device 0000:16:1d.2
(XEN) PCI add device 0000:16:1d.3
(XEN) PCI add device 0000:16:1e.0
(XEN) PCI add device 0000:16:1e.1
(XEN) PCI add device 0000:16:1e.2
(XEN) PCI add device 0000:16:1e.3
(XEN) PCI add device 0000:16:1e.4
(XEN) PCI add device 0000:16:1e.5
(XEN) PCI add device 0000:16:1e.6
(XEN) PCI add device 0000:64:03.0
(XEN) PCI add device 0000:64:05.0
(XEN) PCI add device 0000:64:05.2
(XEN) PCI add device 0000:64:05.4
(XEN) PCI add device 0000:64:08.0
(XEN) PCI add device 0000:64:09.0
(XEN) PCI add device 0000:64:0a.0
(XEN) PCI add device 0000:64:0a.1
(XEN) PCI add device 0000:64:0a.2
(XEN) PCI add device 0000:64:0a.3
(XEN) PCI add device 0000:64:0a.4
(XEN) PCI add device 0000:64:0a.5
(XEN) PCI add device 0000:64:0a.6
(XEN) PCI add device 0000:64:0a.7
(XEN) PCI add device 0000:64:0b.0
(XEN) PCI add device 0000:64:0b.1
(XEN) PCI add device 0000:64:0b.2
(XEN) PCI add device 0000:64:0b.3
(XEN) PCI add device 0000:64:0c.0
(XEN) PCI add device 0000:64:0c.1
(XEN) PCI add device 0000:64:0c.2
(XEN) PCI add device 0000:64:0c.3
(XEN) PCI add device 0000:64:0c.4
(XEN) PCI add device 0000:64:0c.5
(XEN) PCI add device 0000:64:0c.6
(XEN) PCI add device 0000:64:0c.7
(XEN) PCI add device 0000:64:0d.0
(XEN) PCI add device 0000:64:0d.1
(XEN) PCI add device 0000:64:0d.2
(XEN) PCI add device 0000:64:0d.3
(XEN) PCI add device 0000:65:00.0
(XEN) PCI add device 0000:65:00.1
(XEN) PCI add device 0000:65:00.2
(XEN) PCI add device 0000:65:00.3
(XEN) PCI add device 0000:b2:00.0
(XEN) PCI add device 0000:b2:05.0
(XEN) PCI add device 0000:b2:05.2
(XEN) PCI add device 0000:b2:05.4
(XEN) PCI add device 0000:b2:12.0
(XEN) PCI add device 0000:b2:12.1
(XEN) PCI add device 0000:b2:12.2
(XEN) PCI add device 0000:b2:15.0
(XEN) PCI add device 0000:b2:16.0
(XEN) PCI add device 0000:b2:16.4
(XEN) PCI add device 0000:b2:17.0
(XEN) PCI add device 0000:b3:00.0
(XEN) PCI add device 0000:b4:00.0
(XEN) PCI add device 0000:b4:02.0
(XEN) PCI add device 0000:b4:03.0
(XEN) PCI add device 0000:b5:00.0
(XEN) PCI add device 0000:b6:00.0
(XEN) PCI add device 0000:b7:00.0
(XEN) PCI add device 0000:b7:00.1
(XEN) PCI add device 0000:b7:00.2
(XEN) PCI add device 0000:b7:00.3
(XEN) Platform timer appears to have unexpectedly wrapped 10 or more times.
(XEN) [VT-D]d0:PCIe: unmap 0000:65:00.2
(XEN) [VT-D]d32753:PCIe: map 0000:65:00.2
(XEN) [VT-D]d0:PCIe: unmap 0000:65:00.1
(XEN) [VT-D]d32753:PCIe: map 0000:65:00.1
(XEN) [VT-D]d0:PCIe: unmap 0000:65:00.0
(XEN) [VT-D]d32753:PCIe: map 0000:65:00.0
(XEN) [VT-D]d32753:PCIe: unmap 0000:65:00.2
(XEN) [VT-D]d2:PCIe: map 0000:65:00.2
(XEN) [VT-D]d32753:PCIe: unmap 0000:65:00.1
(XEN) [VT-D]d2:PCIe: map 0000:65:00.1
(XEN) [VT-D]d32753:PCIe: unmap 0000:65:00.0
(XEN) [VT-D]d2:PCIe: map 0000:65:00.0

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 06.01.2022 16:08, James Dingwall wrote:
>>> On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:                                                                            
>>>> On 21.07.2021 11:29, James Dingwall wrote:                                                                                             
>>>>> We have a system which intermittently starts up and reports an incorrect cpu frequency:                                               
> ...
>>> I'm sorry to ask, but have you got around to actually doing that? Or
>>> else is resolving this no longer of interest?
> 
> We have experienced an occurence of this issue on 4.14.3 with 'loglvl=all'
> present on the xen command line.  I have attached the 'xl dmesg' output for
> the fast MHz boot, the diff from the normal case is small so I've not added
> that log separately:
> 
> --- normal-mhz/xl-dmesg.txt     2022-01-06 14:13:47.231465234 +0000
> +++ funny-mhz/xl-dmesg.txt      2022-01-06 13:45:43.825148510 +0000
> @@ -211,7 +211,7 @@
>  (XEN)  cap enforcement granularity: 10ms
>  (XEN) load tracking window length 1073741824 ns
>  (XEN) Platform timer is 24.000MHz HPET
> -(XEN) Detected 2294.639 MHz processor.
> +(XEN) Detected 7623.412 MHz processor.
>  (XEN) EFI memory map:
>  (XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
>  (XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f
> @@ -616,6 +616,7 @@
>  (XEN) PCI add device 0000:b7:00.1
>  (XEN) PCI add device 0000:b7:00.2
>  (XEN) PCI add device 0000:b7:00.3
> +(XEN) Platform timer appears to have unexpectedly wrapped 10 or more times.
>  (XEN) [VT-D]d0:PCIe: unmap 0000:65:00.2
>  (XEN) [VT-D]d32753:PCIe: map 0000:65:00.2
>  (XEN) [VT-D]d0:PCIe: unmap 0000:65:00.1

Thanks. In an earlier mail the reported value was 6895.384 MHz, but I
guess that was on a different system (with a base freq of 2200 MHz).
I wonder how stable the too high value is ...

For the moment I have only one possibly explanation: A SMI hitting in
the middle of the tail of init_hpet() (or init_pmtimer()), taking long
enough to cause the function to return way too large a number. With a
50ms calibration period that would be about 166ms. I vaguely recall
having heard of SMI potentially taking this long.

While I can see ways to reduce the likelihood of hitting the issue,
for now I lack a good idea how to avoid the problem altogether. I'll
try to get around to at least put together a debugging patch to
hopefully confirm the vague theory.

Jan

> I also have the dom0 kernel dmesg available if that would be useful but I've
> left it off initially because the log is quite large.  I don't see much in
> the diff between boots except where speed/times are reported and where things
> are initialised in a slightly different order.
> 
> Thanks,
> James

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Andrew Cooper]

On 06/01/2022 16:00, Jan Beulich wrote:
> On 06.01.2022 16:08, James Dingwall wrote:
>>>> On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:                                                                            
>>>>> On 21.07.2021 11:29, James Dingwall wrote:                                                                                             
>>>>>> We have a system which intermittently starts up and reports an incorrect cpu frequency:                                               
>> ...
>>>> I'm sorry to ask, but have you got around to actually doing that? Or
>>>> else is resolving this no longer of interest?
>> We have experienced an occurence of this issue on 4.14.3 with 'loglvl=all'
>> present on the xen command line.  I have attached the 'xl dmesg' output for
>> the fast MHz boot, the diff from the normal case is small so I've not added
>> that log separately:
>>
>> --- normal-mhz/xl-dmesg.txt     2022-01-06 14:13:47.231465234 +0000
>> +++ funny-mhz/xl-dmesg.txt      2022-01-06 13:45:43.825148510 +0000
>> @@ -211,7 +211,7 @@
>>  (XEN)  cap enforcement granularity: 10ms
>>  (XEN) load tracking window length 1073741824 ns
>>  (XEN) Platform timer is 24.000MHz HPET
>> -(XEN) Detected 2294.639 MHz processor.
>> +(XEN) Detected 7623.412 MHz processor.
>>  (XEN) EFI memory map:
>>  (XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
>>  (XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f
>> @@ -616,6 +616,7 @@
>>  (XEN) PCI add device 0000:b7:00.1
>>  (XEN) PCI add device 0000:b7:00.2
>>  (XEN) PCI add device 0000:b7:00.3
>> +(XEN) Platform timer appears to have unexpectedly wrapped 10 or more times.
>>  (XEN) [VT-D]d0:PCIe: unmap 0000:65:00.2
>>  (XEN) [VT-D]d32753:PCIe: map 0000:65:00.2
>>  (XEN) [VT-D]d0:PCIe: unmap 0000:65:00.1
> Thanks. In an earlier mail the reported value was 6895.384 MHz, but I
> guess that was on a different system (with a base freq of 2200 MHz).
> I wonder how stable the too high value is ...
>
> For the moment I have only one possibly explanation: A SMI hitting in
> the middle of the tail of init_hpet() (or init_pmtimer()), taking long
> enough to cause the function to return way too large a number. With a
> 50ms calibration period that would be about 166ms. I vaguely recall
> having heard of SMI potentially taking this long.

SMI's are stupidly long.  To avoid leaking secrets via speculation, SMIs
have to rendezvous at least the sibling threads, and SMM entry/exit
undergoes every flushing action which has been slowing down software
since 2018.

You can confirm SMIs using MSR_SMI_COUNT (0x34).  It's
non-architectural, but is present in Nehalem and later.

~Andrew

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 06.01.2022 16:08, James Dingwall wrote:
>>> On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:                                                                            
>>>> On 21.07.2021 11:29, James Dingwall wrote:                                                                                             
>>>>> We have a system which intermittently starts up and reports an incorrect cpu frequency:                                               
> ...
>>> I'm sorry to ask, but have you got around to actually doing that? Or
>>> else is resolving this no longer of interest?
> 
> We have experienced an occurence of this issue on 4.14.3 with 'loglvl=all'
> present on the xen command line.  I have attached the 'xl dmesg' output for
> the fast MHz boot, the diff from the normal case is small so I've not added
> that log separately:
> 
> --- normal-mhz/xl-dmesg.txt     2022-01-06 14:13:47.231465234 +0000
> +++ funny-mhz/xl-dmesg.txt      2022-01-06 13:45:43.825148510 +0000
> @@ -211,7 +211,7 @@
>  (XEN)  cap enforcement granularity: 10ms
>  (XEN) load tracking window length 1073741824 ns
>  (XEN) Platform timer is 24.000MHz HPET
> -(XEN) Detected 2294.639 MHz processor.
> +(XEN) Detected 7623.412 MHz processor.
>  (XEN) EFI memory map:
>  (XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
>  (XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f

Below is a patch (suitably adjusted for 4.14.3) which I would hope can
take care of the issue (assuming my vague guess on the reasons wasn't
entirely off). It has some debugging code intentionally left in, and
it's also not complete yet (other timer code needing similar
adjustment). Given the improvements I've observed independent of your
issue, I may not wait with submission until getting feedback from you,
since - aiui - it may take some time for you to actually run into a
case where the change would actually make an observable difference.

Jan

x86: improve TSC / CPU freq calibration accuracy

While the problem report was for extreme errors, even smaller ones would
better be avoided: The calculated period to run calibration loops over
can (and usually will) be shorter than the actual time elapsed between
first and last platform timer and TSC reads. Adjust values returned from
the init functions accordingly.

On a Skylake system I've tested this on accuracy (using HPET) went from
detecting in some cases more than 220kHz too high a value to about
±1kHz. On other systems the original error range was much smaller, with
less (in some cases only very little) improvement.

Reported-by: James Dingwall <james-xen@dingwall.me.uk>
Signed-off-by: Jan Beulich <jbeulich@suse.com>
---
TBD: Do we think we need to guard against the bizarre case of
     "target + count" overflowing (i.e. wrapping)?
TBD: Accuracy could be slightly further improved by using a (to be
     introduced) rounding variant of muldiv64().
TBD: I'm not entirely sure how useful the conditionals are - there
     shouldn't be any inaccuracies from the division when count equals
     target (upon entry to the conditionals), as then the divisor is
     what the original value was just multiplied by.

--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
 
 static int64_t __init init_hpet(struct platform_timesource *pts)
 {
-    uint64_t hpet_rate, start;
+    uint64_t hpet_rate, start, expired;
     uint32_t count, target;
+unsigned int i;//temp
 
     if ( hpet_address && strcmp(opt_clocksource, pts->id) &&
          cpuidle_using_deep_cstate() )
@@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
 
     pts->frequency = hpet_rate;
 
+for(i = 0; i < 16; ++i) {//temp
     count = hpet_read32(HPET_COUNTER);
     start = rdtsc_ordered();
     target = count + CALIBRATE_VALUE(hpet_rate);
     if ( target < count )
         while ( hpet_read32(HPET_COUNTER) >= count )
             continue;
-    while ( hpet_read32(HPET_COUNTER) < target )
+    while ( (count = hpet_read32(HPET_COUNTER)) < target )
         continue;
 
-    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
+    expired = rdtsc_ordered() - start;
+
+    if ( likely(count > target) )
+    {
+        /*
+         * A (perhaps significant) delay before the last HPET read above (e.g.
+         * due to a SMI or NMI) can lead to (perhaps severe) inaccuracy if not
+         * accounting for the time expired past the originally calculated end
+         * of the calibration period.
+         */
+printk("%lu -> ", expired * CALIBRATE_FRAC);//temp
+        count -= target;
+        target = CALIBRATE_VALUE(hpet_rate);
+        expired = muldiv64(expired, target, target + count);
+printk("%lu (%3u,%u)\n", expired * CALIBRATE_FRAC, count, target);//temp
+    }
+}
+
+    return expired * CALIBRATE_FRAC;
 }
 
 static void resume_hpet(struct platform_timesource *pts)

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[James Dingwall]

On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
> On 06.01.2022 16:08, James Dingwall wrote:
> >>> On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:                                                                            
> >>>> On 21.07.2021 11:29, James Dingwall wrote:                                                                                             
> >>>>> We have a system which intermittently starts up and reports an incorrect cpu frequency:                                               
> > ...
> >>> I'm sorry to ask, but have you got around to actually doing that? Or
> >>> else is resolving this no longer of interest?
> > 
> > We have experienced an occurence of this issue on 4.14.3 with 'loglvl=all'
> > present on the xen command line.  I have attached the 'xl dmesg' output for
> > the fast MHz boot, the diff from the normal case is small so I've not added
> > that log separately:
> > 
> > --- normal-mhz/xl-dmesg.txt     2022-01-06 14:13:47.231465234 +0000
> > +++ funny-mhz/xl-dmesg.txt      2022-01-06 13:45:43.825148510 +0000
> > @@ -211,7 +211,7 @@
> >  (XEN)  cap enforcement granularity: 10ms
> >  (XEN) load tracking window length 1073741824 ns
> >  (XEN) Platform timer is 24.000MHz HPET
> > -(XEN) Detected 2294.639 MHz processor.
> > +(XEN) Detected 7623.412 MHz processor.
> >  (XEN) EFI memory map:
> >  (XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
> >  (XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f
> 
> Below is a patch (suitably adjusted for 4.14.3) which I would hope can
> take care of the issue (assuming my vague guess on the reasons wasn't
> entirely off). It has some debugging code intentionally left in, and
> it's also not complete yet (other timer code needing similar
> adjustment). Given the improvements I've observed independent of your
> issue, I may not wait with submission until getting feedback from you,
> since - aiui - it may take some time for you to actually run into a
> case where the change would actually make an observable difference.

I'll get it added to our build and see what we find...

Thanks,
James

> 
> Jan
> 
> x86: improve TSC / CPU freq calibration accuracy
> 
> While the problem report was for extreme errors, even smaller ones would
> better be avoided: The calculated period to run calibration loops over
> can (and usually will) be shorter than the actual time elapsed between
> first and last platform timer and TSC reads. Adjust values returned from
> the init functions accordingly.
> 
> On a Skylake system I've tested this on accuracy (using HPET) went from
> detecting in some cases more than 220kHz too high a value to about
> ±1kHz. On other systems the original error range was much smaller, with
> less (in some cases only very little) improvement.
> 
> Reported-by: James Dingwall <james-xen@dingwall.me.uk>
> Signed-off-by: Jan Beulich <jbeulich@suse.com>
> ---
> TBD: Do we think we need to guard against the bizarre case of
>      "target + count" overflowing (i.e. wrapping)?
> TBD: Accuracy could be slightly further improved by using a (to be
>      introduced) rounding variant of muldiv64().
> TBD: I'm not entirely sure how useful the conditionals are - there
>      shouldn't be any inaccuracies from the division when count equals
>      target (upon entry to the conditionals), as then the divisor is
>      what the original value was just multiplied by.
> 
> --- a/xen/arch/x86/time.c
> +++ b/xen/arch/x86/time.c
> @@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
>  
>  static int64_t __init init_hpet(struct platform_timesource *pts)
>  {
> -    uint64_t hpet_rate, start;
> +    uint64_t hpet_rate, start, expired;
>      uint32_t count, target;
> +unsigned int i;//temp
>  
>      if ( hpet_address && strcmp(opt_clocksource, pts->id) &&
>           cpuidle_using_deep_cstate() )
> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>  
>      pts->frequency = hpet_rate;
>  
> +for(i = 0; i < 16; ++i) {//temp
>      count = hpet_read32(HPET_COUNTER);
>      start = rdtsc_ordered();
>      target = count + CALIBRATE_VALUE(hpet_rate);
>      if ( target < count )
>          while ( hpet_read32(HPET_COUNTER) >= count )
>              continue;
> -    while ( hpet_read32(HPET_COUNTER) < target )
> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>          continue;
>  
> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
> +    expired = rdtsc_ordered() - start;
> +
> +    if ( likely(count > target) )
> +    {
> +        /*
> +         * A (perhaps significant) delay before the last HPET read above (e.g.
> +         * due to a SMI or NMI) can lead to (perhaps severe) inaccuracy if not
> +         * accounting for the time expired past the originally calculated end
> +         * of the calibration period.
> +         */
> +printk("%lu -> ", expired * CALIBRATE_FRAC);//temp
> +        count -= target;
> +        target = CALIBRATE_VALUE(hpet_rate);
> +        expired = muldiv64(expired, target, target + count);
> +printk("%lu (%3u,%u)\n", expired * CALIBRATE_FRAC, count, target);//temp
> +    }
> +}
> +
> +    return expired * CALIBRATE_FRAC;
>  }
>  
>  static void resume_hpet(struct platform_timesource *pts)
> 

-- 
------------------------------------------------------------------------
James Dingwall
e: james@dingwall.me.uk
w: http://www.dingwall.me.uk/
------------------------------------------------------------------------

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 07.01.2022 12:39, Jan Beulich wrote:
> --- a/xen/arch/x86/time.c
> +++ b/xen/arch/x86/time.c
> @@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
>  
>  static int64_t __init init_hpet(struct platform_timesource *pts)
>  {
> -    uint64_t hpet_rate, start;
> +    uint64_t hpet_rate, start, expired;
>      uint32_t count, target;
> +unsigned int i;//temp
>  
>      if ( hpet_address && strcmp(opt_clocksource, pts->id) &&
>           cpuidle_using_deep_cstate() )
> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>  
>      pts->frequency = hpet_rate;
>  
> +for(i = 0; i < 16; ++i) {//temp
>      count = hpet_read32(HPET_COUNTER);
>      start = rdtsc_ordered();
>      target = count + CALIBRATE_VALUE(hpet_rate);
>      if ( target < count )
>          while ( hpet_read32(HPET_COUNTER) >= count )
>              continue;
> -    while ( hpet_read32(HPET_COUNTER) < target )
> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>          continue;

Unlike I first thought but matching my earlier reply, this only reduces
the likelihood of encountering an issue. In particular, a long-duration
event ahead of the final HPET read above would be covered, but ...

> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
> +    expired = rdtsc_ordered() - start;

... such an event occurring between the final HPET read and the TSC
read would still be an issue. So far I've only been able to think of an
ugly way to further reduce likelihood for this window, but besides that
neither being neat nor excluding the possibility altogether, I have to
point out that we have the same issue in a number of other places:
Back-to-back reads of platform timer and TSC are assumed to happen
close together elsewhere as well.

Cc-ing other x86 maintainers to see whether they have any helpful
thoughts ...

Jan

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Roger Pau Monné]

On Mon, Jan 10, 2022 at 08:52:55AM +0100, Jan Beulich wrote:
> On 07.01.2022 12:39, Jan Beulich wrote:
> > --- a/xen/arch/x86/time.c
> > +++ b/xen/arch/x86/time.c
> > @@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
> >  
> >  static int64_t __init init_hpet(struct platform_timesource *pts)
> >  {
> > -    uint64_t hpet_rate, start;
> > +    uint64_t hpet_rate, start, expired;
> >      uint32_t count, target;
> > +unsigned int i;//temp
> >  
> >      if ( hpet_address && strcmp(opt_clocksource, pts->id) &&
> >           cpuidle_using_deep_cstate() )
> > @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
> >  
> >      pts->frequency = hpet_rate;
> >  
> > +for(i = 0; i < 16; ++i) {//temp
> >      count = hpet_read32(HPET_COUNTER);
> >      start = rdtsc_ordered();
> >      target = count + CALIBRATE_VALUE(hpet_rate);
> >      if ( target < count )
> >          while ( hpet_read32(HPET_COUNTER) >= count )
> >              continue;
> > -    while ( hpet_read32(HPET_COUNTER) < target )
> > +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
> >          continue;
> 
> Unlike I first thought but matching my earlier reply, this only reduces
> the likelihood of encountering an issue. In particular, a long-duration
> event ahead of the final HPET read above would be covered, but ...
> 
> > -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
> > +    expired = rdtsc_ordered() - start;
> 
> ... such an event occurring between the final HPET read and the TSC
> read would still be an issue. So far I've only been able to think of an
> ugly way to further reduce likelihood for this window, but besides that
> neither being neat nor excluding the possibility altogether, I have to
> point out that we have the same issue in a number of other places:
> Back-to-back reads of platform timer and TSC are assumed to happen
> close together elsewhere as well.

Right, sorry replied to the patch first without reading this.

> Cc-ing other x86 maintainers to see whether they have any helpful
> thoughts ...

I'm not sure there's much we can do, we could maybe count NMIs and
retry if we detect an NMI has happened during calibration, but we
can't do this for SMIs, as I don't think there's a way to get this
information on all hardware we support. The MSR_SMI_COUNT (0x34) is
Intel-only and requires Nehalem or later.

Thanks, Roger.

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 10.01.2022 15:49, Roger Pau Monné wrote:
> On Mon, Jan 10, 2022 at 08:52:55AM +0100, Jan Beulich wrote:
>> On 07.01.2022 12:39, Jan Beulich wrote:
>>> --- a/xen/arch/x86/time.c
>>> +++ b/xen/arch/x86/time.c
>>> @@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
>>>  
>>>  static int64_t __init init_hpet(struct platform_timesource *pts)
>>>  {
>>> -    uint64_t hpet_rate, start;
>>> +    uint64_t hpet_rate, start, expired;
>>>      uint32_t count, target;
>>> +unsigned int i;//temp
>>>  
>>>      if ( hpet_address && strcmp(opt_clocksource, pts->id) &&
>>>           cpuidle_using_deep_cstate() )
>>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>>  
>>>      pts->frequency = hpet_rate;
>>>  
>>> +for(i = 0; i < 16; ++i) {//temp
>>>      count = hpet_read32(HPET_COUNTER);
>>>      start = rdtsc_ordered();
>>>      target = count + CALIBRATE_VALUE(hpet_rate);
>>>      if ( target < count )
>>>          while ( hpet_read32(HPET_COUNTER) >= count )
>>>              continue;
>>> -    while ( hpet_read32(HPET_COUNTER) < target )
>>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>>          continue;
>>
>> Unlike I first thought but matching my earlier reply, this only reduces
>> the likelihood of encountering an issue. In particular, a long-duration
>> event ahead of the final HPET read above would be covered, but ...
>>
>>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>>> +    expired = rdtsc_ordered() - start;
>>
>> ... such an event occurring between the final HPET read and the TSC
>> read would still be an issue. So far I've only been able to think of an
>> ugly way to further reduce likelihood for this window, but besides that
>> neither being neat nor excluding the possibility altogether, I have to
>> point out that we have the same issue in a number of other places:
>> Back-to-back reads of platform timer and TSC are assumed to happen
>> close together elsewhere as well.
> 
> Right, sorry replied to the patch first without reading this.

No problem at all.

>> Cc-ing other x86 maintainers to see whether they have any helpful
>> thoughts ...
> 
> I'm not sure there's much we can do, we could maybe count NMIs and
> retry if we detect an NMI has happened during calibration, but we
> can't do this for SMIs, as I don't think there's a way to get this
> information on all hardware we support. The MSR_SMI_COUNT (0x34) is
> Intel-only and requires Nehalem or later.

Yeah, no, I wouldn't want to make ourselves depend on such counting
anyway. There can always be yet another reason for long enough a
delay. The rough plan I have for further reducing the likelihood is
building on the assumption that there hopefully wouldn't be many
such events in close succession. I would read both counters perhaps
3 times, calculating (from the TSC alone) and recording the shortest
of the sequences. Then I'd continue reading both counters for as
long as the duration further shrinks (which will necessarily be a
finite process). For calculation I'd then use the tuple from the
fastest of the (4 or more) read sequences.

Thinking about it, maybe I should make this a separate patch rather
than folding that extra complexity into here (the patch intended
for staging now looks quite different anyway, partly thanks to the
fix for the issue you did point out).

Jan

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Roger Pau Monné]

On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
> On 06.01.2022 16:08, James Dingwall wrote:
> >>> On Wed, Jul 21, 2021 at 12:59:11PM +0200, Jan Beulich wrote:                                                                            
> >>>> On 21.07.2021 11:29, James Dingwall wrote:                                                                                             
> >>>>> We have a system which intermittently starts up and reports an incorrect cpu frequency:                                               
> > ...
> >>> I'm sorry to ask, but have you got around to actually doing that? Or
> >>> else is resolving this no longer of interest?
> > 
> > We have experienced an occurence of this issue on 4.14.3 with 'loglvl=all'
> > present on the xen command line.  I have attached the 'xl dmesg' output for
> > the fast MHz boot, the diff from the normal case is small so I've not added
> > that log separately:
> > 
> > --- normal-mhz/xl-dmesg.txt     2022-01-06 14:13:47.231465234 +0000
> > +++ funny-mhz/xl-dmesg.txt      2022-01-06 13:45:43.825148510 +0000
> > @@ -211,7 +211,7 @@
> >  (XEN)  cap enforcement granularity: 10ms
> >  (XEN) load tracking window length 1073741824 ns
> >  (XEN) Platform timer is 24.000MHz HPET
> > -(XEN) Detected 2294.639 MHz processor.
> > +(XEN) Detected 7623.412 MHz processor.
> >  (XEN) EFI memory map:
> >  (XEN)  0000000000000-0000000007fff type=3 attr=000000000000000f
> >  (XEN)  0000000008000-000000003cfff type=7 attr=000000000000000f
> 
> Below is a patch (suitably adjusted for 4.14.3) which I would hope can
> take care of the issue (assuming my vague guess on the reasons wasn't
> entirely off). It has some debugging code intentionally left in, and
> it's also not complete yet (other timer code needing similar
> adjustment). Given the improvements I've observed independent of your
> issue, I may not wait with submission until getting feedback from you,
> since - aiui - it may take some time for you to actually run into a
> case where the change would actually make an observable difference.
> 
> Jan
> 
> x86: improve TSC / CPU freq calibration accuracy
> 
> While the problem report was for extreme errors, even smaller ones would
> better be avoided: The calculated period to run calibration loops over
> can (and usually will) be shorter than the actual time elapsed between
> first and last platform timer and TSC reads. Adjust values returned from
> the init functions accordingly.
> 
> On a Skylake system I've tested this on accuracy (using HPET) went from
> detecting in some cases more than 220kHz too high a value to about
> ±1kHz. On other systems the original error range was much smaller, with
> less (in some cases only very little) improvement.
> 
> Reported-by: James Dingwall <james-xen@dingwall.me.uk>
> Signed-off-by: Jan Beulich <jbeulich@suse.com>
> ---
> TBD: Do we think we need to guard against the bizarre case of
>      "target + count" overflowing (i.e. wrapping)?

I also wonder whether a value of target close enough to the wrapping
point could cause the loop to stuck indefinitely, as count would
overflow and thus the condition won't be meet.

> TBD: Accuracy could be slightly further improved by using a (to be
>      introduced) rounding variant of muldiv64().
> TBD: I'm not entirely sure how useful the conditionals are - there
>      shouldn't be any inaccuracies from the division when count equals
>      target (upon entry to the conditionals), as then the divisor is
>      what the original value was just multiplied by.
> 
> --- a/xen/arch/x86/time.c
> +++ b/xen/arch/x86/time.c
> @@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
>  
>  static int64_t __init init_hpet(struct platform_timesource *pts)
>  {
> -    uint64_t hpet_rate, start;
> +    uint64_t hpet_rate, start, expired;

Might be better named elapsed rather than expired?

It doesn't store the end of loop TSC value, but the delta between
start and end.

>      uint32_t count, target;
> +unsigned int i;//temp
>  
>      if ( hpet_address && strcmp(opt_clocksource, pts->id) &&
>           cpuidle_using_deep_cstate() )
> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>  
>      pts->frequency = hpet_rate;
>  
> +for(i = 0; i < 16; ++i) {//temp
>      count = hpet_read32(HPET_COUNTER);
>      start = rdtsc_ordered();
>      target = count + CALIBRATE_VALUE(hpet_rate);
>      if ( target < count )
>          while ( hpet_read32(HPET_COUNTER) >= count )
>              continue;
> -    while ( hpet_read32(HPET_COUNTER) < target )
> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>          continue;
>  
> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
> +    expired = rdtsc_ordered() - start;

There's also a window between the HPET read and the TSC read where an
SMI/NMI could cause a wrong frequency detection.

Thanks, Roger.

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 10.01.2022 13:37, Roger Pau Monné wrote:
> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>> x86: improve TSC / CPU freq calibration accuracy
>>
>> While the problem report was for extreme errors, even smaller ones would
>> better be avoided: The calculated period to run calibration loops over
>> can (and usually will) be shorter than the actual time elapsed between
>> first and last platform timer and TSC reads. Adjust values returned from
>> the init functions accordingly.
>>
>> On a Skylake system I've tested this on accuracy (using HPET) went from
>> detecting in some cases more than 220kHz too high a value to about
>> ±1kHz. On other systems the original error range was much smaller, with
>> less (in some cases only very little) improvement.
>>
>> Reported-by: James Dingwall <james-xen@dingwall.me.uk>
>> Signed-off-by: Jan Beulich <jbeulich@suse.com>
>> ---
>> TBD: Do we think we need to guard against the bizarre case of
>>      "target + count" overflowing (i.e. wrapping)?
> 
> I also wonder whether a value of target close enough to the wrapping
> point could cause the loop to stuck indefinitely, as count would
> overflow and thus the condition won't be meet.

Oh, good point. I guess I'll make another patch to deal with that;
you mentioning leaves me surprised we so far had no reports of such.

>> --- a/xen/arch/x86/time.c
>> +++ b/xen/arch/x86/time.c
>> @@ -378,8 +378,9 @@ static u64 read_hpet_count(void)
>>  
>>  static int64_t __init init_hpet(struct platform_timesource *pts)
>>  {
>> -    uint64_t hpet_rate, start;
>> +    uint64_t hpet_rate, start, expired;
> 
> Might be better named elapsed rather than expired?
> 
> It doesn't store the end of loop TSC value, but the delta between
> start and end.

I don't mind; I've renamed it, as the difference between the two in
this context isn't very clear to me anyway.

>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>  
>>      pts->frequency = hpet_rate;
>>  
>> +for(i = 0; i < 16; ++i) {//temp
>>      count = hpet_read32(HPET_COUNTER);
>>      start = rdtsc_ordered();
>>      target = count + CALIBRATE_VALUE(hpet_rate);
>>      if ( target < count )
>>          while ( hpet_read32(HPET_COUNTER) >= count )
>>              continue;
>> -    while ( hpet_read32(HPET_COUNTER) < target )
>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>          continue;
>>  
>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>> +    expired = rdtsc_ordered() - start;
> 
> There's also a window between the HPET read and the TSC read where an
> SMI/NMI could cause a wrong frequency detection.

Right, as said in an earlier reply I did notice this myself (actually
on the way home on Friday). As also said there, for now I can't see
any real (i.e. complete) solution to this and the similar instances
of the issue elsewhere.

Jan

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Andrew Cooper]

On 10/01/2022 13:11, Jan Beulich wrote:
> On 10.01.2022 13:37, Roger Pau Monné wrote:
>> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>>  
>>>      pts->frequency = hpet_rate;
>>>  
>>> +for(i = 0; i < 16; ++i) {//temp
>>>      count = hpet_read32(HPET_COUNTER);
>>>      start = rdtsc_ordered();
>>>      target = count + CALIBRATE_VALUE(hpet_rate);
>>>      if ( target < count )
>>>          while ( hpet_read32(HPET_COUNTER) >= count )
>>>              continue;
>>> -    while ( hpet_read32(HPET_COUNTER) < target )
>>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>>          continue;
>>>  
>>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>>> +    expired = rdtsc_ordered() - start;
>> There's also a window between the HPET read and the TSC read where an
>> SMI/NMI could cause a wrong frequency detection.
> Right, as said in an earlier reply I did notice this myself (actually
> on the way home on Friday). As also said there, for now I can't see
> any real (i.e. complete) solution to this and the similar instances
> of the issue elsewhere.

Calibration loops like this cannot be made robust.  This is specifically
why frequency information is being made available via architectural
means, and is available via non-architectural means in other cases.

There's a whole bunch of situations (#STOPCLK, TERM and PSMI off the top
of my head, but I bet HDC will screw with things too) which will mess
with any calibration loop, even if you could disable SMIs.  While,
mechanically, we can disable SMIs on AMD with CLGI, we absolutely
shouldn't run a calibration loop like this with SMIs disabled.


Much as I hate to suggest it, we should parse the frequency out of the
long CPUID string, and compare it to the calibration time.  (This
technique is mandated in the Intel BWG during very early setup.)

If it is different by a large margin, rerun the calibration, and if it
is still different, complain loudly into the logs.  This will fix a
one-off-spurious event, whereas if e.g. the system is thermally
throttling due to a bad heat sync, there is nothing software can do to
recover the system.

~Andrew

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 10.01.2022 16:43, Andrew Cooper wrote:
> On 10/01/2022 13:11, Jan Beulich wrote:
>> On 10.01.2022 13:37, Roger Pau Monné wrote:
>>> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>>>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>>>  
>>>>      pts->frequency = hpet_rate;
>>>>  
>>>> +for(i = 0; i < 16; ++i) {//temp
>>>>      count = hpet_read32(HPET_COUNTER);
>>>>      start = rdtsc_ordered();
>>>>      target = count + CALIBRATE_VALUE(hpet_rate);
>>>>      if ( target < count )
>>>>          while ( hpet_read32(HPET_COUNTER) >= count )
>>>>              continue;
>>>> -    while ( hpet_read32(HPET_COUNTER) < target )
>>>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>>>          continue;
>>>>  
>>>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>>>> +    expired = rdtsc_ordered() - start;
>>> There's also a window between the HPET read and the TSC read where an
>>> SMI/NMI could cause a wrong frequency detection.
>> Right, as said in an earlier reply I did notice this myself (actually
>> on the way home on Friday). As also said there, for now I can't see
>> any real (i.e. complete) solution to this and the similar instances
>> of the issue elsewhere.
> 
> Calibration loops like this cannot be made robust.  This is specifically
> why frequency information is being made available via architectural
> means, and is available via non-architectural means in other cases.
> 
> There's a whole bunch of situations (#STOPCLK, TERM and PSMI off the top
> of my head, but I bet HDC will screw with things too) which will mess
> with any calibration loop, even if you could disable SMIs.  While,
> mechanically, we can disable SMIs on AMD with CLGI, we absolutely
> shouldn't run a calibration loop like this with SMIs disabled.
> 
> 
> Much as I hate to suggest it, we should parse the frequency out of the
> long CPUID string, and compare it to the calibration time.  (This
> technique is mandated in the Intel BWG during very early setup.)

This, according to some initial checking, might work for Intel CPUs,
but apparently won't work for AMD ones (and I don't dare to think of
what might happen if we run under, say, qemu). Imo we'd need to deal
gracefully with the case that we can't parse the frequency out of
that string, with "gracefully" including that our calibration still
won't be too far off.

Also I wonder if we wouldn't better prefer CPUID leaf 0x15 / 0x16
data over parsing extended leaf.

> If it is different by a large margin, rerun the calibration, and if it
> is still different, complain loudly into the logs.  This will fix a
> one-off-spurious event, whereas if e.g. the system is thermally
> throttling due to a bad heat sync, there is nothing software can do to
> recover the system.

I was already considering to use reference data like that from CPUID
leaves 0x15 / 0x16, but I couldn't really settle on what "large
margin" would really want to be. Imo we should try to correct not-
just-as-large errors as well, if we can.

For the moment I continue to consider my plan (outlined in another
reply on this thread) superior to what you suggest, but I'll be
looking forward to further replies from you or others.

Jan

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Juergen Gross]

[-- Attachment #1.1.1: Type: text/plain, Size: 3843 bytes --]

On 10.01.22 18:04, Jan Beulich wrote:
> On 10.01.2022 16:43, Andrew Cooper wrote:
>> On 10/01/2022 13:11, Jan Beulich wrote:
>>> On 10.01.2022 13:37, Roger Pau Monné wrote:
>>>> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>>>>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>>>>   
>>>>>       pts->frequency = hpet_rate;
>>>>>   
>>>>> +for(i = 0; i < 16; ++i) {//temp
>>>>>       count = hpet_read32(HPET_COUNTER);
>>>>>       start = rdtsc_ordered();
>>>>>       target = count + CALIBRATE_VALUE(hpet_rate);
>>>>>       if ( target < count )
>>>>>           while ( hpet_read32(HPET_COUNTER) >= count )
>>>>>               continue;
>>>>> -    while ( hpet_read32(HPET_COUNTER) < target )
>>>>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>>>>           continue;
>>>>>   
>>>>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>>>>> +    expired = rdtsc_ordered() - start;
>>>> There's also a window between the HPET read and the TSC read where an
>>>> SMI/NMI could cause a wrong frequency detection.
>>> Right, as said in an earlier reply I did notice this myself (actually
>>> on the way home on Friday). As also said there, for now I can't see
>>> any real (i.e. complete) solution to this and the similar instances
>>> of the issue elsewhere.
>>
>> Calibration loops like this cannot be made robust.  This is specifically
>> why frequency information is being made available via architectural
>> means, and is available via non-architectural means in other cases.
>>
>> There's a whole bunch of situations (#STOPCLK, TERM and PSMI off the top
>> of my head, but I bet HDC will screw with things too) which will mess
>> with any calibration loop, even if you could disable SMIs.  While,
>> mechanically, we can disable SMIs on AMD with CLGI, we absolutely
>> shouldn't run a calibration loop like this with SMIs disabled.
>>
>>
>> Much as I hate to suggest it, we should parse the frequency out of the
>> long CPUID string, and compare it to the calibration time.  (This
>> technique is mandated in the Intel BWG during very early setup.)
> 
> This, according to some initial checking, might work for Intel CPUs,
> but apparently won't work for AMD ones (and I don't dare to think of
> what might happen if we run under, say, qemu). Imo we'd need to deal
> gracefully with the case that we can't parse the frequency out of
> that string, with "gracefully" including that our calibration still
> won't be too far off.
> 
> Also I wonder if we wouldn't better prefer CPUID leaf 0x15 / 0x16
> data over parsing extended leaf.
> 
>> If it is different by a large margin, rerun the calibration, and if it
>> is still different, complain loudly into the logs.  This will fix a
>> one-off-spurious event, whereas if e.g. the system is thermally
>> throttling due to a bad heat sync, there is nothing software can do to
>> recover the system.
> 
> I was already considering to use reference data like that from CPUID
> leaves 0x15 / 0x16, but I couldn't really settle on what "large
> margin" would really want to be. Imo we should try to correct not-
> just-as-large errors as well, if we can.
> 
> For the moment I continue to consider my plan (outlined in another
> reply on this thread) superior to what you suggest, but I'll be
> looking forward to further replies from you or others.

Didn't Andrew mention that SMIs can be detected to have happened via
an SMI counter?

I'd save the SMI counter (and possibly MCE and NMI counters, too)
before calibration and check them not to have changed afterwards.

In case one of the counters did change, redo the calibration.

In the qemu (or nested virt) case the frequency might just be wrong,
but this is no regression compared to today.


Juergen

[-- Attachment #1.1.2: OpenPGP public key --]
[-- Type: application/pgp-keys, Size: 3135 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 11.01.2022 06:32, Juergen Gross wrote:
> On 10.01.22 18:04, Jan Beulich wrote:
>> On 10.01.2022 16:43, Andrew Cooper wrote:
>>> On 10/01/2022 13:11, Jan Beulich wrote:
>>>> On 10.01.2022 13:37, Roger Pau Monné wrote:
>>>>> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>>>>>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>>>>>   
>>>>>>       pts->frequency = hpet_rate;
>>>>>>   
>>>>>> +for(i = 0; i < 16; ++i) {//temp
>>>>>>       count = hpet_read32(HPET_COUNTER);
>>>>>>       start = rdtsc_ordered();
>>>>>>       target = count + CALIBRATE_VALUE(hpet_rate);
>>>>>>       if ( target < count )
>>>>>>           while ( hpet_read32(HPET_COUNTER) >= count )
>>>>>>               continue;
>>>>>> -    while ( hpet_read32(HPET_COUNTER) < target )
>>>>>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>>>>>           continue;
>>>>>>   
>>>>>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>>>>>> +    expired = rdtsc_ordered() - start;
>>>>> There's also a window between the HPET read and the TSC read where an
>>>>> SMI/NMI could cause a wrong frequency detection.
>>>> Right, as said in an earlier reply I did notice this myself (actually
>>>> on the way home on Friday). As also said there, for now I can't see
>>>> any real (i.e. complete) solution to this and the similar instances
>>>> of the issue elsewhere.
>>>
>>> Calibration loops like this cannot be made robust.  This is specifically
>>> why frequency information is being made available via architectural
>>> means, and is available via non-architectural means in other cases.
>>>
>>> There's a whole bunch of situations (#STOPCLK, TERM and PSMI off the top
>>> of my head, but I bet HDC will screw with things too) which will mess
>>> with any calibration loop, even if you could disable SMIs.  While,
>>> mechanically, we can disable SMIs on AMD with CLGI, we absolutely
>>> shouldn't run a calibration loop like this with SMIs disabled.
>>>
>>>
>>> Much as I hate to suggest it, we should parse the frequency out of the
>>> long CPUID string, and compare it to the calibration time.  (This
>>> technique is mandated in the Intel BWG during very early setup.)
>>
>> This, according to some initial checking, might work for Intel CPUs,
>> but apparently won't work for AMD ones (and I don't dare to think of
>> what might happen if we run under, say, qemu). Imo we'd need to deal
>> gracefully with the case that we can't parse the frequency out of
>> that string, with "gracefully" including that our calibration still
>> won't be too far off.
>>
>> Also I wonder if we wouldn't better prefer CPUID leaf 0x15 / 0x16
>> data over parsing extended leaf.
>>
>>> If it is different by a large margin, rerun the calibration, and if it
>>> is still different, complain loudly into the logs.  This will fix a
>>> one-off-spurious event, whereas if e.g. the system is thermally
>>> throttling due to a bad heat sync, there is nothing software can do to
>>> recover the system.
>>
>> I was already considering to use reference data like that from CPUID
>> leaves 0x15 / 0x16, but I couldn't really settle on what "large
>> margin" would really want to be. Imo we should try to correct not-
>> just-as-large errors as well, if we can.
>>
>> For the moment I continue to consider my plan (outlined in another
>> reply on this thread) superior to what you suggest, but I'll be
>> looking forward to further replies from you or others.
> 
> Didn't Andrew mention that SMIs can be detected to have happened via
> an SMI counter?

Yes, but that's again an Intel-only thing. Plus, as said elsewhere,
I don't think it can be considered sufficient to account for SMI and
NMI alone - there can be any number of other things causing delays.

Jan

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 10.01.2022 18:04, Jan Beulich wrote:
> On 10.01.2022 16:43, Andrew Cooper wrote:
>> On 10/01/2022 13:11, Jan Beulich wrote:
>>> On 10.01.2022 13:37, Roger Pau Monné wrote:
>>>> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>>>>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>>>>  
>>>>>      pts->frequency = hpet_rate;
>>>>>  
>>>>> +for(i = 0; i < 16; ++i) {//temp
>>>>>      count = hpet_read32(HPET_COUNTER);
>>>>>      start = rdtsc_ordered();
>>>>>      target = count + CALIBRATE_VALUE(hpet_rate);
>>>>>      if ( target < count )
>>>>>          while ( hpet_read32(HPET_COUNTER) >= count )
>>>>>              continue;
>>>>> -    while ( hpet_read32(HPET_COUNTER) < target )
>>>>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>>>>          continue;
>>>>>  
>>>>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>>>>> +    expired = rdtsc_ordered() - start;
>>>> There's also a window between the HPET read and the TSC read where an
>>>> SMI/NMI could cause a wrong frequency detection.
>>> Right, as said in an earlier reply I did notice this myself (actually
>>> on the way home on Friday). As also said there, for now I can't see
>>> any real (i.e. complete) solution to this and the similar instances
>>> of the issue elsewhere.
>>
>> Calibration loops like this cannot be made robust.  This is specifically
>> why frequency information is being made available via architectural
>> means, and is available via non-architectural means in other cases.
>>
>> There's a whole bunch of situations (#STOPCLK, TERM and PSMI off the top
>> of my head, but I bet HDC will screw with things too) which will mess
>> with any calibration loop, even if you could disable SMIs.  While,
>> mechanically, we can disable SMIs on AMD with CLGI, we absolutely
>> shouldn't run a calibration loop like this with SMIs disabled.
>>
>>
>> Much as I hate to suggest it, we should parse the frequency out of the
>> long CPUID string, and compare it to the calibration time.  (This
>> technique is mandated in the Intel BWG during very early setup.)
> 
> This, according to some initial checking, might work for Intel CPUs,
> but apparently won't work for AMD ones (and I don't dare to think of
> what might happen if we run under, say, qemu). Imo we'd need to deal
> gracefully with the case that we can't parse the frequency out of
> that string, with "gracefully" including that our calibration still
> won't be too far off.

May I further (re-)emphasize the fact that the issue exists not only
in the calibration loops. There we wouldn't have a result that could
(in principle) be compared against some parsed value. Whereas my
proposed model can be adopted for use there as well (I think; I
didn't actually try it out yet, as I was hoping I was overlooking
some other, fully reliable approach).

Jan

Re: xen 4.14.3 incorrect (~3x) cpu frequency reported

[Jan Beulich]

On 10.01.2022 13:37, Roger Pau Monné wrote:
> On Fri, Jan 07, 2022 at 12:39:04PM +0100, Jan Beulich wrote:
>> @@ -415,16 +416,35 @@ static int64_t __init init_hpet(struct p
>>  
>>      pts->frequency = hpet_rate;
>>  
>> +for(i = 0; i < 16; ++i) {//temp
>>      count = hpet_read32(HPET_COUNTER);
>>      start = rdtsc_ordered();
>>      target = count + CALIBRATE_VALUE(hpet_rate);
>>      if ( target < count )
>>          while ( hpet_read32(HPET_COUNTER) >= count )
>>              continue;
>> -    while ( hpet_read32(HPET_COUNTER) < target )
>> +    while ( (count = hpet_read32(HPET_COUNTER)) < target )
>>          continue;
>>  
>> -    return (rdtsc_ordered() - start) * CALIBRATE_FRAC;
>> +    expired = rdtsc_ordered() - start;
> 
> There's also a window between the HPET read and the TSC read where an
> SMI/NMI could cause a wrong frequency detection.

It occurred to me only while preparing a draft change that this is an
issue not only for the tail pair of reads, but also for the initial pair.
Hence I'm now actually making a helper function to be used in both
places. This slightly sub-optimal as it means that it's not as easy to
make use of the last HPET read in the loop above, but I guess we can
tolerate that one extra read in preference over more complicated logic.

Jan