Bug 437252 - kernel: Timer ISR/0: Time went backwards
kernel: Timer ISR/0: Time went backwards
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: kernel-xen (Show other bugs)
5.2
x86_64 Linux
high Severity high
: rc
: ---
Assigned To: Bill Burns
Martin Jenner
: Regression
: 437199 437275 (view as bug list)
Depends On:
Blocks: 617043
  Show dependency treegraph
 
Reported: 2008-03-13 05:07 EDT by Alexander Todorov
Modified: 2010-08-09 05:03 EDT (History)
8 users (show)

See Also:
Fixed In Version: RHBA-2008-0314
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 617043 (view as bug list)
Environment:
Last Closed: 2008-05-21 11:11:42 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
/var/log/messages right after booting with the faulty kernel (600.65 KB, text/plain)
2008-03-13 08:43 EDT, Alexander Todorov
no flags Details
xm dmesg output (5.23 KB, text/plain)
2008-03-13 08:43 EDT, Alexander Todorov
no flags Details

  None (edit)
Description Alexander Todorov 2008-03-13 05:07:47 EDT
Description of problem:
Booting with the new RHEL 5.2 beta, kernel-xen is causing the system to run very
slowly. There are messages in /var/log/messages of the form:
Mar 13 09:47:18 redbull kernel: Timer ISR/0: Time went backwards:
delta=-182760806 delta_cpu=337239194 shadow=14464641200 off=1356607073
processed=16004000000 cpu_processed
=15484000000
Mar 13 09:47:18 redbull kernel:  0: 15484000000
Mar 13 09:47:18 redbull kernel:  1: 16004000000
Mar 13 09:47:18 redbull kernel: Timer ISR/0: Time went backwards:
delta=-229675725 delta_cpu=342324275 shadow=14464641200 off=1697691741
processed=16392000000 cpu_processed
=15820000000
Mar 13 09:47:18 redbull kernel:  0: 15820000000
Mar 13 09:47:18 redbull kernel:  1: 16392000000
Mar 13 09:47:18 redbull kernel: Timer ISR/0: Time went backwards:
delta=-277581555 delta_cpu=342418445 shadow=16502019442 off=404896
processed=16780000000 cpu_processed=161
60000000
Mar 13 09:47:18 redbull kernel:  0: 16160000000
Mar 13 09:47:19 redbull kernel:  1: 16776000000
Mar 13 09:47:19 redbull kernel: ata2: SATA link down (SStatus 0 SControl 0)
Mar 13 09:47:19 redbull kernel: Timer ISR/0: Time went backwards:
delta=-143853727 delta_cpu=244146273 shadow=16502019442 off=242133019
processed=16888000000 cpu_processed=
16500000000
Mar 13 09:47:19 redbull kernel:  0: 16500000000
Mar 13 09:47:19 redbull kernel:  1: 16888000000
Mar 13 09:47:19 redbull kernel: ata3: SATA link down (SStatus 0 SControl 0)
Mar 13 09:47:19 redbull kernel: Timer ISR/1: Time went backwards:
delta=-18651767 delta_cpu=109348233 shadow=16782375409 off=430977242
processed=17232000000 cpu_processed=1
7104000000
Mar 13 09:47:19 redbull kernel:  0: 17228000000
Mar 13 09:47:19 redbull kernel:  1: 17104000000
Mar 13 09:47:19 redbull kernel: Timer ISR/1: Time went backwards:
delta=-150657850 delta_cpu=113342150 shadow=16782375409 off=538969600
processed=17472000000 cpu_processed=
17208000000

That are printed constantly

Version-Release number of selected component (if applicable):
kernel-xen-2.6.18-84.el5

How reproducible:
100%

Steps to Reproduce:
1. Boot the system with kernel-xen
2.
3.
  
Actual results:
System running slowly, about 15min until start of GDM. The above messages in
/var/log/messages (and on tty2 also)

Expected results:
Normal operation. 

Additional info:
This is on lenovo T60 laptop. Booting with non xen kernel is fine. system start
time is as normal.
Comment 1 Bill Burns 2008-03-13 07:49:19 EDT
Can you please attach the entire messages file and the output of xm dmesg as
well? Thanks.
Comment 2 Alexander Todorov 2008-03-13 08:43:09 EDT
Created attachment 297928 [details]
/var/log/messages right after booting with the faulty kernel

Noticed also messages of:
BUG: soft lockup - CPU#0 stuck for 10s! [swapper:0]

in the log and for CPU#0, CPU#1 on the console.
Comment 3 Alexander Todorov 2008-03-13 08:43:32 EDT
Created attachment 297929 [details]
xm dmesg output
Comment 4 Prarit Bhargava 2008-03-18 10:37:57 EDT
*** Bug 437275 has been marked as a duplicate of this bug. ***
Comment 5 Bill Burns 2008-03-18 14:54:15 EDT
Fix is known. Patch to add an alternate idle_loop for profiling exposed the xen
idle code to manipulation by other subsystems causing improper idle looping for
xen. This caused time went backwards, soft lockups, etc. Fix is to remove patch
22307: linux-2.6-xen-idle-poll-instead-of-hypercall-block.patch
Comment 6 Bill Burns 2008-03-18 15:32:31 EDT
This was a regression from previous behavior.
Comment 7 Bill Burns 2008-03-18 16:24:58 EDT
*** Bug 437199 has been marked as a duplicate of this bug. ***
Comment 9 Bill Burns 2008-03-19 07:45:41 EDT
brew build available here, for about a week:
http://brewweb.devel.redhat.com/brew/taskinfo?taskID=1218099
Comment 10 Don Zickus 2008-03-26 16:31:58 EDT
in kernel-2.6.18-87.el5
You can download this test kernel from http://people.redhat.com/dzickus/el5
Comment 14 errata-xmlrpc 2008-05-21 11:11:42 EDT
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on the solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2008-0314.html

Note You need to log in before you can comment on or make changes to this bug.