Re: [PATCH 7/7] printk: provide a filtering macro for printk

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Tim Bird]

Marc Andre Tanner wrote:
> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>> Some places in the kernel break the message into pieces, like so:
>>>
>>> printk(KERN_ERR, "Error: first part ");
>>> ...
>>> printk(" more info for error.\n");
>> Technically, shouldn't the second part of the message actually be:
>>
>> printk(KERN_CONT " more info for error.\n");
>>
>> Maybe some mechanism could be created to handle the continued message
>> if they have the KERN_CONT?
> 
> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
> to change that.
> 
>>> These parts would not be handled consistently under certain
>>> conditions.
>>>
>>> It would be confusing to see only part of the message,
>>> but I don't know how often this construct is used.  
> 
> $ grep -R KERN_CONT linux-2.6 | wc -l
> 373
> 
>>> Maybe
>>> another mechanism is needed to ensure that continuation
>>> printk lines have the same log level as their start strings.
> 
> I currently don't see a way to achieve this with the CPP.

If it's that few, then maybe it's OK to actually change
the code for those printk statements. (Heck, these locations
were all changed in the last 2 years anyway.)

I'm just brainstorming here, but how about changing them from:
  printk(KERN_INFO "foo");
  printk(KERN_CONT "bar\n");
to:
  printk(KERN_INFO "foo");
  printk_cont(KERN_INFO "bar\n");

This way the continuation line has the log level, and can
be conditionally compiled based on the VERBOSITY level.  A little
magic would be needed to strip the first 3 chars of the fmt
string in printk_cont().

I think this makes the printk messages a bit more consistent anyway,
and still marks lines that are continuation lines.

>>> But, overall, very slick!  It's nice to see a solution that doesn't
>>> require changing all printks statements in the kernel.
> 
> Yes that's what I thought too. Thanks to the comments so far the next 
> version of the patch will contain even less changes to the rest of the 
> kernel.
>  
>> I haven't looked over this patch series yet but does it work with the
>> pr_<level> macros (pr_info, pr_err, etc.)?
> 
> It should work, yes.

 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Tim Bird]

Tim Bird wrote:
> Marc Andre Tanner wrote:
>> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>>> Some places in the kernel break the message into pieces, like so:
>>>>
>>>> printk(KERN_ERR, "Error: first part ");
>>>> ...
>>>> printk(" more info for error.\n");
>>> Technically, shouldn't the second part of the message actually be:
>>>
>>> printk(KERN_CONT " more info for error.\n");
>>>
>>> Maybe some mechanism could be created to handle the continued message
>>> if they have the KERN_CONT?
>> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
>> to change that.
>>
>>>> These parts would not be handled consistently under certain
>>>> conditions.
>>>>
>>>> It would be confusing to see only part of the message,
>>>> but I don't know how often this construct is used.  
>> $ grep -R KERN_CONT linux-2.6 | wc -l
>> 373
>>
>>>> Maybe
>>>> another mechanism is needed to ensure that continuation
>>>> printk lines have the same log level as their start strings.
>> I currently don't see a way to achieve this with the CPP.
> 
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 
> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().
> 
> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.

Just another note.  Detecting continuation lines also complicates
the printk timestamping code.  If all continuation lines were
distinguishable by the printk code, then it might be possible
to simplify the timestamping code as a side effect of the
change.
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Corporation of America
=============================

RE: [PATCH 7/7] printk: provide a filtering macro for printk

[H Hartley Sweeten]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 2664 bytes --]

On Wednesday, September 02, 2009 10:05 AM, Tim Bird wrote:
> Marc Andre Tanner wrote:
>> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
>>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
>>>> Some places in the kernel break the message into pieces, like so:
>>>>
>>>> printk(KERN_ERR, "Error: first part ");
>>>> ...
>>>> printk(" more info for error.\n");
>>> Technically, shouldn't the second part of the message actually be:
>>>
>>> printk(KERN_CONT " more info for error.\n");
>>>
>>> Maybe some mechanism could be created to handle the continued message
>>> if they have the KERN_CONT?
>> 
>> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
>> to change that.
>> 
>>>> These parts would not be handled consistently under certain
>>>> conditions.
>>>>
>>>> It would be confusing to see only part of the message,
>>>> but I don't know how often this construct is used.  
>> 
>> $ grep -R KERN_CONT linux-2.6 | wc -l
>> 373
>> 
>>>> Maybe
>>>> another mechanism is needed to ensure that continuation
>>>> printk lines have the same log level as their start strings.
>> 
>> I currently don't see a way to achieve this with the CPP.
>
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 

Unfortunately not all the continued printk statements in the kernel are
properly tagged with KERN_CONT (or pr_cont, etc.).

> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().
> 
> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.
> 
>>>> But, overall, very slick!  It's nice to see a solution that doesn't
>>>> require changing all printks statements in the kernel.
>> 
>> Yes that's what I thought too. Thanks to the comments so far the next 
>> version of the patch will contain even less changes to the rest of the 
>> kernel.
>>  
>>> I haven't looked over this patch series yet but does it work with the
>>> pr_<level> macros (pr_info, pr_err, etc.)?
>> 
>> It should work, yes.

Regards,
Hartley
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Marc Andre Tanner]

On Wed, Sep 02, 2009 at 02:22:52PM -0400, H Hartley Sweeten wrote:
> On Wednesday, September 02, 2009 10:05 AM, Tim Bird wrote:
> > Marc Andre Tanner wrote:
> >> On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
> >>> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
> >>>> Some places in the kernel break the message into pieces, like so:
> >>>>
> >>>> printk(KERN_ERR, "Error: first part ");
> >>>> ...
> >>>> printk(" more info for error.\n");
> >>> Technically, shouldn't the second part of the message actually be:
> >>>
> >>> printk(KERN_CONT " more info for error.\n");
> >>>
> >>> Maybe some mechanism could be created to handle the continued message
> >>> if they have the KERN_CONT?
> >> 
> >> Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
> >> to change that.
> >> 
> >>>> These parts would not be handled consistently under certain
> >>>> conditions.
> >>>>
> >>>> It would be confusing to see only part of the message,
> >>>> but I don't know how often this construct is used.  
> >> 
> >> $ grep -R KERN_CONT linux-2.6 | wc -l
> >> 373
> >> 
> >>>> Maybe
> >>>> another mechanism is needed to ensure that continuation
> >>>> printk lines have the same log level as their start strings.
> >> 
> >> I currently don't see a way to achieve this with the CPP.
> >
> > If it's that few, then maybe it's OK to actually change
> > the code for those printk statements. (Heck, these locations
> > were all changed in the last 2 years anyway.)
> > 
> > I'm just brainstorming here, but how about changing them from:
> >   printk(KERN_INFO "foo");
> >   printk(KERN_CONT "bar\n");
> > to:
> >   printk(KERN_INFO "foo");
> >   printk_cont(KERN_INFO "bar\n");
> 
> Unfortunately not all the continued printk statements in the kernel are
> properly tagged with KERN_CONT (or pr_cont, etc.).

Yes and a quick search revealed that there are actually quite a lot of
those untagged messages.

As I needed some distraction from some other work I played around a bit
more with a solution which wouldn't require to change existing kernel
code. It uses a variable which would have to be available in every
function to store the loglevel of messages which are split over multiple
printk calls. Here is what I came up with so far:

#define PRINTK_IS_LINE(fmt) (					\
	((const char*)(fmt))[sizeof((fmt)) - 2] == '\n'		\
)

#define PRINTK_LEVEL(fmt) (					\
	(((const char *)(fmt))[0] == '<' &&			\
	 ((const char *)(fmt))[1] >= '0' &&			\
	 ((const char *)(fmt))[1] <= '9'			\
	) ? ((const char *)(fmt))[1] - '0' : 4			\
)

#define printk(fmt, ...) ({ 								\
	int __printk_ret = 0;								\
	int __printk_level = __printk_cont_level;					\
											\
	if (__builtin_constant_p((fmt)) && ((fmt))) {					\
		/* check if we are dealing with a line ending */			\
		if (PRINTK_IS_LINE((fmt))) {						\
			/* check if it was a whole line */				\
			if (__printk_cont_level == -1)					\
				__printk_level = PRINTK_LEVEL((fmt));			\
			__printk_cont_level = -1;					\
		} else if (__printk_cont_level == -1) /* first part of a line? */	\
			__printk_level = __printk_cont_level = PRINTK_LEVEL((fmt));	\
	}										\
											\
	if (!__builtin_constant_p((fmt)) || __printk_level <= CONFIG_PRINTK_VERBOSITY)	\
		__printk_ret = printk((fmt), ##__VA_ARGS__); 				\
											\
	__printk_ret;									\
})

Apart from the fact that it's getting uglier it obviously depends on
the availability of __printk_cont_level (which would get compiled out,
at least I hope so) in every function. 

So

void demo() {
	...
}

would have to become:

void demo() {
	int __printk_cont_level = -1;
	...	
}

I don't know whether this is possible at all through some kind of gcc
magic. There is also the problem of introducing warnings when 
__prink_cont_level isn't used in a function but I guess this could be
dealt with some __attribute__ setting.

Anyway just wanted to share the results of a brainstorming session.

Marc 

-- 
 Marc Andre Tanner >< http://www.brain-dump.org/ >< GPG key: CF7D56C0

Re: [PATCH 7/7] printk: provide a filtering macro for printk

[Geert Uytterhoeven]

On Wed, 2 Sep 2009, Tim Bird wrote:
> Marc Andre Tanner wrote:
> > On Tue, Sep 01, 2009 at 07:32:25PM -0400, H Hartley Sweeten wrote:
> >> On Tuesday, September 01, 2009 4:24 PM, Tim Bird wrote:
> >>> Some places in the kernel break the message into pieces, like so:
> >>>
> >>> printk(KERN_ERR, "Error: first part ");
> >>> ...
> >>> printk(" more info for error.\n");
> >> Technically, shouldn't the second part of the message actually be:
> >>
> >> printk(KERN_CONT " more info for error.\n");
> >>
> >> Maybe some mechanism could be created to handle the continued message
> >> if they have the KERN_CONT?
> > 
> > Yes it's true that KERN_CONT isn't handled correctly, but I don't see a way
> > to change that.
> > 
> >>> These parts would not be handled consistently under certain
> >>> conditions.
> >>>
> >>> It would be confusing to see only part of the message,
> >>> but I don't know how often this construct is used.  
> > 
> > $ grep -R KERN_CONT linux-2.6 | wc -l
> > 373
> > 
> >>> Maybe
> >>> another mechanism is needed to ensure that continuation
> >>> printk lines have the same log level as their start strings.
> > 
> > I currently don't see a way to achieve this with the CPP.
> 
> If it's that few, then maybe it's OK to actually change
> the code for those printk statements. (Heck, these locations
> were all changed in the last 2 years anyway.)
> 
> I'm just brainstorming here, but how about changing them from:
>   printk(KERN_INFO "foo");
>   printk(KERN_CONT "bar\n");
> to:
>   printk(KERN_INFO "foo");
>   printk_cont(KERN_INFO "bar\n");
> 
> This way the continuation line has the log level, and can
> be conditionally compiled based on the VERBOSITY level.  A little
> magic would be needed to strip the first 3 chars of the fmt
> string in printk_cont().

You could strip the first 3 chars by adding 3 to the pointer. Which will
fail horribly if the KERN_* is forgotten and the format string is very short.
And the KERN_* still consumes memory.

Or make the KERN_* an explicit first parameter:

    printk_cont(KERN_INFO, "bar\n");

Is "strcmp(p, KERN_INFO)" optimized away for constant strings?

> I think this makes the printk messages a bit more consistent anyway,
> and still marks lines that are continuation lines.

With kind regards,

Geert Uytterhoeven
Software Architect
Techsoft Centre

Technology and Software Centre Europe
The Corporate Village · Da Vincilaan 7-D1 · B-1935 Zaventem · Belgium

Phone:    +32 (0)2 700 8453
Fax:      +32 (0)2 700 8622
E-mail:   Geert.Uytterhoeven@sonycom.com
Internet: http://www.sony-europe.com/

A division of Sony Europe (Belgium) N.V.
VAT BE 0413.825.160 · RPR Brussels
Fortis · BIC GEBABEBB · IBAN BE41293037680010