[PATCH] printk: Print cpuid along with the timestamp with CONFIG_PRINTK_TIME

[PATCH] printk: Print cpuid along with the timestamp with CONFIG_PRINTK_TIME

[Ravikiran G Thirumalai]

I found it useful to have the cpuid of the printing cpu along with the
timestamp -- especially while debugging hangs during bootups.

I don't know why this hasn't been implemened in the kernel yet, and
cannot think of a strong reason not to have it.  Yes, the cpuid prefix will
take 5 more characters per line,  but having  the cpuid info is worth it,
I think.

Thanks,
Kiran

---


Add cpuid information to printk if CONFIG_PRINTK_TIME is enabled.
This information is useful to debug hangs and bootup issues.

Signed-off-by: Ravikiran Thirumalai <kiran@scalex86.org>

Index: linux-git/kernel/printk.c
===================================================================
--- linux-git.orig/kernel/printk.c	2008-09-16 15:37:48.000000000 -0700
+++ linux-git/kernel/printk.c	2008-09-18 12:27:10.489662938 -0700
@@ -739,9 +739,10 @@ asmlinkage int vprintk(const char *fmt, 
 
 				t = cpu_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+				tlen = sprintf(tbuf, "[%5lu.%06lu:%d] ",
 						(unsigned long) t,
-						nanosec_rem / 1000);
+						nanosec_rem / 1000,
+						printk_cpu);
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);

Re: [PATCH] printk: Print cpuid along with the timestamp with CONFIG_PRINTK_TIME

[Andrew Morton]

On Thu, 18 Sep 2008 12:37:20 -0700
Ravikiran G Thirumalai <kiran@scalex86.org> wrote:

> I found it useful to have the cpuid of the printing cpu along with the
> timestamp -- especially while debugging hangs during bootups.
> 
> I don't know why this hasn't been implemened in the kernel yet, and
> cannot think of a strong reason not to have it.  Yes, the cpuid prefix will
> take 5 more characters per line,  but having  the cpuid info is worth it,
> I think.
> 
> Thanks,
> Kiran
> 
> ---
> 
> 
> Add cpuid information to printk if CONFIG_PRINTK_TIME is enabled.
> This information is useful to debug hangs and bootup issues.
> 
> Signed-off-by: Ravikiran Thirumalai <kiran@scalex86.org>
> 
> Index: linux-git/kernel/printk.c
> ===================================================================
> --- linux-git.orig/kernel/printk.c	2008-09-16 15:37:48.000000000 -0700
> +++ linux-git/kernel/printk.c	2008-09-18 12:27:10.489662938 -0700
> @@ -739,9 +739,10 @@ asmlinkage int vprintk(const char *fmt, 
>  
>  				t = cpu_clock(printk_cpu);
>  				nanosec_rem = do_div(t, 1000000000);
> -				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
> +				tlen = sprintf(tbuf, "[%5lu.%06lu:%d] ",
>  						(unsigned long) t,
> -						nanosec_rem / 1000);
> +						nanosec_rem / 1000,
> +						printk_cpu);
>  
>  				for (tp = tbuf; tp < tbuf + tlen; tp++)
>  					emit_log_char(*tp);

Yes, I guess it could be useful sometimes.  otoh anyone who is down at
that level of detail and is using printk to debug something can add
their own %d/smp_processor_id().

Your patch illogically ties the cpu-id-printing feature to the
printk.time feature.  I guess that's liveable with, but
Documentation/kernel-parameters.txt should be updated.

Anyone who was parsing that output might get a shock, but that's
liveable with too.  Probably their parser will continue to work anwyay.


I don't know whether the usefulness of this feature outweighs its
various costs.  Input is sought.

Re: [PATCH] printk: Print cpuid along with the timestamp with CONFIG_PRINTK_TIME

[Ravikiran G Thirumalai]

On Thu, Sep 18, 2008 at 12:51:23PM -0700, Andrew Morton wrote:
>On Thu, 18 Sep 2008 12:37:20 -0700
>Ravikiran G Thirumalai <kiran@scalex86.org> wrote:
>> 
>> Signed-off-by: Ravikiran Thirumalai <kiran@scalex86.org>
>> 
>> Index: linux-git/kernel/printk.c
>> ===================================================================
>> --- linux-git.orig/kernel/printk.c	2008-09-16 15:37:48.000000000 -0700
>> +++ linux-git/kernel/printk.c	2008-09-18 12:27:10.489662938 -0700
>> @@ -739,9 +739,10 @@ asmlinkage int vprintk(const char *fmt, 
>>  
>>  				t = cpu_clock(printk_cpu);
>>  				nanosec_rem = do_div(t, 1000000000);
>> -				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
>> +				tlen = sprintf(tbuf, "[%5lu.%06lu:%d] ",
>>  						(unsigned long) t,
>> -						nanosec_rem / 1000);
>> +						nanosec_rem / 1000,
>> +						printk_cpu);
>>  
>>  				for (tp = tbuf; tp < tbuf + tlen; tp++)
>>  					emit_log_char(*tp);
>
>
>Your patch illogically ties the cpu-id-printing feature to the
>printk.time feature.  I guess that's liveable with, but
>Documentation/kernel-parameters.txt should be updated.
>

Didn't realize Documentation/kernel-parameters.txt had reference and even a
runtime parameter to control this!  I always enabled CONFIG_PRINTK_TIME
to get timestamps. Here's an updated patch.

As for the cpuid with the timestamp, the timestamp that is being
is  the printed the cpu's time stamp.

---

Add cpuid information to printk if CONFIG_PRINTK_TIME is enabled.
This information is useful to debug hangs and boot issues.

Signed-off-by: Ravikiran Thirumalai <kiran@scalex86.org>

Index: linux-git/kernel/printk.c
===================================================================
--- linux-git.orig/kernel/printk.c	2008-09-16 15:37:48.000000000 -0700
+++ linux-git/kernel/printk.c	2008-09-18 12:27:10.489662938 -0700
@@ -739,9 +739,10 @@ asmlinkage int vprintk(const char *fmt, 
 
 				t = cpu_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+				tlen = sprintf(tbuf, "[%5lu.%06lu:%d] ",
 						(unsigned long) t,
-						nanosec_rem / 1000);
+						nanosec_rem / 1000,
+						printk_cpu);
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);
Index: linux-git/Documentation/kernel-parameters.txt
===================================================================
--- linux-git.orig/Documentation/kernel-parameters.txt	2008-09-16 11:30:13.000000000 -0700
+++ linux-git/Documentation/kernel-parameters.txt	2008-09-18 17:11:35.167079714 -0700
@@ -1687,7 +1687,10 @@ and is between 256 and 4096 characters. 
 			default: off.
 
 	printk.time=	Show timing data prefixed to each printk message line
-			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
+			Format: <bool>  (1/Y/y=enable, 0/N/n=disable).
+			Per-cpu timestamps are prefixed as
+			"[sssss.uuuuuu:cpuid]" on each and every line printed,
+			if this option is enabled.
 
 	profile=	[KNL] Enable kernel profiling via /proc/profile
 			Format: [schedule,]<number>

Re: [PATCH] printk: Print cpuid along with the timestamp with CONFIG_PRINTK_TIME

[Marcin Slusarz]

On Thu, Sep 18, 2008 at 05:35:09PM -0700, Ravikiran G Thirumalai wrote:
> On Thu, Sep 18, 2008 at 12:51:23PM -0700, Andrew Morton wrote:
> >On Thu, 18 Sep 2008 12:37:20 -0700
> >Ravikiran G Thirumalai <kiran@scalex86.org> wrote:
> >> 
> >> Signed-off-by: Ravikiran Thirumalai <kiran@scalex86.org>
> >> 
> >> Index: linux-git/kernel/printk.c
> >> ===================================================================
> >> --- linux-git.orig/kernel/printk.c	2008-09-16 15:37:48.000000000 -0700
> >> +++ linux-git/kernel/printk.c	2008-09-18 12:27:10.489662938 -0700
> >> @@ -739,9 +739,10 @@ asmlinkage int vprintk(const char *fmt, 
> >>  
> >>  				t = cpu_clock(printk_cpu);
> >>  				nanosec_rem = do_div(t, 1000000000);
> >> -				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
> >> +				tlen = sprintf(tbuf, "[%5lu.%06lu:%d] ",
> >>  						(unsigned long) t,
> >> -						nanosec_rem / 1000);
> >> +						nanosec_rem / 1000,
> >> +						printk_cpu);
> >>  
> >>  				for (tp = tbuf; tp < tbuf + tlen; tp++)
> >>  					emit_log_char(*tp);
> >
> >
> >Your patch illogically ties the cpu-id-printing feature to the
> >printk.time feature.  I guess that's liveable with, but
> >Documentation/kernel-parameters.txt should be updated.
> >
> 
> Didn't realize Documentation/kernel-parameters.txt had reference and even a
> runtime parameter to control this!  I always enabled CONFIG_PRINTK_TIME
> to get timestamps. Here's an updated patch.
> 
> As for the cpuid with the timestamp, the timestamp that is being
> is  the printed the cpu's time stamp.

Do we really need this information on UP kernels?
Why don't you add another option for this feature?

Marcin

Re: [PATCH] printk: Print cpuid along with the timestamp with CONFIG_PRINTK_TIME

[Ravikiran G Thirumalai]

On Fri, Sep 19, 2008 at 07:15:21PM +0200, Marcin Slusarz wrote:
>
>Do we really need this information on UP kernels?

I thought about it, and left it as the way it is to have a consistent format
between UP and SMP.  With most of the modern cpus being multicore, or headed
that way, and since the entire timestamp prefix  can be controlled by a boot
option, is it worth having different formats for UP and SMP?  Most distros
ship SMP kernels anyways.