[PATCH] printk_time: prepare stub for using other than cpu_clock

[PATCH] printk_time: prepare stub for using other than cpu_clock

[Yinghai Lu]

Signed-off-by: Yinghai Lu <yhlu.kernel@gmail.com>

---
 include/linux/kernel.h |    5 +++++
 init/main.c            |    1 +
 kernel/printk.c        |   14 +++++++++++++-
 3 files changed, 19 insertions(+), 1 deletion(-)

Index: linux-2.6/include/linux/kernel.h
===================================================================
--- linux-2.6.orig/include/linux/kernel.h
+++ linux-2.6/include/linux/kernel.h
@@ -190,7 +190,10 @@ extern int kernel_text_address(unsigned
 struct pid;
 extern struct pid *session_of_pgrp(struct pid *pgrp);
 
+typedef unsigned long long (*printk_time_clock_fn)(int cpu);
 #ifdef CONFIG_PRINTK
+extern void set_printk_time_clock(printk_time_clock_fn fn);
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
@@ -201,6 +204,8 @@ extern int printk_ratelimit(void);
 extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 				   unsigned int interval_msec);
 #else
+static inline void set_printk_time_clock(printk_time_clock_fn fn) { }
+
 static inline int vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 static inline int vprintk(const char *s, va_list args) { return 0; }
Index: linux-2.6/init/main.c
===================================================================
--- linux-2.6.orig/init/main.c
+++ linux-2.6/init/main.c
@@ -671,6 +671,7 @@ asmlinkage void __init start_kernel(void
 	if (late_time_init)
 		late_time_init();
 	calibrate_delay();
+	set_printk_time_clock(cpu_clock);
 	pidmap_init();
 	pgtable_cache_init();
 	prio_tree_init();
Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -659,6 +659,18 @@ static int recursion_bug;
 	static int new_text_line = 1;
 static char printk_buf[1024];
 
+static unsigned long long default_printk_time_clock(int cpu)
+{
+	return 0;
+}
+
+static printk_time_clock_fn printk_time_clock = default_printk_time_clock;
+
+void set_printk_time_clock(printk_time_clock_fn fn)
+{
+	printk_time_clock = fn;
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -734,7 +746,7 @@ asmlinkage int vprintk(const char *fmt,
 				unsigned long long t;
 				unsigned long nanosec_rem;
 
-				t = cpu_clock(printk_cpu);
+				t = printk_time_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
 				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
 						(unsigned long) t,

[PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Yinghai Lu]

so can get tsc value on printk at first.

for debug delay with big system with a lot of memory.

need to apply after
	[PATCH] printk_time: prepare stub for using other than cpu_clock

Signed-off-by: Yinghai Lu <yhlu.kernel@gmail.com>

---
 arch/x86/kernel/cpu/common.c    |   11 +++++++++++
 arch/x86/kernel/cpu/common_64.c |   12 ++++++++++++
 2 files changed, 23 insertions(+)

Index: linux-2.6/arch/x86/kernel/cpu/common.c
===================================================================
--- linux-2.6.orig/arch/x86/kernel/cpu/common.c
+++ linux-2.6/arch/x86/kernel/cpu/common.c
@@ -647,6 +647,15 @@ __setup("clearcpuid=", setup_disablecpui
 
 cpumask_t cpu_initialized __cpuinitdata = CPU_MASK_NONE;
 
+static unsigned long long tsc_clock(int cpu)
+{
+	unsigned long long t;
+
+	rdtscll(t);
+
+	return t;
+}
+
 void __init early_cpu_init(void)
 {
 	struct cpu_vendor_dev *cvdev;
@@ -657,6 +666,8 @@ void __init early_cpu_init(void)
 		cpu_devs[cvdev->vendor] = cvdev->cpu_dev;
 
 	early_cpu_detect();
+	if (cpu_has_tsc)
+		set_printk_time_clock(tsc_clock);
 	validate_pat_support(&boot_cpu_data);
 }
 
Index: linux-2.6/arch/x86/kernel/cpu/common_64.c
===================================================================
--- linux-2.6.orig/arch/x86/kernel/cpu/common_64.c
+++ linux-2.6/arch/x86/kernel/cpu/common_64.c
@@ -249,6 +249,15 @@ static void __cpuinit detect_nopl(struct
 	}
 }
 
+static unsigned long long tsc_clock(int cpu)
+{
+	unsigned long long t;
+
+	rdtscll(t);
+
+	return t;
+}
+
 static void __cpuinit early_identify_cpu(struct cpuinfo_x86 *c);
 
 void __init early_cpu_init(void)
@@ -261,6 +270,9 @@ void __init early_cpu_init(void)
                 cpu_devs[cvdev->vendor] = cvdev->cpu_dev;
 	early_cpu_support_print();
 	early_identify_cpu(&boot_cpu_data);
+
+	if (cpu_has_tsc)
+		set_printk_time_clock(tsc_clock);
 }
 
 /* Do some early cpuid on the boot CPU to get some parameter that are

Re: [PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Ingo Molnar]

* Yinghai Lu <yhlu.kernel@gmail.com> wrote:

> +static unsigned long long tsc_clock(int cpu)
> +{
> +	unsigned long long t;
> +
> +	rdtscll(t);
> +
> +	return t;
> +}

hm, i'm not sure i like the whole direction - this reintroduces 
printk_clock in essence.

how about initializing cpu_clock() sooner, so that printk timestamps 
start ticking as soon as possible?

	Ingo

Re: [PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Peter Zijlstra]

On Wed, 2008-08-27 at 09:42 +0200, Ingo Molnar wrote:
> * Yinghai Lu <yhlu.kernel@gmail.com> wrote:
> 
> > +static unsigned long long tsc_clock(int cpu)
> > +{
> > +	unsigned long long t;
> > +
> > +	rdtscll(t);
> > +
> > +	return t;
> > +}
> 
> hm, i'm not sure i like the whole direction - this reintroduces 
> printk_clock in essence.
> 
> how about initializing cpu_clock() sooner, so that printk timestamps 
> start ticking as soon as possible?

which will make some archs quite unhappy iirc, see those arm and ia64
bugs I caused the other day.

Re: [PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> On Wed, 2008-08-27 at 09:42 +0200, Ingo Molnar wrote:
> > * Yinghai Lu <yhlu.kernel@gmail.com> wrote:
> > 
> > > +static unsigned long long tsc_clock(int cpu)
> > > +{
> > > +	unsigned long long t;
> > > +
> > > +	rdtscll(t);
> > > +
> > > +	return t;
> > > +}
> > 
> > hm, i'm not sure i like the whole direction - this reintroduces 
> > printk_clock in essence.
> > 
> > how about initializing cpu_clock() sooner, so that printk timestamps 
> > start ticking as soon as possible?
> 
> which will make some archs quite unhappy iirc, see those arm and ia64 
> bugs I caused the other day.

that's OK - that still allows arches to start their clocks whenever they 
want to. But also add the possibility for architectures to initialize 
things even sooner.

	Ingo

[PATCH] printk_time: prepare stub for using other than cpu_clock

[Yinghai Lu]

Signed-off-by: Yinghai Lu <yhlu.kernel@gmail.com>

---
 include/linux/kernel.h |    5 +++++
 init/main.c            |    1 +
 kernel/printk.c        |   14 +++++++++++++-
 3 files changed, 19 insertions(+), 1 deletion(-)

Index: linux-2.6/include/linux/kernel.h
===================================================================
--- linux-2.6.orig/include/linux/kernel.h
+++ linux-2.6/include/linux/kernel.h
@@ -184,7 +184,10 @@ extern int kernel_text_address(unsigned
 struct pid;
 extern struct pid *session_of_pgrp(struct pid *pgrp);
 
+typedef unsigned long long (*printk_time_clock_fn)(int cpu);
 #ifdef CONFIG_PRINTK
+extern void set_printk_time_clock(printk_time_clock_fn fn);
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
@@ -195,6 +198,8 @@ extern int printk_ratelimit(void);
 extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 				   unsigned int interval_msec);
 #else
+static inline void set_printk_time_clock(printk_time_clock_fn fn) { }
+
 static inline int vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 static inline int vprintk(const char *s, va_list args) { return 0; }
Index: linux-2.6/init/main.c
===================================================================
--- linux-2.6.orig/init/main.c
+++ linux-2.6/init/main.c
@@ -663,6 +663,7 @@ asmlinkage void __init start_kernel(void
 	if (late_time_init)
 		late_time_init();
 	calibrate_delay();
+	set_printk_time_clock(cpu_clock);
 	pidmap_init();
 	pgtable_cache_init();
 	prio_tree_init();
Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/kernel/printk.c
@@ -662,6 +662,18 @@ static int recursion_bug;
 	static int new_text_line = 1;
 static char printk_buf[1024];
 
+static unsigned long long default_printk_time_clock(int cpu)
+{
+	return 0;
+}
+
+static printk_time_clock_fn printk_time_clock = default_printk_time_clock;
+
+void set_printk_time_clock(printk_time_clock_fn fn)
+{
+	printk_time_clock = fn;
+}
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -737,7 +749,7 @@ asmlinkage int vprintk(const char *fmt,
 				unsigned long long t;
 				unsigned long nanosec_rem;
 
-				t = cpu_clock(printk_cpu);
+				t = printk_time_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
 				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
 						(unsigned long) t,

[PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Yinghai Lu]

so can get tsc value on printk

need to apply after
	[PATCH] printk_time: prepare stub for using other than cpu_clock

Signed-off-by: Yinghai Lu <yhlu.kernel@gmail.com>

---
 arch/x86/kernel/cpu/common.c    |   11 +++++++++++
 arch/x86/kernel/cpu/common_64.c |   12 ++++++++++++
 2 files changed, 23 insertions(+)

Index: linux-2.6/arch/x86/kernel/cpu/common.c
===================================================================
--- linux-2.6.orig/arch/x86/kernel/cpu/common.c
+++ linux-2.6/arch/x86/kernel/cpu/common.c
@@ -617,6 +617,15 @@ __setup("clearcpuid=", setup_disablecpui
 
 cpumask_t cpu_initialized __cpuinitdata = CPU_MASK_NONE;
 
+static unsigned long long tsc_clock(int cpu)
+{
+	unsigned long long t;
+
+	rdtscll(t);
+
+	return t;
+}
+
 void __init early_cpu_init(void)
 {
 	struct cpu_vendor_dev *cvdev;
@@ -627,6 +636,8 @@ void __init early_cpu_init(void)
 		cpu_devs[cvdev->vendor] = cvdev->cpu_dev;
 
 	early_cpu_detect();
+	if (cpu_has_tsc)
+		set_printk_time_clock(tsc_clock);
 	validate_pat_support(&boot_cpu_data);
 }
 
Index: linux-2.6/arch/x86/kernel/cpu/common_64.c
===================================================================
--- linux-2.6.orig/arch/x86/kernel/cpu/common_64.c
+++ linux-2.6/arch/x86/kernel/cpu/common_64.c
@@ -215,6 +215,15 @@ static void __init early_cpu_support_pri
 	}
 }
 
+static unsigned long long tsc_clock(int cpu)
+{
+	unsigned long long t;
+
+	rdtscll(t);
+
+	return t;
+}
+
 static void __cpuinit early_identify_cpu(struct cpuinfo_x86 *c);
 
 void __init early_cpu_init(void)
@@ -227,6 +236,9 @@ void __init early_cpu_init(void)
                 cpu_devs[cvdev->vendor] = cvdev->cpu_dev;
 	early_cpu_support_print();
 	early_identify_cpu(&boot_cpu_data);
+
+	if (cpu_has_tsc)
+		set_printk_time_clock(tsc_clock);
 }
 
 /* Do some early cpuid on the boot CPU to get some parameter that are

Re: [PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Peter Zijlstra]

On Tue, 2008-07-29 at 03:09 -0700, Yinghai Lu wrote:
> so can get tsc value on printk
> 
> need to apply after
> 	[PATCH] printk_time: prepare stub for using other than cpu_clock


You failed to mention why we want this... ;-)


> Signed-off-by: Yinghai Lu <yhlu.kernel@gmail.com>
> 
> ---
>  arch/x86/kernel/cpu/common.c    |   11 +++++++++++
>  arch/x86/kernel/cpu/common_64.c |   12 ++++++++++++
>  2 files changed, 23 insertions(+)
> 
> Index: linux-2.6/arch/x86/kernel/cpu/common.c
> ===================================================================
> --- linux-2.6.orig/arch/x86/kernel/cpu/common.c
> +++ linux-2.6/arch/x86/kernel/cpu/common.c
> @@ -617,6 +617,15 @@ __setup("clearcpuid=", setup_disablecpui
>  
>  cpumask_t cpu_initialized __cpuinitdata = CPU_MASK_NONE;
>  
> +static unsigned long long tsc_clock(int cpu)
> +{
> +	unsigned long long t;
> +
> +	rdtscll(t);
> +
> +	return t;
> +}
> +
>  void __init early_cpu_init(void)
>  {
>  	struct cpu_vendor_dev *cvdev;
> @@ -627,6 +636,8 @@ void __init early_cpu_init(void)
>  		cpu_devs[cvdev->vendor] = cvdev->cpu_dev;
>  
>  	early_cpu_detect();
> +	if (cpu_has_tsc)
> +		set_printk_time_clock(tsc_clock);
>  	validate_pat_support(&boot_cpu_data);
>  }
>  
> Index: linux-2.6/arch/x86/kernel/cpu/common_64.c
> ===================================================================
> --- linux-2.6.orig/arch/x86/kernel/cpu/common_64.c
> +++ linux-2.6/arch/x86/kernel/cpu/common_64.c
> @@ -215,6 +215,15 @@ static void __init early_cpu_support_pri
>  	}
>  }
>  
> +static unsigned long long tsc_clock(int cpu)
> +{
> +	unsigned long long t;
> +
> +	rdtscll(t);
> +
> +	return t;
> +}
> +
>  static void __cpuinit early_identify_cpu(struct cpuinfo_x86 *c);
>  
>  void __init early_cpu_init(void)
> @@ -227,6 +236,9 @@ void __init early_cpu_init(void)
>                  cpu_devs[cvdev->vendor] = cvdev->cpu_dev;
>  	early_cpu_support_print();
>  	early_identify_cpu(&boot_cpu_data);
> +
> +	if (cpu_has_tsc)
> +		set_printk_time_clock(tsc_clock);
>  }
>  
>  /* Do some early cpuid on the boot CPU to get some parameter that are
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

Re: [PATCH] x86: printk_time to use tsc before cpu_clock is ready

[Yinghai Lu]

On Tue, Jul 29, 2008 at 3:13 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Tue, 2008-07-29 at 03:09 -0700, Yinghai Lu wrote:
>> so can get tsc value on printk
>>
>> need to apply after
>>       [PATCH] printk_time: prepare stub for using other than cpu_clock
>
>
> You failed to mention why we want this... ;-)
>

"
otherwise will get
[    0.000000]....
.....
[    0.000000] TSC calibrated against PM_TIMER
[    0.000000] Detected 2493.378 MHz processor.
[    0.008000] spurious 8259A interrupt: IRQ7.
[    0.008000] Console: colour VGA+ 80x25
[    0.008000] console handover: boot [uart0] -> real [ttyS0]
[    0.008000] Checking aperture...
[    0.008000] No AGP bridge found
[    0.008000] Node 0: aperture @ dc000000 size 64 MB
[    0.008000] Node 1: aperture @ dc000000 size 64 MB
[    0.008000] Node 2: aperture @ dc000000 size 64 MB
[    0.008000] Node 3: aperture @ dc000000 size 64 MB
[    0.008000] Node 4: aperture @ dc000000 size 64 MB
[    0.008000] Node 5: aperture @ dc000000 size 64 MB
[    0.008000] Node 6: aperture @ dc000000 size 64 MB
[    0.008000] Node 7: aperture @ dc000000 size 64 MB
[    0.008000] Memory: 264718324k/269090816k available (7532k kernel
code, 3716316k reserved, 5099k data, 484k init)
[    0.008000] CPA: page pool initialized 1 of 1 pages preallocated
[    0.008000] SLUB: Genslabs=13, HWalign=64, Order=0-3, MinObjects=0,
CPUs=32, Nodes=8
[    0.008000] hpet clockevent registered
[    0.008000] Calibrating delay loop (skipped), value calculated
using timer frequency.. 4986.72 BogoMIPS (lpj=9973456)
[    0.060003] Dentry cache hash table entries: 33554432 (order: 16,
268435456 bytes)

with this patch could get tsc to replace those [0,000000] and
[0.0080000], so could debug possible delay on big system on early
stage.
"

YH