Re: 2.6.25.2 - Jiffies/Time jumping back and forth (Regereesion from 2.6.24)

[Martin Knoblauch <knobi@knobisoft.de>]

----- Original Message ----

> From: Martin Knoblauch <spamtrap@knobisoft.de>
> To: Thomas Gleixner <tglx@linutronix.de>
> Cc: Gabriel C <nix.or.die@googlemail.com>; Bart Van Assche <bart.vanassche@gmail.com>; linux-kernel@vger.kernel.org; hmh@hmh.eng.br
> Sent: Friday, May 9, 2008 3:01:10 PM
> Subject: Re: 2.6.25.2 - Jiffies/Time jumping back and forth (Regereesion from 2.6.24)
> 
> ----- Original Message ----
> 
> > From: Thomas Gleixner 
> > To: Martin Knoblauch 
> > Cc: Gabriel C ; Bart Van Assche 
> ; linux-kernel@vger.kernel.org; hmh@hmh.eng.br
> > Sent: Thursday, May 8, 2008 4:13:55 PM
> > Subject: Re: 2.6.25.2 - Jiffies/Time jumping back and forth (Regereesion from 
> 2.6.24)
> > 
> > On Thu, 8 May 2008, Martin Knoblauch wrote:
> > > on two different systems running 2.6.25.2:
> > > 
> > > ibm x3650(2xDualCore)
> > > -------------------------------------
> > > [root@lpsdm60 ~]# cat 
> > /sys/devices/system/clocksource/clocksource0/available_clocksource
> > > tsc hpet acpi_pm jiffies
> > > [root@lpsdm60 ~]# cat 
> > /sys/devices/system/clocksource/clocksource0/current_clocksource
> > > tsc
> > > 
> > > HP Proliant DL-380G4 (2xSingleCore)
> > > ------------------------------------------------------------
> > > [root@lpsdm52 ~]# cat 
> > /sys/devices/system/clocksource/clocksource0/available_clocksource
> > > tsc hpet acpi_pm jiffies
> > > [root@lpsdm52 ~]# cat 
> > /sys/devices/system/clocksource/clocksource0/current_clocksource
> > > tsc
> > > 
> > > and on the DL380G4 running 2.6.24:
> > > ---------------------------------------------------------
> > > [root@lpsdm52 ~]# cat 
> > /sys/devices/system/clocksource/clocksource0/available_clocksource
> > > hpet acpi_pm jiffies tsc
> > > [root@lpsdm52 ~]# cat 
> > /sys/devices/system/clocksource/clocksource0/current_clocksource
> > > hpet
> > 
> > So on 2.6.24 the TSC is declared unstable at some point and 2.6.25
> > thinks it works fine. Is this the same kernel config (aside of the 24/25 fuzz) 
> ?
> > 
> > Thanks,
> >     tglx
> 
> hah. I love open source :-)
> 
> Between 2.6.24 and 2.6.25 there was some patching in "kernel/printk.c". 
> Especially this is interesting:
> 
> 
> @@ -680,7 +742,7 @@
>                                         loglev_char = default_message_loglevel
>                                                 + '0';
>                                 }
> -                               t = printk_clock();
> +                               t = cpu_clock(printk_cpu);
>                                 nanosec_rem = do_div(t, 1000000000);
>                                 tlen = sprintf(tbuf,
>                                                 "<%c>[%5lu.%06lu] ",
> 
> 
> Where "prink_clock()" basically translates into "sched_clock()" in 2.6.24. If I 
> change the 2.6.25 version to directly call "sched_clock()", the timestamps are 
> back to the expected values and are no longer jumping back and forth. So, 
> something in "cpu_clock()" is fishy.
> 

 so, I added the "/printk_cpu#" to the printk timestamp. It seems that the jumping is depends on which CPU is used in the call to cpu_clock(). They seem to run at different speeds.

[    0.000000/0] TSC calibrated against PM_TIMER
[    0.000003/0] time.c: Detected 2327.507 MHz processor.
[    0.002112/0] Console: colour VGA+ 80x25
[    0.002119/0] console [tty0] enabled
[    0.002147/0] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.002148/0] ... MAX_LOCKDEP_SUBCLASSES:    8
[    0.002149/0] ... MAX_LOCK_DEPTH:          48
[    0.002151/0] ... MAX_LOCKDEP_KEYS:        2048
[    0.002152/0] ... CLASSHASH_SIZE:           1024
[    0.002153/0] ... MAX_LOCKDEP_ENTRIES:     8192
[    0.002154/0] ... MAX_LOCKDEP_CHAINS:      16384
[    0.002156/0] ... CHAINHASH_SIZE:          8192
[    0.002157/0]  memory used by lock dependency info: 1712 kB
[    0.002158/0]  per task-struct memory footprint: 3456 bytes
[    0.002161/0] Checking aperture...
[    0.002170/0] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    0.004000/0] Placing software IO TLB between 0x15093000 - 0x19093000
[    0.004000/0] Memory: 8110260k/9437184k available (2945k kernel code, 277728k reserved, 1568k data, 796k init)
[    0.004000/0] CPA: page pool initialized 1 of 1 pages preallocated
[    0.004000/0] hpet clockevent registered
[    0.080008/0] Calibrating delay using timer specific routine.. 4660.35 BogoMIPS (lpj=9320712)
[    0.080104/0] Security Framework initialized
[    0.080110/0] SELinux:  Initializing.
[    0.080150/0] SELinux:  Starting in permissive mode
[    0.080157/0] selinux_register_security:  Registering secondary module capability
[    0.080159/0] Capability LSM initialized as secondary
[    0.080904/0] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes)
[    0.085951/0] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.088684/0] Mount-cache hash table entries: 256
[    0.089128/0] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.089130/0] CPU: L2 cache: 4096K
[    0.089133/0] CPU 0/0 -> Node 0
[    0.089135/0] CPU: Physical Processor ID: 0
[    0.089136/0] CPU: Processor Core ID: 0
[    0.089142/0] CPU0: Thermal monitoring enabled (TM2)
[    0.089144/0] using mwait in idle threads.
[    0.089152/0] Freeing SMP alternatives: 22k freed
[    0.089171/0] ACPI: Core revision 20070126
[    0.135354/0] Using local APIC timer interrupts.
[    0.136010/0] APIC timer calibration result 20781297
[    0.136012/0] Detected 20.781 MHz APIC timer.
[    0.136435/0] lockdep: fixing up alternatives.
[    0.136478/0] Booting processor 1/4 APIC 0x1
[    0.004000/1] Initializing CPU#1
[    0.004000/1] Calibrating delay using timer specific routine.. 4655.08 BogoMIPS (lpj=9310168)
[    0.004000/1] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.004000/1] CPU: L2 cache: 4096K
[    0.004000/1] CPU 1/1 -> Node 0
[    0.004000/1] CPU: Physical Processor ID: 0
[    0.004000/1] CPU: Processor Core ID: 1
[    0.004000/1] CPU1: Thermal monitoring enabled (TM2)
[    0.004000/1] Intel(R) Xeon(R) CPU            5140  @ 2.33GHz stepping 06
[    0.224558/0] checking TSC synchronization [CPU#0 -> CPU#1]: passed.
[    0.228357/0] lockdep: fixing up alternatives.
[    0.228392/0] Booting processor 2/4 APIC 0x6
[    0.004000/2] Initializing CPU#2
[    0.004000/2] Calibrating delay using timer specific routine.. 4655.12 BogoMIPS (lpj=9310252)
[    0.004000/2] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.004000/2] CPU: L2 cache: 4096K
[    0.004000/2] CPU 2/6 -> Node 0
[    0.004000/2] CPU: Physical Processor ID: 3
[    0.004000/2] CPU: Processor Core ID: 0
[    0.004000/2] CPU2: Thermal monitoring enabled (TM2)
[    0.004000/2] Intel(R) Xeon(R) CPU            5140  @ 2.33GHz stepping 06
[    0.316632/0] checking TSC synchronization [CPU#0 -> CPU#2]: passed.
[    0.320292/0] lockdep: fixing up alternatives.
[    0.320325/0] Booting processor 3/4 APIC 0x7
[    0.004000/3] Initializing CPU#3
[    0.004000/3] Calibrating delay using timer specific routine.. 4655.13 BogoMIPS (lpj=9310270)
[    0.004000/3] CPU: L1 I cache: 32K, L1 D cache: 32K
[    0.004000/3] CPU: L2 cache: 4096K
[    0.004000/3] CPU 3/7 -> Node 0
[    0.004000/3] CPU: Physical Processor ID: 3
[    0.004000/3] CPU: Processor Core ID: 1
[    0.004000/3] CPU3: Thermal monitoring enabled (TM2)
[    0.004000/3] Intel(R) Xeon(R) CPU            5140  @ 2.33GHz stepping 06
[    0.408625/0] checking TSC synchronization [CPU#0 -> CPU#3]: passed.
[    0.412054/0] Brought up 4 CPUs
[    0.412168/0] CPU0 attaching sched-domain:
[    0.412170/0]  domain 0: span 03
[    0.412172/0]   groups: 01 02
[    0.412175/0]   domain 1: span 0f
[    0.412176/0]    groups: 03 0c
[    0.412179/0]    domain 2: span 0f