[PATCH 2/2] allow printk delay after multi lines

[PATCH 2/2] allow printk delay after multi lines

[Dave Young]

printk delay help us to capture printk messages on some unconvenient senarios,
but it is still not easy to read.

Add another sysctl variable printk_delay_per_lines to make it more readable.
We can set the lines according to screen height, then take pictures by camera.

kmesg will delay printk_delay_per_lines * printk_delay_msecs milliseconds
after every printk_delay_per_lines lines when printk_delay is enabled.

Setting the lines by proc/sysctl interface:
/proc/sys/kernel/printk_delay_per_lines

Andrew, sorry, I have not find time to cleanup the kernel.h sysctl variables.
If I'm free I will try to do it.

The value range from 1 - 100, default value is 1

Signed-off-by: Dave Young <hidave.darkstar@gmail.com>
---

 Documentation/sysctl/kernel.txt |    9 +++++++++
 include/linux/kernel.h          |    1 +
 kernel/printk.c                 |   12 +++++++++++-
 kernel/sysctl.c                 |    9 +++++++++
 4 files changed, 30 insertions(+), 1 deletions(-)

--- linux-2.6.orig/Documentation/sysctl/kernel.txt	2010-02-02 13:38:09.517495705 +0800
+++ linux-2.6/Documentation/sysctl/kernel.txt	2010-02-02 13:40:47.657480122 +0800
@@ -374,6 +374,15 @@ Value from 0 - 10000 is allowed.
 
 ==============================================================
 
+printk_delay_per_lines:
+
+Delay printk message every printk_delay_per_lines lines
+in printk_delay * printk_delay_per_lines milliseconds
+
+Value from 1 - 100 is allowed.
+
+==============================================================
+
 randomize-va-space:
 
 This option can be used to select the type of process address
--- linux-2.6.orig/include/linux/kernel.h	2010-02-02 13:38:09.537495564 +0800
+++ linux-2.6/include/linux/kernel.h	2010-02-02 13:40:47.657480122 +0800
@@ -246,6 +246,7 @@ extern bool printk_timed_ratelimit(unsig
 				   unsigned int interval_msec);
 
 extern int printk_delay_msec;
+extern int printk_delay_per_lines;
 
 /*
  * Print a one-time message (analogous to WARN_ONCE() et al):
--- linux-2.6.orig/kernel/printk.c	2010-02-02 13:39:19.446657319 +0800
+++ linux-2.6/kernel/printk.c	2010-02-02 13:40:47.660813615 +0800
@@ -656,16 +656,26 @@ static int new_text_line = 1;
 static char printk_buf[1024];
 
 int printk_delay_msec __read_mostly;
+int printk_delay_per_lines __read_mostly;
 
 static inline void printk_delay(void)
 {
 	if (unlikely(printk_delay_msec)) {
-		int m = printk_delay_msec;
+		static int m, l;
 
+		if (!l)
+			l = printk_delay_per_lines;
+
+		if (--l) {
+			m += printk_delay_msec;
+			return;
+		}
+		m += printk_delay_msec;
 		while (m--) {
 			mdelay(1);
 			touch_nmi_watchdog();
 		}
+		m = 0;
 	}
 }
 
--- linux-2.6.orig/kernel/sysctl.c	2010-02-02 13:38:09.507495705 +0800
+++ linux-2.6/kernel/sysctl.c	2010-02-02 13:40:47.660813615 +0800
@@ -684,6 +684,15 @@ static struct ctl_table kern_table[] = {
 		.extra1		= &zero,
 		.extra2		= &ten_thousand,
 	},
+	{
+		.procname	= "printk_delay_per_lines",
+		.data		= &printk_delay_per_lines,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec_minmax,
+		.extra1		= &one,
+		.extra2		= &one_hundred,
+	},
 #endif
 	{
 		.procname	= "ngroups_max",

Re: [PATCH 2/2] allow printk delay after multi lines

[Andrew Morton]

On Sat, 6 Feb 2010 21:40:56 +0800
Dave Young <hidave.darkstar@gmail.com> wrote:

> printk delay help us to capture printk messages on some unconvenient senarios,
> but it is still not easy to read.
> 
> Add another sysctl variable printk_delay_per_lines to make it more readable.
> We can set the lines according to screen height, then take pictures by camera.
> 
> kmesg will delay printk_delay_per_lines * printk_delay_msecs milliseconds
> after every printk_delay_per_lines lines when printk_delay is enabled.
> 
> Setting the lines by proc/sysctl interface:
> /proc/sys/kernel/printk_delay_per_lines
> 
> Andrew, sorry, I have not find time to cleanup the kernel.h sysctl variables.
> If I'm free I will try to do it.
> 
> The value range from 1 - 100, default value is 1
> 
> ...
>
> --- linux-2.6.orig/include/linux/kernel.h	2010-02-02 13:38:09.537495564 +0800
> +++ linux-2.6/include/linux/kernel.h	2010-02-02 13:40:47.657480122 +0800
> @@ -246,6 +246,7 @@ extern bool printk_timed_ratelimit(unsig
>  				   unsigned int interval_msec);
>  
>  extern int printk_delay_msec;
> +extern int printk_delay_per_lines;
>  
>  /*
>   * Print a one-time message (analogous to WARN_ONCE() et al):
> --- linux-2.6.orig/kernel/printk.c	2010-02-02 13:39:19.446657319 +0800
> +++ linux-2.6/kernel/printk.c	2010-02-02 13:40:47.660813615 +0800
> @@ -656,16 +656,26 @@ static int new_text_line = 1;
>  static char printk_buf[1024];
>  
>  int printk_delay_msec __read_mostly;
> +int printk_delay_per_lines __read_mostly;
>  
>  static inline void printk_delay(void)
>  {
>  	if (unlikely(printk_delay_msec)) {
> -		int m = printk_delay_msec;
> +		static int m, l;
>  
> +		if (!l)
> +			l = printk_delay_per_lines;
> +
> +		if (--l) {
> +			m += printk_delay_msec;
> +			return;
> +		}
> +		m += printk_delay_msec;
>  		while (m--) {
>  			mdelay(1);
>  			touch_nmi_watchdog();
>  		}
> +		m = 0;
>  	}
>  }

- The default value is zero, not 1.  And zero will be treated as 4G. 
  That's a bug.

- This feature would be a lot more useful if the user could specify
  printk_delay_per_lines on the boot command line.  Ditto
  printk_delay_msec.  So you can stop the important mesages from
  scrolling off.  (I think there's already a way to do that, but I'm
  too lazy to go remember what it was).

- The permitted range of 1-100 for printk_delay_per_lines seems
  arbitrary and unneeded.  Why shouldn't I be able to set it to 10,000?
  I see no harm in permitting that.

- If the user sets printk_delay_per_lines=N, the kernel will pause
  for N*printk_delay_msec every N lines.  This is odd, and unintuitive.
  And it'll really hurt if I set printk_delay_per_lines=10000!

  I'd expect the kernel to pause for printk_delay_msec every N lines,
  and I think that would be better.

Re: [PATCH 2/2] allow printk delay after multi lines

[Andrew Morton]

On Mon, 8 Feb 2010 13:56:54 -0800
Andrew Morton <akpm@linux-foundation.org> wrote:

> On Sat, 6 Feb 2010 21:40:56 +0800
> Dave Young <hidave.darkstar@gmail.com> wrote:
> 
> > printk delay help us to capture printk messages on some unconvenient senarios,
> > but it is still not easy to read.
> > 
> > Add another sysctl variable printk_delay_per_lines to make it more readable.
> > We can set the lines according to screen height, then take pictures by camera.
> > 
> > kmesg will delay printk_delay_per_lines * printk_delay_msecs milliseconds
> > after every printk_delay_per_lines lines when printk_delay is enabled.
> > 
> > Setting the lines by proc/sysctl interface:
> > /proc/sys/kernel/printk_delay_per_lines
> > 
> > Andrew, sorry, I have not find time to cleanup the kernel.h sysctl variables.
> > If I'm free I will try to do it.
> > 
> > The value range from 1 - 100, default value is 1
> > 
> > ...
> >
> > --- linux-2.6.orig/include/linux/kernel.h	2010-02-02 13:38:09.537495564 +0800
> > +++ linux-2.6/include/linux/kernel.h	2010-02-02 13:40:47.657480122 +0800
> > @@ -246,6 +246,7 @@ extern bool printk_timed_ratelimit(unsig
> >  				   unsigned int interval_msec);
> >  
> >  extern int printk_delay_msec;
> > +extern int printk_delay_per_lines;
> >  
> >  /*
> >   * Print a one-time message (analogous to WARN_ONCE() et al):
> > --- linux-2.6.orig/kernel/printk.c	2010-02-02 13:39:19.446657319 +0800
> > +++ linux-2.6/kernel/printk.c	2010-02-02 13:40:47.660813615 +0800
> > @@ -656,16 +656,26 @@ static int new_text_line = 1;
> >  static char printk_buf[1024];
> >  
> >  int printk_delay_msec __read_mostly;
> > +int printk_delay_per_lines __read_mostly;
> >  
> >  static inline void printk_delay(void)
> >  {
> >  	if (unlikely(printk_delay_msec)) {
> > -		int m = printk_delay_msec;
> > +		static int m, l;
> >  
> > +		if (!l)
> > +			l = printk_delay_per_lines;
> > +
> > +		if (--l) {
> > +			m += printk_delay_msec;
> > +			return;
> > +		}
> > +		m += printk_delay_msec;
> >  		while (m--) {
> >  			mdelay(1);
> >  			touch_nmi_watchdog();
> >  		}
> > +		m = 0;
> >  	}
> >  }
> 

Also...

- The above code is racy: if multiple CPUs run printk_delay()
  concurrently, `m' and `l' will get mucked up.

  We should verify that the effects of this race are benign.  This
  will be hard.

  Or we fix the race.  One could add locking (irq-safe locking), but
  I suspect a better approach would be to use atomic ops.

Re: [PATCH 2/2] allow printk delay after multi lines

[Dave Young]

On Tue, Feb 9, 2010 at 6:01 AM, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Mon, 8 Feb 2010 13:56:54 -0800
> Andrew Morton <akpm@linux-foundation.org> wrote:
>
>> On Sat, 6 Feb 2010 21:40:56 +0800
>> Dave Young <hidave.darkstar@gmail.com> wrote:
>>
>> > printk delay help us to capture printk messages on some unconvenient senarios,
>> > but it is still not easy to read.
>> >
>> > Add another sysctl variable printk_delay_per_lines to make it more readable.
>> > We can set the lines according to screen height, then take pictures by camera.
>> >
>> > kmesg will delay printk_delay_per_lines * printk_delay_msecs milliseconds
>> > after every printk_delay_per_lines lines when printk_delay is enabled.
>> >
>> > Setting the lines by proc/sysctl interface:
>> > /proc/sys/kernel/printk_delay_per_lines
>> >
>> > Andrew, sorry, I have not find time to cleanup the kernel.h sysctl variables.
>> > If I'm free I will try to do it.
>> >
>> > The value range from 1 - 100, default value is 1
>> >
>> > ...
>> >
>> > --- linux-2.6.orig/include/linux/kernel.h   2010-02-02 13:38:09.537495564 +0800
>> > +++ linux-2.6/include/linux/kernel.h        2010-02-02 13:40:47.657480122 +0800
>> > @@ -246,6 +246,7 @@ extern bool printk_timed_ratelimit(unsig
>> >                                unsigned int interval_msec);
>> >
>> >  extern int printk_delay_msec;
>> > +extern int printk_delay_per_lines;
>> >
>> >  /*
>> >   * Print a one-time message (analogous to WARN_ONCE() et al):
>> > --- linux-2.6.orig/kernel/printk.c  2010-02-02 13:39:19.446657319 +0800
>> > +++ linux-2.6/kernel/printk.c       2010-02-02 13:40:47.660813615 +0800
>> > @@ -656,16 +656,26 @@ static int new_text_line = 1;
>> >  static char printk_buf[1024];
>> >
>> >  int printk_delay_msec __read_mostly;
>> > +int printk_delay_per_lines __read_mostly;
>> >
>> >  static inline void printk_delay(void)
>> >  {
>> >     if (unlikely(printk_delay_msec)) {
>> > -           int m = printk_delay_msec;
>> > +           static int m, l;
>> >
>> > +           if (!l)
>> > +                   l = printk_delay_per_lines;
>> > +
>> > +           if (--l) {
>> > +                   m += printk_delay_msec;
>> > +                   return;
>> > +           }
>> > +           m += printk_delay_msec;
>> >             while (m--) {
>> >                     mdelay(1);
>> >                     touch_nmi_watchdog();
>> >             }
>> > +           m = 0;
>> >     }
>> >  }
>>
>
> Also...
>
> - The above code is racy: if multiple CPUs run printk_delay()
>  concurrently, `m' and `l' will get mucked up.
>
>  We should verify that the effects of this race are benign.  This
>  will be hard.
>
>  Or we fix the race.  One could add locking (irq-safe locking), but
>  I suspect a better approach would be to use atomic ops.
>

will change to  use atomic ops

-- 
Regards
dave

Re: [PATCH 2/2] allow printk delay after multi lines

[Dave Young]

On Tue, Feb 9, 2010 at 5:56 AM, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Sat, 6 Feb 2010 21:40:56 +0800
> Dave Young <hidave.darkstar@gmail.com> wrote:
>
>> printk delay help us to capture printk messages on some unconvenient senarios,
>> but it is still not easy to read.
>>
>> Add another sysctl variable printk_delay_per_lines to make it more readable.
>> We can set the lines according to screen height, then take pictures by camera.
>>
>> kmesg will delay printk_delay_per_lines * printk_delay_msecs milliseconds
>> after every printk_delay_per_lines lines when printk_delay is enabled.
>>
>> Setting the lines by proc/sysctl interface:
>> /proc/sys/kernel/printk_delay_per_lines
>>
>> Andrew, sorry, I have not find time to cleanup the kernel.h sysctl variables.
>> If I'm free I will try to do it.
>>
>> The value range from 1 - 100, default value is 1
>>
>> ...
>>
>> --- linux-2.6.orig/include/linux/kernel.h     2010-02-02 13:38:09.537495564 +0800
>> +++ linux-2.6/include/linux/kernel.h  2010-02-02 13:40:47.657480122 +0800
>> @@ -246,6 +246,7 @@ extern bool printk_timed_ratelimit(unsig
>>                                  unsigned int interval_msec);
>>
>>  extern int printk_delay_msec;
>> +extern int printk_delay_per_lines;
>>
>>  /*
>>   * Print a one-time message (analogous to WARN_ONCE() et al):
>> --- linux-2.6.orig/kernel/printk.c    2010-02-02 13:39:19.446657319 +0800
>> +++ linux-2.6/kernel/printk.c 2010-02-02 13:40:47.660813615 +0800
>> @@ -656,16 +656,26 @@ static int new_text_line = 1;
>>  static char printk_buf[1024];
>>
>>  int printk_delay_msec __read_mostly;
>> +int printk_delay_per_lines __read_mostly;
>>
>>  static inline void printk_delay(void)
>>  {
>>       if (unlikely(printk_delay_msec)) {
>> -             int m = printk_delay_msec;
>> +             static int m, l;
>>
>> +             if (!l)
>> +                     l = printk_delay_per_lines;
>> +
>> +             if (--l) {
>> +                     m += printk_delay_msec;
>> +                     return;
>> +             }
>> +             m += printk_delay_msec;
>>               while (m--) {
>>                       mdelay(1);
>>                       touch_nmi_watchdog();
>>               }
>> +             m = 0;
>>       }
>>  }
>
> - The default value is zero, not 1.  And zero will be treated as 4G.
>  That's a bug.

Will fix.

>
> - This feature would be a lot more useful if the user could specify
>  printk_delay_per_lines on the boot command line.  Ditto
>  printk_delay_msec.  So you can stop the important mesages from
>  scrolling off.  (I think there's already a way to do that, but I'm
>  too lazy to go remember what it was).

I think it's the similar "boot_delay". It's a little different as
calibration is not done on the early booting phase, so busy loop
is used instead to delay. It's hard to make boot delay accurate.

Maybe delay_per_lines can be done while booting as well,
but it should be another patch,  isn't it?

>
> - The permitted range of 1-100 for printk_delay_per_lines seems
>  arbitrary and unneeded.  Why shouldn't I be able to set it to 10,000?
>  I see no harm in permitting that.
>
> - If the user sets printk_delay_per_lines=N, the kernel will pause
>  for N*printk_delay_msec every N lines.  This is odd, and unintuitive.
>  And it'll really hurt if I set printk_delay_per_lines=10000!
>
>  I'd expect the kernel to pause for printk_delay_msec every N lines,
>  and I think that would be better.

Fine to me as well. Thanks for your comments.

-- 
Regards
dave

Re: [PATCH 2/2] allow printk delay after multi lines

[Dave Young]

On Tue, Feb 9, 2010 at 10:31 AM, Dave Young <hidave.darkstar@gmail.com> wrote:
> On Tue, Feb 9, 2010 at 5:56 AM, Andrew Morton <akpm@linux-foundation.org> wrote:
>> On Sat, 6 Feb 2010 21:40:56 +0800
>> Dave Young <hidave.darkstar@gmail.com> wrote:
>>
>>> printk delay help us to capture printk messages on some unconvenient senarios,
>>> but it is still not easy to read.
>>>
>>> Add another sysctl variable printk_delay_per_lines to make it more readable.
>>> We can set the lines according to screen height, then take pictures by camera.
>>>
>>> kmesg will delay printk_delay_per_lines * printk_delay_msecs milliseconds
>>> after every printk_delay_per_lines lines when printk_delay is enabled.
>>>
>>> Setting the lines by proc/sysctl interface:
>>> /proc/sys/kernel/printk_delay_per_lines
>>>
>>> Andrew, sorry, I have not find time to cleanup the kernel.h sysctl variables.
>>> If I'm free I will try to do it.
>>>
>>> The value range from 1 - 100, default value is 1
>>>
>>> ...
>>>
>>> --- linux-2.6.orig/include/linux/kernel.h     2010-02-02 13:38:09.537495564 +0800
>>> +++ linux-2.6/include/linux/kernel.h  2010-02-02 13:40:47.657480122 +0800
>>> @@ -246,6 +246,7 @@ extern bool printk_timed_ratelimit(unsig
>>>                                  unsigned int interval_msec);
>>>
>>>  extern int printk_delay_msec;
>>> +extern int printk_delay_per_lines;
>>>
>>>  /*
>>>   * Print a one-time message (analogous to WARN_ONCE() et al):
>>> --- linux-2.6.orig/kernel/printk.c    2010-02-02 13:39:19.446657319 +0800
>>> +++ linux-2.6/kernel/printk.c 2010-02-02 13:40:47.660813615 +0800
>>> @@ -656,16 +656,26 @@ static int new_text_line = 1;
>>>  static char printk_buf[1024];
>>>
>>>  int printk_delay_msec __read_mostly;
>>> +int printk_delay_per_lines __read_mostly;
>>>
>>>  static inline void printk_delay(void)
>>>  {
>>>       if (unlikely(printk_delay_msec)) {
>>> -             int m = printk_delay_msec;
>>> +             static int m, l;
>>>
>>> +             if (!l)
>>> +                     l = printk_delay_per_lines;
>>> +
>>> +             if (--l) {
>>> +                     m += printk_delay_msec;
>>> +                     return;
>>> +             }
>>> +             m += printk_delay_msec;
>>>               while (m--) {
>>>                       mdelay(1);
>>>                       touch_nmi_watchdog();
>>>               }
>>> +             m = 0;
>>>       }
>>>  }
>>
>> - The default value is zero, not 1.  And zero will be treated as 4G.
>>  That's a bug.
>
> Will fix.
>
>>
>> - This feature would be a lot more useful if the user could specify
>>  printk_delay_per_lines on the boot command line.  Ditto
>>  printk_delay_msec.  So you can stop the important mesages from
>>  scrolling off.  (I think there's already a way to do that, but I'm
>>  too lazy to go remember what it was).
>
> I think it's the similar "boot_delay". It's a little different as
> calibration is not done on the early booting phase, so busy loop
> is used instead to delay. It's hard to make boot delay accurate.
>
> Maybe delay_per_lines can be done while booting as well,
> but it should be another patch,  isn't it?

Or merge the two in one function, so we can set the boot param,
ie. call boot_delay in boot phase, mdelay otherwise.

>
>>
>> - The permitted range of 1-100 for printk_delay_per_lines seems
>>  arbitrary and unneeded.  Why shouldn't I be able to set it to 10,000?
>>  I see no harm in permitting that.
>>
>> - If the user sets printk_delay_per_lines=N, the kernel will pause
>>  for N*printk_delay_msec every N lines.  This is odd, and unintuitive.
>>  And it'll really hurt if I set printk_delay_per_lines=10000!
>>
>>  I'd expect the kernel to pause for printk_delay_msec every N lines,
>>  and I think that would be better.
>
> Fine to me as well. Thanks for your comments.
>

BTW, for the sysctl variables. I found in kernel.h there's:
printk/console_loglevel/panic related extern variables for sysctl.

console_loglevel and panic related variables are used here and there,
not just for sysctl, so I think it should stay in kernel.h.

The printk related variables for sysctl and all the extern variables in
sysctl.c can be move to sysctl.h. Seems no need new head file.

Andrew, what's your opinion?

> --
> Regards
> dave
>



-- 
Regards
dave

Re: [PATCH 2/2] allow printk delay after multi lines

[Andrew Morton]

On Tue, 9 Feb 2010 13:56:34 +0800 Dave Young <hidave.darkstar@gmail.com> wrote:

> BTW, for the sysctl variables. I found in kernel.h there's:
> printk/console_loglevel/panic related extern variables for sysctl.
> 
> console_loglevel and panic related variables are used here and there,
> not just for sysctl, so I think it should stay in kernel.h.
> 
> The printk related variables for sysctl and all the extern variables in
> sysctl.c can be move to sysctl.h. Seems no need new head file.
> 
> Andrew, what's your opinion?

Symbols which are defined in printk.c and which are used in other
compilation units should be declared in printk.h!

We mucked up in the past by putting these things in kernel.h and as
externs in sysctl.c, but that's no reason to continue to do so.  As a
special-case, it makes convenience sense to declare printk() itself and
the loglevel strings etc in kernel.h, but that _is_ a special case.

Re: [PATCH 2/2] allow printk delay after multi lines

[Dave Young]

On Tue, Feb 9, 2010 at 2:07 PM, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Tue, 9 Feb 2010 13:56:34 +0800 Dave Young <hidave.darkstar@gmail.com> wrote:
>
>> BTW, for the sysctl variables. I found in kernel.h there's:
>> printk/console_loglevel/panic related extern variables for sysctl.
>>
>> console_loglevel and panic related variables are used here and there,
>> not just for sysctl, so I think it should stay in kernel.h.
>>
>> The printk related variables for sysctl and all the extern variables in
>> sysctl.c can be move to sysctl.h. Seems no need new head file.
>>
>> Andrew, what's your opinion?
>
> Symbols which are defined in printk.c and which are used in other
> compilation units should be declared in printk.h!
>
> We mucked up in the past by putting these things in kernel.h and as
> externs in sysctl.c, but that's no reason to continue to do so.  As a
> special-case, it makes convenience sense to declare printk() itself and
> the loglevel strings etc in kernel.h, but that _is_ a special case.
>

Lazy is bad, hehe :)
Will do that in a updated patchset, Thanks.

-- 
Regards
dave