Bug 437252

Summary: kernel: Timer ISR/0: Time went backwards
Product: Red Hat Enterprise Linux 5 Reporter: Alexander Todorov <atodorov>
Component: kernel-xenAssignee: Bill Burns <bburns>
Status: CLOSED ERRATA QA Contact: Martin Jenner <mjenner>
Severity: high Docs Contact:
Priority: high    
Version: 5.2CC: borgan, jlaska, jlv, mbooth, mgiles, peterm, prarit, xen-maint
Target Milestone: rcKeywords: Regression
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
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 15:11:42 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 617043    
Attachments:
Description Flags
/var/log/messages right after booting with the faulty kernel
none
xm dmesg output none

Description Alexander Todorov 2008-03-13 09:07:47 UTC 
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 11:49:19 UTC 
Can you please attach the entire messages file and the output of xm dmesg as
well? Thanks.
Comment 2 Alexander Todorov 2008-03-13 12:43:09 UTC 
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 12:43:32 UTC 
Created attachment 297929 [details]
xm dmesg output
Comment 4 Prarit Bhargava 2008-03-18 14:37:57 UTC 
*** Bug 437275 has been marked as a duplicate of this bug. ***
Comment 5 Bill Burns 2008-03-18 18:54:15 UTC 
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 19:32:31 UTC 
This was a regression from previous behavior.
Comment 7 Bill Burns 2008-03-18 20:24:58 UTC 
*** Bug 437199 has been marked as a duplicate of this bug. ***
Comment 9 Bill Burns 2008-03-19 11:45:41 UTC 
brew build available here, for about a week:
http://brewweb.devel.redhat.com/brew/taskinfo?taskID=1218099
Comment 10 Don Zickus 2008-03-26 20:31:58 UTC 
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 15:11:42 UTC 
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