Bug 437252 - kernel: Timer ISR/0: Time went backwards
Summary: kernel: Timer ISR/0: Time went backwards
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: kernel-xen
Version: 5.2
Hardware: x86_64
OS: Linux
high
high
Target Milestone: rc
: ---
Assignee: Bill Burns
QA Contact: Martin Jenner
URL:
Whiteboard:
: 437199 437275 (view as bug list)
Depends On:
Blocks: 617043
TreeView+ depends on / blocked
 
Reported: 2008-03-13 09:07 UTC by Alexander Todorov
Modified: 2010-08-09 09:03 UTC (History)
8 users (show)

Fixed In Version: RHBA-2008-0314
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 617043 (view as bug list)
Environment:
Last Closed: 2008-05-21 15:11:42 UTC
Target Upstream Version:
Embargoed:


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


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2008:0314 0 normal SHIPPED_LIVE Updated kernel packages for Red Hat Enterprise Linux 5.2 2008-05-20 18:43:34 UTC

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



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