Clocksource tsc unstable (delta = -4398046474878 ns)

DISCUSSION Sebastian Hetze 4 participants 7 messages Mar 28, 2010 – Mar 31, 2010 KVM

lore

Share & tools

lore

Sebastian Hetze

author

2010-03-28 11:46 UTC #0 lore raw

Hi *,

this message appeared in the KVM guest kern.log last night:

Mar 27 22:35:30 guest kernel: [260041.559462] Clocksource tsc unstable (delta = -4398046474878 ns)

The guest is running a 2.6.31-20-generic-pae ubuntu kernel with hrtimer-tune-hrtimer_interrupt-hang-logic.patch applied.

If I understand things correct, in kernel/time/clocksource.c clocksource_watchdog() checks all the /sys/devices/system/clocksource/clocksource0/available_clocksource every 0.5sec for an delta of more than 0.0625s. So the tsc must have changed more than one hour within two subsequent calls of clocksource_watchdog. No event in the host nor anything in the guest gives reasonable cause for this step.

However, the number 4398046474878 is only 36226 ns away from 4*1024*1024*1024*1024

The guest is an 32 bit system running in a 64 bit host. Is this an possible cause of this strange message? Any other idea what is going wrong here? Maybe this is a hardware bug?

Best regards,

Sebastian

Athanasius

2010-03-29 10:48 UTC #1 lore raw

Quoted 15 lines · Sebastian Hetze

this message appeared in the KVM guest kern.log last night:
Mar 27 22:35:30 guest kernel: [260041.559462] Clocksource tsc unstable (delta = -4398046474878 ns)
The guest is running a 2.6.31-20-generic-pae ubuntu kernel with hrtimer-tune-hrtimer_interrupt-hang-logic.patch applied.
If I understand things correct, in kernel/time/clocksource.c clocksource_watchdog() checks all the /sys/devices/system/clocksource/clocksource0/available_clocksource every 0.5sec for an delta of more than 0.0625s. So the tsc must have changed more than one hour within two subsequent calls of clocksource_watchdog. No event in the host nor anything in the guest gives reasonable cause for this step.

Quoted 2 lines

However, the number 4398046474878 is only 36226 ns away from 4*1024*1024*1024*1024

I didn't see any such messages but I've had a recent experience with
the time on one KVM host leaping *forwards* approx. 5 and 2.5 hours in two separate incidents. Eerily the exact jumps, as best I can tell from logs are of 17592 and 8796 seconds, give or take a second or two. If you look at these as nanoseconds then that's 'exactly' 2^44 and 2^43 nanoseconds.
What I've done that seems to have avoided this happening again is drop
KVM_CLOCK kernel option from the kvm guests' kernel.

This is with a Debian squeeze (testing) KVM host running 2.6.33 from
vanilla sources and my own config. The guests are Debian lenny (stable) and were also running a 2.6.33 kernel from vanilla sources and my own (different, to match the virtual hardware in a KVM guest) config. Both systems/kernels are 64 bit. The base machine is a Dell R210 with an Intel Xeon X3450 quad-core CPU, with the hyper-threading enabled to give 8 visible CPUs in Linux. This only happened on one of the two guests, the much busier one (it does shell accounts, email, IMAP/POP3, a small news server and NFS serves web pages to the other guest which only runs apache2 and nagios3).
It took around 2-3 days to see the problem both times. Without
KVM_CLOCK it's been up and stable for well over a week now. Without KVM_CLOCK the only clocksource is acpi_pm and thus that is being used. I didn't test forcing that with a boot-time parameter and KVM_CLOCK still enabled.

Given turning KVM_CLOCK off fixed my problem and the problem repeating
itself causes all manner of trouble given how busy the machine is I'm not really willing to test alternative fixes.

Signature · 4 lines

- Athanasius = Athanasius(at)miggy.org / http://www.miggy.org/
                  Finger athan(at)fysh.org for PGP key
	   "And it's me who is my enemy. Me who beats me up.
Me who makes the monsters. Me who strips my confidence." Paula Cole - ME

Sebastian Hetze

author

2010-03-30 08:08 UTC #2 lore raw

Quoted 19 lines · Athanasius

Quoted 15 lines · Sebastian Hetze
this message appeared in the KVM guest kern.log last night:
Mar 27 22:35:30 guest kernel: [260041.559462] Clocksource tsc unstable (delta = -4398046474878 ns)
The guest is running a 2.6.31-20-generic-pae ubuntu kernel with hrtimer-tune-hrtimer_interrupt-hang-logic.patch applied.
If I understand things correct, in kernel/time/clocksource.c clocksource_watchdog() checks all the /sys/devices/system/clocksource/clocksource0/available_clocksource every 0.5sec for an delta of more than 0.0625s. So the tsc must have changed more than one hour within two subsequent calls of clocksource_watchdog. No event in the host nor anything in the guest gives reasonable cause for this step.
Quoted 2 lines
However, the number 4398046474878 is only 36226 ns away from 4*1024*1024*1024*1024

Quoted 8 lines

I didn't see any such messages but I've had a recent experience with
the time on one KVM host leaping *forwards* approx. 5 and 2.5 hours in two separate incidents. Eerily the exact jumps, as best I can tell from logs are of 17592 and 8796 seconds, give or take a second or two. If you look at these as nanoseconds then that's 'exactly' 2^44 and 2^43 nanoseconds.
What I've done that seems to have avoided this happening again is drop
KVM_CLOCK kernel option from the kvm guests' kernel.

To my understanding, kvm-clock is the best and most reliable clocksource available, so I do not think it is a good idea to disable it.

There is a lot of bit shift operation happening with the clocksources, so there may be a real bug hidden somewhere in the code. Somehow ntp adjustment is involved, can this cause such huge steps? Im my case, I actually have NTP running in the guest. However, the statistics show a pretty stable timing here.

Athanasius

2010-03-30 16:12 UTC #3 lore raw

Quoted 10 lines · Sebastian Hetze

Quoted 8 lines · Athanasius
I didn't see any such messages but I've had a recent experience with
the time on one KVM host leaping *forwards* approx. 5 and 2.5 hours in two separate incidents. Eerily the exact jumps, as best I can tell from logs are of 17592 and 8796 seconds, give or take a second or two. If you look at these as nanoseconds then that's 'exactly' 2^44 and 2^43 nanoseconds.
What I've done that seems to have avoided this happening again is drop
KVM_CLOCK kernel option from the kvm guests' kernel.

Quoted 8 lines

To my understanding, kvm-clock is the best and most reliable clocksource available, so I do not think it is a good idea to disable it.
There is a lot of bit shift operation happening with the clocksources, so there may be a real bug hidden somewhere in the code. Somehow ntp adjustment is involved, can this cause such huge steps? Im my case, I actually have NTP running in the guest. However, the statistics show a pretty stable timing here.

This is one thing thing to note, I *was* running ntpd in the affected
guest (and rather obviously, I still am). If there's some bad interaction between KVM_CLOCK and ntpd it needs documenting in the first instance and preferably also fixing.

Signature · 4 lines

- Athanasius = Athanasius(at)miggy.org / http://www.miggy.org/
                  Finger athan(at)fysh.org for PGP key
	   "And it's me who is my enemy. Me who beats me up.
Me who makes the monsters. Me who strips my confidence." Paula Cole - ME

Beinicke, Thomas

2010-03-30 17:14 UTC #4 lore raw

In reply to Sebastian Hetze

Quoted 36 lines · On Tuesday 30 March 2010 10:08:28 Sebastian Hetze wrote:

Quoted 28 lines · Athanasius
Quoted 16 lines · Sebastian Hetze
this message appeared in the KVM guest kern.log last night:
Mar 27 22:35:30 guest kernel: [260041.559462] Clocksource tsc unstable
(delta = -4398046474878 ns)
The guest is running a 2.6.31-20-generic-pae ubuntu kernel with hrtimer-tune-hrtimer_interrupt-hang-logic.patch applied.
If I understand things correct, in kernel/time/clocksource.c clocksource_watchdog() checks all the /sys/devices/system/clocksource/clocksource0/available_clocksource every 0.5sec for an delta of more than 0.0625s. So the tsc must have changed more than one hour within two subsequent calls of clocksource_watchdog. No event in the host nor anything in the guest gives reasonable cause for this step.
Quoted 3 lines
However, the number 4398046474878 is only 36226 ns away from 4*1024*1024*1024*1024
I didn't see any such messages but I've had a recent experience with
the time on one KVM host leaping *forwards* approx. 5 and 2.5 hours in two separate incidents. Eerily the exact jumps, as best I can tell from logs are of 17592 and 8796 seconds, give or take a second or two. If you look at these as nanoseconds then that's 'exactly' 2^44 and 2^43 nanoseconds.
Quoted 3 lines
What I've done that seems to have avoided this happening again is drop
KVM_CLOCK kernel option from the kvm guests' kernel.
To my understanding, kvm-clock is the best and most reliable clocksource available, so I do not think it is a good idea to disable it.

Quoted 9 lines

There is a lot of bit shift operation happening with the clocksources, so there may be a real bug hidden somewhere in the code. Somehow ntp adjustment is involved, can this cause such huge steps? Im my case, I actually have NTP running in the guest. However, the statistics show a pretty stable timing here.
--
To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

I am having the same problem occasional.
It only occurs if the VM is under heavy IO or CPU Load but I can't reproduce it 100%. It just never occurs on VMs that only serve a few web pages though. I also noticed that on a machine which has this problem even an ssh shell is *very* laggy so it's not just a cosmetic problem.

Would removing the hrtimer from the kernel config solve it or is it necessary for KVM?

I remember this problem has been posted her before though there wasn't any real conclusion or solution for it.

Zachary Amsden

2010-03-30 19:33 UTC #5 lore raw

Quoted 57 lines · Thomas

Quoted 39 lines · On Tuesday 30 March 2010 10:08:28 Sebastian Hetze wrote:
Quoted 30 lines · Athanasius
Quoted 16 lines · Sebastian Hetze
this message appeared in the KVM guest kern.log last night:
Mar 27 22:35:30 guest kernel: [260041.559462] Clocksource tsc unstable
(delta = -4398046474878 ns)
The guest is running a 2.6.31-20-generic-pae ubuntu kernel with hrtimer-tune-hrtimer_interrupt-hang-logic.patch applied.
If I understand things correct, in kernel/time/clocksource.c clocksource_watchdog() checks all the /sys/devices/system/clocksource/clocksource0/available_clocksource every 0.5sec for an delta of more than 0.0625s. So the tsc must have changed more than one hour within two subsequent calls of clocksource_watchdog. No event in the host nor anything in the guest gives reasonable cause for this step.
Quoted 4 lines
However, the number 4398046474878 is only 36226 ns away from 4*1024*1024*1024*1024
I didn't see any such messages but I've had a recent experience with
the time on one KVM host leaping *forwards* approx. 5 and 2.5 hours in two separate incidents. Eerily the exact jumps, as best I can tell from logs are of 17592 and 8796 seconds, give or take a second or two. If you look at these as nanoseconds then that's 'exactly' 2^44 and 2^43 nanoseconds.
Quoted 4 lines
What I've done that seems to have avoided this happening again is drop
KVM_CLOCK kernel option from the kvm guests' kernel.
To my understanding, kvm-clock is the best and most reliable clocksource available, so I do not think it is a good idea to disable it.
Quoted 10 lines
There is a lot of bit shift operation happening with the clocksources, so there may be a real bug hidden somewhere in the code. Somehow ntp adjustment is involved, can this cause such huge steps? Im my case, I actually have NTP running in the guest. However, the statistics show a pretty stable timing here.
--
To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
I am having the same problem occasional.
It only occurs if the VM is under heavy IO or CPU Load but I can't reproduce it 100%. It just never occurs on VMs that only serve a few web pages though. I also noticed that on a machine which has this problem even an ssh shell is *very* laggy so it's not just a cosmetic problem.

Quoted 6 lines

Would removing the hrtimer from the kernel config solve it or is it necessary for KVM?
I remember this problem has been posted her before though there wasn't any real conclusion or solution for it.

Are you also running a 32-bit kernel?

Thanks,

Zach

Beinicke, Thomas

2010-03-31 13:09 UTC #6 lore raw

Quoted 55 lines · On Wednesday 31 March 2010 21:32:18 you wrote:

Quoted 54 lines · Thomas
Quoted 37 lines · On Tuesday 30 March 2010 10:08:28 Sebastian Hetze wrote:
Quoted 28 lines · Athanasius
Quoted 16 lines · Sebastian Hetze
this message appeared in the KVM guest kern.log last night:
Mar 27 22:35:30 guest kernel: [260041.559462] Clocksource tsc unstable
(delta = -4398046474878 ns)
The guest is running a 2.6.31-20-generic-pae ubuntu kernel with hrtimer-tune-hrtimer_interrupt-hang-logic.patch applied.
If I understand things correct, in kernel/time/clocksource.c clocksource_watchdog() checks all the /sys/devices/system/clocksource/clocksource0/available_clocksource every 0.5sec for an delta of more than 0.0625s. So the tsc must have changed more than one hour within two subsequent calls of clocksource_watchdog. No event in the host nor anything in the guest gives reasonable cause for this step.
Quoted 3 lines
However, the number 4398046474878 is only 36226 ns away from 4*1024*1024*1024*1024
I didn't see any such messages but I've had a recent experience with
the time on one KVM host leaping *forwards* approx. 5 and 2.5 hours in two separate incidents. Eerily the exact jumps, as best I can tell from logs are of 17592 and 8796 seconds, give or take a second or two.
If you look at these as nanoseconds then that's 'exactly' 2^44 and
2^43 nanoseconds.
Quoted 4 lines
What I've done that seems to have avoided this happening again is drop
KVM_CLOCK kernel option from the kvm guests' kernel.
To my understanding, kvm-clock is the best and most reliable clocksource available, so I do not think it is a good idea to disable it.
Quoted 9 lines
There is a lot of bit shift operation happening with the clocksources, so there may be a real bug hidden somewhere in the code. Somehow ntp adjustment is involved, can this cause such huge steps? Im my case, I actually have NTP running in the guest. However, the statistics show a pretty stable timing here.
--
To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
I am having the same problem occasional.
It only occurs if the VM is under heavy IO or CPU Load but I can't reproduce it 100%. It just never occurs on VMs that only serve a few web pages though. I also noticed that on a machine which has this problem even an ssh shell is *very* laggy so it's not just a cosmetic problem.

Quoted 7 lines

Quoted 5 lines
Would removing the hrtimer from the kernel config solve it or is it necessary for KVM?
I remember this problem has been posted her before though there wasn't any real conclusion or solution for it.
Are you also running a 32-bit kernel?

I have the problem on 32-bit and 64-bit clients.
The host machines are all 64-bit.

Quoted 3 lines

Thanks,
Zach