[PATCH] shrink printk timestamp field

[PATCH] shrink printk timestamp field

[Joe Korty]

Shrink the printk timestamp field.

Keep the printk timestamp from occupying more of the
scarce, 80-column console line space than it really needs.

We eliminate the excessive whitespace the field added to
the line, and reduce timestamp precision from six digits
(usecs) to three digits (msecs).  msecs seems adequate
for the purpose of tracking boot sequence timing issues.

Signed-off-by: Joe Korty <joe.korty@ccur.com>

Index: 2.6.27-rc4-git4/kernel/printk.c
===================================================================
--- 2.6.27-rc4-git4.orig/kernel/printk.c	2008-08-26 18:23:03.000000000 -0400
+++ 2.6.27-rc4-git4/kernel/printk.c	2008-08-26 18:23:49.000000000 -0400
@@ -739,9 +739,9 @@
 
 				t = cpu_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+				tlen = sprintf(tbuf, "[%3lu.%03lu] ",
 						(unsigned long) t,
-						nanosec_rem / 1000);
+						nanosec_rem / 1000000);
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);

Re: [PATCH] shrink printk timestamp field

[Ingo Molnar]

* Joe Korty <joe.korty@ccur.com> wrote:

> Shrink the printk timestamp field.
> 
> Keep the printk timestamp from occupying more of the
> scarce, 80-column console line space than it really needs.
> 
> We eliminate the excessive whitespace the field added to
> the line, and reduce timestamp precision from six digits
> (usecs) to three digits (msecs).  msecs seems adequate
> for the purpose of tracking boot sequence timing issues.
> 
> Signed-off-by: Joe Korty <joe.korty@ccur.com>

applied to tip/core/printk, thanks Joe.

	Ingo

Re: [PATCH] shrink printk timestamp field

[Andrew Morton]

On Wed, 27 Aug 2008 11:17:59 -0400
Joe Korty <joe.korty@ccur.com> wrote:

> Shrink the printk timestamp field.
> 
> Keep the printk timestamp from occupying more of the
> scarce, 80-column console line space than it really needs.
> 
> We eliminate the excessive whitespace the field added to
> the line, and reduce timestamp precision from six digits
> (usecs) to three digits (msecs).  msecs seems adequate
> for the purpose of tracking boot sequence timing issues.
> 
> Signed-off-by: Joe Korty <joe.korty@ccur.com>
> 
> Index: 2.6.27-rc4-git4/kernel/printk.c
> ===================================================================
> --- 2.6.27-rc4-git4.orig/kernel/printk.c	2008-08-26 18:23:03.000000000 -0400
> +++ 2.6.27-rc4-git4/kernel/printk.c	2008-08-26 18:23:49.000000000 -0400
> @@ -739,9 +739,9 @@
>  
>  				t = cpu_clock(printk_cpu);
>  				nanosec_rem = do_div(t, 1000000000);
> -				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
> +				tlen = sprintf(tbuf, "[%3lu.%03lu] ",
>  						(unsigned long) t,
> -						nanosec_rem / 1000);
> +						nanosec_rem / 1000000);
>  
>  				for (tp = tbuf; tp < tbuf + tlen; tp++)
>  					emit_log_char(*tp);

This is a significant loss in utility.

[   16.817285] md: Autodetecting RAID arrays.
[   16.817288] md: Scanned 0 and added 0 devices.
[   16.817290] md: autorun ...
[   16.817292] md: ... autorun DONE.

This not-terribly-fast machine can emit printks into the log buffer
within two microseconds.  That's a pretty useful ad-hoc timing
factility.

This patch will reduce the precision by a factor of five hundred.

Re: [PATCH] shrink printk timestamp field

[Joe Korty]

On Fri, Aug 29, 2008 at 07:35:40PM -0400, Andrew Morton wrote:
> On Wed, 27 Aug 2008 11:17:59 -0400 Joe Korty <joe.korty@ccur.com> wrote:
> 
> > Shrink the printk timestamp field.
> >
> > Keep the printk timestamp from occupying more of the
> > scarce, 80-column console line space than it really needs.
> >
> 
> This is a significant loss in utility.
> 
> [   16.817285] md: Autodetecting RAID arrays.
> [   16.817288] md: Scanned 0 and added 0 devices.
> [   16.817290] md: autorun ...
> [   16.817292] md: ... autorun DONE.
> 
> This not-terribly-fast machine can emit printks into the log buffer
> within two microseconds.  That's a pretty useful ad-hoc timing
> factility.
> 
> This patch will reduce the precision by a factor of five hundred.

I was looking at it from the point of view of finding out where the
boot process was too slow.  For that millisecs is enough.  I am not
sure where knowing printk output to the microsec would be useful for
solving anything.

Joe

Re: [PATCH] shrink printk timestamp field

[Andrew Morton]

On Sat, 30 Aug 2008 10:38:08 -0400 Joe Korty <joe.korty@ccur.com> wrote:

> On Fri, Aug 29, 2008 at 07:35:40PM -0400, Andrew Morton wrote:
> > On Wed, 27 Aug 2008 11:17:59 -0400 Joe Korty <joe.korty@ccur.com> wrote:
> > 
> > > Shrink the printk timestamp field.
> > >
> > > Keep the printk timestamp from occupying more of the
> > > scarce, 80-column console line space than it really needs.
> > >
> > 
> > This is a significant loss in utility.
> > 
> > [   16.817285] md: Autodetecting RAID arrays.
> > [   16.817288] md: Scanned 0 and added 0 devices.
> > [   16.817290] md: autorun ...
> > [   16.817292] md: ... autorun DONE.
> > 
> > This not-terribly-fast machine can emit printks into the log buffer
> > within two microseconds.  That's a pretty useful ad-hoc timing
> > factility.
> > 
> > This patch will reduce the precision by a factor of five hundred.
> 
> I was looking at it from the point of view of finding out where the
> boot process was too slow.  For that millisecs is enough.  I am not
> sure where knowing printk output to the microsec would be useful for
> solving anything.
> 

Of course it's useful.  If you're working on performance or latency in
a disk, network or USB driver, microsecond resolution is about right.

Re: [PATCH] shrink printk timestamp field

[Leon Woestenberg]

Hello,

On Sat, Aug 30, 2008 at 7:16 PM, Andrew Morton
<akpm@linux-foundation.org> wrote:
> On Sat, 30 Aug 2008 10:38:08 -0400 Joe Korty <joe.korty@ccur.com> wrote:
>> On Fri, Aug 29, 2008 at 07:35:40PM -0400, Andrew Morton wrote:
>> > On Wed, 27 Aug 2008 11:17:59 -0400 Joe Korty <joe.korty@ccur.com> wrote:
>> >
>> > > Shrink the printk timestamp field.
>>
>> I was looking at it from the point of view of finding out where the
>> boot process was too slow.  For that millisecs is enough.  I am not
>> sure where knowing printk output to the microsec would be useful for
>> solving anything.
>
> Of course it's useful.  If you're working on performance or latency in
> a disk, network or USB driver, microsecond resolution is about right.
>
I second this. If we have timestamps enables, let it be useful for all
current uses. The 3 digits extra are very cheap useful information in
that area (without resorting to more elaborate methods like the
recently merged latency tracer).

Rather than cut 3 digits off, maybe fix some of the too-wide prints
would solve the posters issue better.

Can we please have this patch non-committed or reverted?

Regards,
-- 
Leon

Re: [PATCH] shrink printk timestamp field

[Joe Korty]

On Sat, Aug 30, 2008 at 01:47:06PM -0400, Leon Woestenberg wrote:
> On Sat, Aug 30, 2008 at 7:16 PM, Andrew Morton <akpm@linux-foundation.org> wrote:
>> On Sat, 30 Aug 2008 10:38:08 -0400 Joe Korty <joe.korty@ccur.com> wrote:
>>> On Fri, Aug 29, 2008 at 07:35:40PM -0400, Andrew Morton wrote:
>>>> On Wed, 27 Aug 2008 11:17:59 -0400 Joe Korty <joe.korty@ccur.com> wrote:
>>>>
>>>>> Shrink the printk timestamp field.
>>>
>>> I was looking at it from the point of view of finding out where the
>>> boot process was too slow.  For that millisecs is enough.  I am not
>>> sure where knowing printk output to the microsec would be useful for
>>> solving anything.
>>
>> Of course it's useful.  If you're working on performance or latency in
>> a disk, network or USB driver, microsecond resolution is about right.
>>
> I second this. If we have timestamps enables, let it be useful for all
> current uses. The 3 digits extra are very cheap useful information in
> that area (without resorting to more elaborate methods like the
> recently merged latency tracer).
> 
> Rather than cut 3 digits off, maybe fix some of the too-wide prints
> would solve the posters issue better.
> 
> Can we please have this patch non-committed or reverted?

I have no objection...
Joe

Re: [PATCH] shrink printk timestamp field

[Benny Halevy]

On Aug. 30, 2008, 20:16 +0300, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Sat, 30 Aug 2008 10:38:08 -0400 Joe Korty <joe.korty@ccur.com> wrote:
> 
>> On Fri, Aug 29, 2008 at 07:35:40PM -0400, Andrew Morton wrote:
>>> On Wed, 27 Aug 2008 11:17:59 -0400 Joe Korty <joe.korty@ccur.com> wrote:
>>>
>>>> Shrink the printk timestamp field.
>>>>
>>>> Keep the printk timestamp from occupying more of the
>>>> scarce, 80-column console line space than it really needs.
>>>>
>>> This is a significant loss in utility.
>>>
>>> [   16.817285] md: Autodetecting RAID arrays.
>>> [   16.817288] md: Scanned 0 and added 0 devices.
>>> [   16.817290] md: autorun ...
>>> [   16.817292] md: ... autorun DONE.
>>>
>>> This not-terribly-fast machine can emit printks into the log buffer
>>> within two microseconds.  That's a pretty useful ad-hoc timing
>>> factility.
>>>
>>> This patch will reduce the precision by a factor of five hundred.
>> I was looking at it from the point of view of finding out where the
>> boot process was too slow.  For that millisecs is enough.  I am not
>> sure where knowing printk output to the microsec would be useful for
>> solving anything.
>>
> 
> Of course it's useful.  If you're working on performance or latency in
> a disk, network or USB driver, microsecond resolution is about right.

How about supporting a configurable format string either by .config
and/or in runtime, e.g. given by a command line parameter?

Benny

> 
> --
> 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] shrink printk timestamp field

[Ingo Molnar]

* Joe Korty <joe.korty@ccur.com> wrote:

> >> Of course it's useful.  If you're working on performance or latency 
> >> in a disk, network or USB driver, microsecond resolution is about 
> >> right.
> >
> > I second this. If we have timestamps enables, let it be useful for 
> > all current uses. The 3 digits extra are very cheap useful 
> > information in that area (without resorting to more elaborate 
> > methods like the recently merged latency tracer).
> > 
> > Rather than cut 3 digits off, maybe fix some of the too-wide prints 
> > would solve the posters issue better.
> > 
> > Can we please have this patch non-committed or reverted?
> 
> I have no objection...

ok, i've zapped it from tip/core/printk.

	Ingo