[PATCH] pmtmr and PRINTK_TIME timings display

[PATCH] pmtmr and PRINTK_TIME timings display

[Borislav Petkov]

Hi,

on my laptop ASUS M6B00N PRINTK_TIME is enabled in order to show timing 
information in all the boottime printk's. However, all output looks like this

<snip>
[4294667.997000] CPU: After generic identify, caps: a7e9fbbf 00000000 00000000 
00000000 00000180 00000000 00000000
[4294667.997000] CPU: After vendor identify, caps: a7e9fbbf 00000000 00000000 
00000000 00000180 00000000 00000000
[4294667.997000] CPU: L1 I cache: 32K, L1 D cache: 32K
[4294667.997000] CPU: L2 cache: 1024K
[4294667.997000] CPU: After all inits, caps: a7e9fbbf 00000000 00000000 
00000040 00000180 00000000 00000000
[4294667.997000] CPU: Intel(R) Pentium(R) M processor 1500MHz stepping 05
[4294667.997000] Enabling fast FPU save and restore... done.
[4294667.997000] Enabling unmasked SIMD FPU exception support... done.
[4294667.997000] Checking 'hlt' instruction... OK.
[4294668.041000] ACPI: setting ELCR to 0200 (from 0c30)
</snip>

If I'm not wrong, the time value that gets printed is actually the jiffies_64 
value set to INITIAL_JIFFIES, which in turn is set to wrap 5 minutes after 
boot so that "jiffies wrap bugs show up earlier." This is because 
sched_clock() in <arch/i386/kernel/timers/timer_tsc.c> returns the jiffies_64 
value converted to nanoseconds after checking use_tsc. This, in turn, is 0 
because my machine selects the power management timer as the high-res 
timesource before reading the timestamp counter for printk timing.

My desktop machine however, uses the tsc for printk timing and its boot 
messages look like this:

<snip>
[4294667.296000] mapped APIC to ffffd000 (fee00000)
[4294667.296000] mapped IOAPIC to ffffc000 (fec00000)
[4294667.296000] Initializing CPU#0
[4294667.296000] CPU 0 irqstacks, hard=c0481000 soft=c047f000
[4294667.296000] PID hash table entries: 2048 (order: 11, 32768 bytes)
[    0.000000] Detected 2606.874 MHz processor.
[   20.523785] Using tsc for high-res timesource
[   20.524715] Console: colour VGA+ 80x25
[   20.751678] Dentry cache hash table entries: 131072 (order: 7, 524288 
bytes)
[   20.760133] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[   20.778329] Memory: 514964k/524224k available (2127k kernel code, 8776k 
reserved, 1246k data, 180k init, 0k highmem)
</snip>

where you see the deltas between the printk's printed once the tsc timer is 
initialized as opposed to the first bootlog where you see all times relative 
to a single point in time. The python script <scripts/show_delta> in the 
kernel source converts between these two representations but there's a pretty 
simple solution IMHO to make PRINTK_TIME uniform and independent from the 
used timer. The one liner is against 2.6.12.3.

After applying it, printk timing looks like this:

<snip>
[    0.000000] Detected 1500.132 MHz processor.
[    0.000000] Using pmtmr for high-res timesource
[    0.000000] Console: colour VGA+ 80x25
[    1.890000] Dentry cache hash table entries: 131072 (order: 7, 524288 
bytes)
[    1.891000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    1.906000] Memory: 513756k/523520k available (2839k kernel code, 9276k 
reserved, 1148k data, 152k init, 0k highmem)
[    1.906000] Checking if this processor honours the WP bit even in 
supervisor mode... Ok.
[    1.906000] Calibrating delay loop... 2973.69 BogoMIPS (lpj=1486848)
[    1.928000] Security Framework v1.0.0 initialized
</snip>


Signed-off-by: Borislav Petkov <petkov@uni-muenster.de>

--- arch/i386/kernel/timers/timer_tsc.c.orig	2005-08-04 12:57:37.000000000 
+0200
+++ arch/i386/kernel/timers/timer_tsc.c	2005-08-04 14:19:48.000000000 +0200
@@ -146,7 +146,7 @@ unsigned long long sched_clock(void)
 	if (!use_tsc)
 #endif
 		/* no locking but a rare wrong value is not a big deal */
-		return jiffies_64 * (1000000000 / HZ);
+		return (jiffies_64 - INITIAL_JIFFIES) * (1000000000 / HZ);
 
 	/* Read the Time Stamp Counter */
 	rdtscll(this_offset);


-- 
Regards,
Borislav Petkov.

Re: [PATCH] pmtmr and PRINTK_TIME timings display

[Steven Rostedt]

On Thu, 2005-08-04 at 14:59 +0200, Borislav Petkov wrote:

> 
> where you see the deltas between the printk's printed once the tsc timer is 
> initialized as opposed to the first bootlog where you see all times relative 
> to a single point in time. The python script <scripts/show_delta> in the 
> kernel source converts between these two representations but there's a pretty 
> simple solution IMHO to make PRINTK_TIME uniform and independent from the 
> used timer. The one liner is against 2.6.12.3.
> 
> After applying it, printk timing looks like this:
> 
> <snip>
> [    0.000000] Detected 1500.132 MHz processor.
> [    0.000000] Using pmtmr for high-res timesource
> [    0.000000] Console: colour VGA+ 80x25
> [    1.890000] Dentry cache hash table entries: 131072 (order: 7, 524288 
> bytes)
> [    1.891000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
> [    1.906000] Memory: 513756k/523520k available (2839k kernel code, 9276k 
> reserved, 1148k data, 152k init, 0k highmem)
> [    1.906000] Checking if this processor honours the WP bit even in 
> supervisor mode... Ok.
> [    1.906000] Calibrating delay loop... 2973.69 BogoMIPS (lpj=1486848)
> [    1.928000] Security Framework v1.0.0 initialized
> </snip>
> 

But if you are debugging problems with jiffies wrapping, wouldn't you
want to see the jiffies unmodified?  I understand your point, but the
tsc output (which I do prefer) seems to only be for the tsc (on x86),
and all else use jiffies (haven't looked at other archs). So debugging a
problem with jiffy wrap*, one would need to use something other than the
tsc, and then they would see the time the wrap occurred.

Also, the big number stands out more than the 3 zeros, so when I see
that, I know right away to go and change it back to use the tsc (since
my debugging usually needs higher resolutions).

* new product from Renolds ;-)

-- Steve

Re: [PATCH] pmtmr and PRINTK_TIME timings display

[Borislav Petkov]

On Thursday 04 August 2005 15:19, Steven Rostedt wrote:
> On Thu, 2005-08-04 at 14:59 +0200, Borislav Petkov wrote:
> > where you see the deltas between the printk's printed once the tsc timer
> > is initialized as opposed to the first bootlog where you see all times
> > relative to a single point in time. The python script
> > <scripts/show_delta> in the kernel source converts between these two
> > representations but there's a pretty simple solution IMHO to make
> > PRINTK_TIME uniform and independent from the used timer. The one liner is
> > against 2.6.12.3.
> >
> > After applying it, printk timing looks like this:
> >
> > <snip>
> > [    0.000000] Detected 1500.132 MHz processor.
> > [    0.000000] Using pmtmr for high-res timesource
> > [    0.000000] Console: colour VGA+ 80x25
> > [    1.890000] Dentry cache hash table entries: 131072 (order: 7, 524288
> > bytes)
> > [    1.891000] Inode-cache hash table entries: 65536 (order: 6, 262144
> > bytes) [    1.906000] Memory: 513756k/523520k available (2839k kernel
> > code, 9276k reserved, 1148k data, 152k init, 0k highmem)
> > [    1.906000] Checking if this processor honours the WP bit even in
> > supervisor mode... Ok.
> > [    1.906000] Calibrating delay loop... 2973.69 BogoMIPS (lpj=1486848)
> > [    1.928000] Security Framework v1.0.0 initialized
> > </snip>
>
> But if you are debugging problems with jiffies wrapping, wouldn't you
> want to see the jiffies unmodified?  I understand your point, but the
> tsc output (which I do prefer) seems to only be for the tsc (on x86),
> and all else use jiffies (haven't looked at other archs). So debugging a
> problem with jiffy wrap*, one would need to use something other than the
> tsc, and then they would see the time the wrap occurred.
>
> Also, the big number stands out more than the 3 zeros, so when I see
> that, I know right away to go and change it back to use the tsc (since
> my debugging usually needs higher resolutions).
>
> * new product from Renolds ;-)
>
> -- Steve

I get it. Actually, I wasn't very sure whether this is the right solution 
since my desktop machine uses tsc timer as default while the laptop the 
pmtmr. I also remember that there was a patch a while ago on lkml which 
enabled a modifiable behavior for PRINTK_TIME through a /proc interface and 
kernel boot option but it somehow didn't get accepted. Ok, then, since we 
keep the jiffies solution across arch's, how can I force the kernel to use 
tsc for printk timings so that i can see the deltas between the different 
printk's instead of the jiffies_64 ns value? The Pentium-M Centrino on the 
laptop evidently supports rdtsc as a msr instruction after testing with this 
small inline assembly snippet:

#include <stdio.h>

int main()
{
		unsigned long long val;
		__asm__ __volatile__("rdtsc" : "=A" (val));
		printf("%llu\n", val);

		return 0;
}


-- 
Regards,
Borislav Petkov.

Re: [PATCH] pmtmr and PRINTK_TIME timings display

[Steven Rostedt]

> I get it. Actually, I wasn't very sure whether this is the right solution 
> since my desktop machine uses tsc timer as default while the laptop the 
> pmtmr. I also remember that there was a patch a while ago on lkml which 
> enabled a modifiable behavior for PRINTK_TIME through a /proc interface and 
> kernel boot option but it somehow didn't get accepted. Ok, then, since we 
> keep the jiffies solution across arch's, how can I force the kernel to use 
> tsc for printk timings so that i can see the deltas between the different 
> printk's instead of the jiffies_64 ns value? The Pentium-M Centrino on the 
> laptop evidently supports rdtsc as a msr instruction after testing with this 
> small inline assembly snippet:

Just turn off the PM timer by disabling CONFIG_X86_PM_TIMER, then your
laptop should just use the tsc timer.


>From make menuconfig:

 Prompt: Power Management Timer Support                                  │
  │   Defined at drivers/acpi/Kconfig:307                                   │
  │   Depends on: !X86_VOYAGER && !X86_VISWS && !IA64_HP_SIM && (IA64 || X8 │
  │   Location:                                                             │
  │     -> Power management options (ACPI, APM)                             │
  │       -> ACPI (Advanced Configuration and Power Interface) Support      │
  │         -> ACPI Support (ACPI [=y])           

-- Steve

Re: [PATCH] pmtmr and PRINTK_TIME timings display

[john stultz]

On Thu, 2005-08-04 at 14:59 +0200, Borislav Petkov wrote:
> Hi,
> 
> on my laptop ASUS M6B00N PRINTK_TIME is enabled in order to show timing 
> information in all the boottime printk's. However, all output looks like this
> 
> <snip>
> [4294667.997000] CPU: After generic identify, caps: a7e9fbbf 00000000 00000000 
> 00000000 00000180 00000000 00000000
> [4294667.997000] CPU: After vendor identify, caps: a7e9fbbf 00000000 00000000 
> 00000000 00000180 00000000 00000000
> [4294667.997000] CPU: L1 I cache: 32K, L1 D cache: 32K
> [4294667.997000] CPU: L2 cache: 1024K
> [4294667.997000] CPU: After all inits, caps: a7e9fbbf 00000000 00000000 
> 00000040 00000180 00000000 00000000
> [4294667.997000] CPU: Intel(R) Pentium(R) M processor 1500MHz stepping 05
> [4294667.997000] Enabling fast FPU save and restore... done.
> [4294667.997000] Enabling unmasked SIMD FPU exception support... done.
> [4294667.997000] Checking 'hlt' instruction... OK.
> [4294668.041000] ACPI: setting ELCR to 0200 (from 0c30)
> </snip>
> 
> If I'm not wrong, the time value that gets printed is actually the jiffies_64 
> value set to INITIAL_JIFFIES, which in turn is set to wrap 5 minutes after 
> boot so that "jiffies wrap bugs show up earlier." This is because 
> sched_clock() in <arch/i386/kernel/timers/timer_tsc.c> returns the jiffies_64 
> value converted to nanoseconds after checking use_tsc. This, in turn, is 0 
> because my machine selects the power management timer as the high-res 
> timesource before reading the timestamp counter for printk timing.
> 
[snip]
> After applying it, printk timing looks like this:
> 
> <snip>
> [    0.000000] Detected 1500.132 MHz processor.
> [    0.000000] Using pmtmr for high-res timesource
> [    0.000000] Console: colour VGA+ 80x25
> [    1.890000] Dentry cache hash table entries: 131072 (order: 7, 524288 
> bytes)
> [    1.891000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
> [    1.906000] Memory: 513756k/523520k available (2839k kernel code, 9276k 
> reserved, 1148k data, 152k init, 0k highmem)
> [    1.906000] Checking if this processor honours the WP bit even in 
> supervisor mode... Ok.
> [    1.906000] Calibrating delay loop... 2973.69 BogoMIPS (lpj=1486848)
> [    1.928000] Security Framework v1.0.0 initialized
> </snip>
> 
> 
> Signed-off-by: Borislav Petkov <petkov@uni-muenster.de>
> 
> --- arch/i386/kernel/timers/timer_tsc.c.orig	2005-08-04 12:57:37.000000000 
> +0200
> +++ arch/i386/kernel/timers/timer_tsc.c	2005-08-04 14:19:48.000000000 +0200
> @@ -146,7 +146,7 @@ unsigned long long sched_clock(void)
>  	if (!use_tsc)
>  #endif
>  		/* no locking but a rare wrong value is not a big deal */
> -		return jiffies_64 * (1000000000 / HZ);
> +		return (jiffies_64 - INITIAL_JIFFIES) * (1000000000 / HZ);
>  
>  	/* Read the Time Stamp Counter */
>  	rdtscll(this_offset);
> 
> 

This patch looks fine to me.
-john

Re: [PATCH] pmtmr and PRINTK_TIME timings display

[john stultz]

On Thu, 2005-08-04 at 17:23 +0200, Borislav Petkov wrote:
> I get it. Actually, I wasn't very sure whether this is the right solution 
> since my desktop machine uses tsc timer as default while the laptop the 
> pmtmr. I also remember that there was a patch a while ago on lkml which 
> enabled a modifiable behavior for PRINTK_TIME through a /proc interface and 
> kernel boot option but it somehow didn't get accepted. Ok, then, since we 
> keep the jiffies solution across arch's, how can I force the kernel to use 
> tsc for printk timings so that i can see the deltas between the different 
> printk's instead of the jiffies_64 ns value? The Pentium-M Centrino on the 
> laptop evidently supports rdtsc as a msr instruction.

The issue is that there are a number of laptops that do not properly
support cpufreq and additionally newer laptop chips halt their TSC's
when they go into C3 mode. This keeps the TSC from working as a proper
timesource on these systems, and causes the need for alternative
timesources like the ACPI PM timer. 

thanks
-john

Re: [PATCH] pmtmr and PRINTK_TIME timings display

[Borislav Petkov]

On Tuesday 16 August 2005 00:18, john stultz wrote:
> On Thu, 2005-08-04 at 17:23 +0200, Borislav Petkov wrote:
> > I get it. Actually, I wasn't very sure whether this is the right solution
> > since my desktop machine uses tsc timer as default while the laptop the
> > pmtmr. I also remember that there was a patch a while ago on lkml which
> > enabled a modifiable behavior for PRINTK_TIME through a /proc interface
> > and kernel boot option but it somehow didn't get accepted. Ok, then,
> > since we keep the jiffies solution across arch's, how can I force the
> > kernel to use tsc for printk timings so that i can see the deltas between
> > the different printk's instead of the jiffies_64 ns value? The Pentium-M
> > Centrino on the laptop evidently supports rdtsc as a msr instruction.
>
> The issue is that there are a number of laptops that do not properly
> support cpufreq and additionally newer laptop chips halt their TSC's
> when they go into C3 mode. This keeps the TSC from working as a proper
> timesource on these systems, and causes the need for alternative
> timesources like the ACPI PM timer.

This _is_ actually my laptop I'm testing it on and sofar no problem. But as 
Steven pointed out earlier, one probably needs a different kind of timing 
information besides delta timings. Besides, <scripts/show_delta> can do all 
the formatting and delta computation already.

Thanks & regards,
Borislav Petkov.