[PATCH]More consistent behaviour for printk_*

[Patrick Georgi]

Hi,

the attached patch make printk_* behaviour more consistent. Without it, side 
effects in the arguments (eg. a pci config read, or variable increment) 
"vanish" with the message, and the behaviour changes.

Example:
printk_info("foo %d\n", i++);

Without this patch, this becomes (for suitable loglevels)
do {} while (0)

With this patch, this will be:
do_printk(EMERG, "", i++);

Some of these effects might be unwanted, but at least they are consistent now. 
For example, via c7 CAR failed for loglevel > 7 for various reasons (patch 
upcoming). While it fails all the time now (this patch is no "magic fix"), 
upcoming development is less likely to produce such "hidden surprises".

To reduce the memory footprint slightly, the formatted strings are discarded. 
A simpler patch would be to just kill the whole "#if #undef #define #endif"-
section, but then a lot of strings that never surface would be compiled in 
(and I doubt the compiler is clever enough to figure that out)

Signed-off-by: Patrick Georgi

Patrick

[Myles Watson]

> -----Original Message-----
> From: coreboot-bounces+mylesgw=[e-mail] [mailto:coreboot-
> bounces+mylesgw=[e-mail]] On Behalf Of Patrick Georgi
> Sent: Monday, April 27, 2009 11:49 AM
> To: [e-mail]
> Subject: [coreboot] [PATCH]More consistent behaviour for printk_*
>
> Hi,
>
> the attached patch make printk_* behaviour more consistent. Without it,
> side
> effects in the arguments (eg. a pci config read, or variable increment)
> "vanish" with the message, and the behaviour changes.
>
> Example:
> printk_info("foo %d\n", i++);
>
> Without this patch, this becomes (for suitable loglevels)
> do {} while (0)
>
> With this patch, this will be:
> do_printk(EMERG, "", i++);
>
> Some of these effects might be unwanted, but at least they are consistent
> now.
> For example, via c7 CAR failed for loglevel > 7 for various reasons (patch
> upcoming). While it fails all the time now (this patch is no "magic fix"),
> upcoming development is less likely to produce such "hidden surprises".
>
> To reduce the memory footprint slightly, the formatted strings are
> discarded.
> A simpler patch would be to just kill the whole "#if #undef #define
> #endif"-

I like simple.
> section, but then a lot of strings that never surface would be compiled in
> (and I doubt the compiler is clever enough to figure that out)

We discussed this recently for v3.  Do you have a good idea of how much
space this actually saves?
> Signed-off-by: Patrick Georgi

Acked-by: Myles Watson

Thanks,
Myles

[Stefan Reinauer]

On 27.04.2009 20:16 Uhr, Myles Watson wrote:
> > section, but then a lot of strings that never surface would be compiled in
> > (and I doubt the compiler is clever enough to figure that out)
>
> We discussed this recently for v3.  Do you have a good idea of how much
> space this actually saves?

It's hardly a few kilobytes. But this is no good way of saving space, by
trimming user messages and introducing side effects.

I think with Patrick's patch we can drop the MAXIMUM_CONSOLE_LOGLEVEL
variable from all stage2 code. It might make sense in the romcc code.
> > Signed-off-by: Patrick Georgi
>
> Acked-by: Myles Watson

I like it! Acked-by: Stefan Reinauer

Stefan Reinauer  writes:
> On 27.04.2009 20:16 Uhr, Myles Watson wrote:
>     section, but then a lot of strings that never surface would be compiled in
>     (and I doubt the compiler is clever enough to figure that out)
>
>
> We discussed this recently for v3.  Do you have a good idea of how much
> space this actually saves?
>
>
>
> It's hardly a few kilobytes. But this is no good way of saving space, by
> trimming user messages and introducing side effects.

When this was introduced.  It was the difference between code that met the
size targets and code that doesn't.  Largely because we have so many messages
at the spew level that really are not intended for users to see just developers.

Eric

[Carl-Daniel Hailfinger]

On 27.04.2009 19:48, Patrick Georgi wrote:
> Hi,
>
> the attached patch make printk_* behaviour more consistent. Without it, side 
> effects in the arguments (eg. a pci config read, or variable increment) 
> "vanish" with the message, and the behaviour changes.

Ouch. Great find!
> Example:
> printk_info("foo %d\n", i++);
>
> Without this patch, this becomes (for suitable loglevels)
> do {} while (0)
>
> With this patch, this will be:
> do_printk(EMERG, "", i++);
>
> Some of these effects might be unwanted, but at least they are consistent now. 
> For example, via c7 CAR failed for loglevel > 7 for various reasons (patch 
> upcoming). While it fails all the time now (this patch is no "magic fix"), 
> upcoming development is less likely to produce such "hidden surprises".
>
> To reduce the memory footprint slightly, the formatted strings are discarded. 
> A simpler patch would be to just kill the whole "#if #undef #define #endif"-
> section, but then a lot of strings that never surface would be compiled in 
> (and I doubt the compiler is clever enough to figure that out)
>
> Signed-off-by: Patrick Georgi

Let me propose an alternative which does not have an empty printk call,
yet keeps the side effects of all parameters.

Signed-off-by: Carl-Daniel Hailfinger

Index: LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
===================================================================
--- LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c	(Revision 4217)
+++ LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c	(Arbeitskopie)
@@ -13,39 +13,39 @@

#if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_EMERG
 #undef  printk_emerg
-#define printk_emerg(fmt, arg...)   do {} while(0)
+#define printk_emerg(fmt, arg...)   do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_ALERT
 #undef  printk_alert
-#define printk_alert(fmt, arg...)   do {} while(0)
+#define printk_alert(fmt, arg...)   do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_CRIT
 #undef  printk_crit
-#define printk_crit(fmt, arg...)    do {} while(0)
+#define printk_crit(fmt, arg...)    do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_ERR
 #undef  printk_err
-#define printk_err(fmt, arg...)     do {} while(0)
+#define printk_err(fmt, arg...)     do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_WARNING
 #undef  printk_warning
-#define printk_warning(fmt, arg...) do {} while(0)
+#define printk_warning(fmt, arg...) do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_NOTICE
 #undef  printk_notice
-#define printk_notice(fmt, arg...)  do {} while(0)
+#define printk_notice(fmt, arg...)  do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_INFO
 #undef  printk_info
-#define printk_info(fmt, arg...)    do {} while(0)
+#define printk_info(fmt, arg...)    do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_DEBUG
 #undef  printk_debug
-#define printk_debug(fmt, arg...)   do {} while(0)
+#define printk_debug(fmt, arg...)   do { arg; } while(0)
 #endif
 #if MAXIMUM_CONSOLE_LOGLEVEL <= BIOS_SPEW
 #undef  printk_spew
-#define printk_spew(fmt, arg...)    do {} while(0)
+#define printk_spew(fmt, arg...)    do { arg; } while(0)
 #endif

#define print_emerg(STR)   printk_emerg  ("%s", (STR))

[Patrick Georgi]

Am 27.04.2009 20:35, schrieb Carl-Daniel Hailfinger:
> Let me propose an alternative which does not have an empty printk call,
> yet keeps the side effects of all parameters.
>
> Signed-off-by: Carl-Daniel Hailfinger
> Index: LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
>
> --- LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c	(Revision 4217)
> +++ LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c	(Arbeitskopie)
> @@ -13,39 +13,39 @@
>
> #if MAXIMUM_CONSOLE_LOGLEVEL<= BIOS_EMERG
>   #undef  printk_emerg
> -#define printk_emerg(fmt, arg...)   do {} while(0)
> +#define printk_emerg(fmt, arg...)   do { arg; } while(0)

...

The only gripe I have with this is that certain bugs stay uncovered (eg. 
the via c7 CAR thing). But granted, they're very rare (basically: when a 
printk_* call is in a place where function calls won't work).

Option #3 would be to just drop all the blocks. Someone with more taste 
than I should decide on this.

Patrick

[ron minnich]

I think moving the v3 style printk to v2 makes the most sense.

ron

[Corey Osgood]

On Mon, Apr 27, 2009 at 3:26 PM, ron minnich  wrote:
> I think moving the v3 style printk to v2 makes the most sense.

If we're going to keep spending time making v2 more v3-like (printk, CBFS,
Kconfig, etc), then why even bother with v3? v3 seems like it's got some
really great advantages, but noone seems to care about finishing it.

-Corey

[Stefan Reinauer]

On 27.04.2009 21:32 Uhr, Corey Osgood wrote:
> On Mon, Apr 27, 2009 at 3:26 PM, ron minnich <[e-mail]
> > wrote:
> I think moving the v3 style printk to v2 makes the most sense.
>
>
> If we're going to keep spending time making v2 more v3-like (printk,
> CBFS, Kconfig, etc), then why even bother with v3? v3 seems like it's
> got some really great advantages, but noone seems to care about
> finishing it.

I think its time that we take what we have learned and bring v2 further
in an evolutionary way.

[ron minnich]

On Mon, Apr 27, 2009 at 1:46 PM, Stefan Reinauer  wrote:
> I think its time that we take what we have learned and bring v2 further in
> an evolutionary way.

I agree.

ron

[Carl-Daniel Hailfinger]

On 27.04.2009 21:32, Corey Osgood wrote:
> On Mon, Apr 27, 2009 at 3:26 PM, ron minnich  wrote:
> > I think moving the v3 style printk to v2 makes the most sense.
>
> If we're going to keep spending time making v2 more v3-like (printk, CBFS,
> Kconfig, etc), then why even bother with v3? v3 seems like it's got some
> really great advantages, but noone seems to care about finishing it.

I still hope we can whip v2 in shape well enough that major parts can be
transplanted into v3.

Regards,
Carl-Daniel

[Peter Stuge]

Corey Osgood wrote:
> v3 seems like it's got some really great advantages, but noone
> seems to care about finishing it.

I know that you and I care, but I have no resources at the moment.

v2 and v3 are converging. I consider it a good thing.
v2 has momentum and v3 has some brilliant solutions.

For some time still, I think both will see use.

//Peter

[Patrick Georgi]

Am 27.04.2009 21:26, schrieb ron minnich:
> I think moving the v3 style printk to v2 makes the most sense.

Would that fix the issue I brought up?

[Carl-Daniel Hailfinger]

On 27.04.2009 21:41, Patrick Georgi wrote:
> Am 27.04.2009 21:26, schrieb ron minnich:
> > I think moving the v3 style printk to v2 makes the most sense.
>
> Would that fix the issue I brought up?

AFAICS it wouldn't. But romcc interactions might become "interesting"
(register shortage etc.).

Regards,
Carl-Daniel

[Carl-Daniel Hailfinger]

On 27.04.2009 21:43, Carl-Daniel Hailfinger wrote:
> On 27.04.2009 21:41, Patrick Georgi wrote:
> > Am 27.04.2009 21:26, schrieb ron minnich:
> > > I think moving the v3 style printk to v2 makes the most sense.
> >
> > Would that fix the issue I brought up?
>
> AFAICS it wouldn't.

Apologies for that incorrect statement. I had remembered a patch which
changed v3 to the v2 style of compiling out some messages (which would
have resulted in three different printk levels (compiled-in messages,
printed-by-default messages and printed-with-current-level messages)
instead of only two levels) and thought that had been committed. Maybe
it was Myles who posted that patch, I can't remember anymore.
> But romcc interactions might become "interesting"
> (register shortage etc.).

The ROMCC interactions are still a probably valid concern.

ROM size might become a problem as well. After all, not everybody needs
all SPEW level messages compiled in.

To be honest, the longer I think about it, the more I favour the
three-level approach with the ability to compile some messages out.

Regards,
Carl-Daniel

[ron minnich]

On Mon, Apr 27, 2009 at 12:41 PM, Patrick Georgi  wrote:
> Am 27.04.2009 21:26, schrieb ron minnich:
> > I think moving the v3 style printk to v2 makes the most sense.
>
> Would that fix the issue I brought up?

yes, because the function call or other side effect is always there,
and the code is always executed, not compiled out. It would fix that
side-effect issue quite nicely.

ron

[Myles Watson]

On Mon, Apr 27, 2009 at 1:26 PM, ron minnich  wrote:
> I think moving the v3 style printk to v2 makes the most sense.

That's fine with me.  Since this fixes a real issue, let's get an easy
fix in now and switch over later.

Thanks,
Myles

[Carl-Daniel Hailfinger]

On 27.04.2009 20:41, Patrick Georgi wrote:
> Am 27.04.2009 20:35, schrieb Carl-Daniel Hailfinger:
> > Let me propose an alternative which does not have an empty printk call,
> > yet keeps the side effects of all parameters.
> >
> > Signed-off-by: Carl-Daniel Hailfinger
> >
> > Index:
> > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > ===================================================================
> >
> > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c   
> > (Revision 4217)
> > +++
> > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c   
> > (Arbeitskopie)
> > @@ -13,39 +13,39 @@
> >
> > #if MAXIMUM_CONSOLE_LOGLEVEL<= BIOS_EMERG
> >   #undef  printk_emerg
> > -#define printk_emerg(fmt, arg...)   do {} while(0)
> > +#define printk_emerg(fmt, arg...)   do { arg; } while(0)
>
> ...
>
> The only gripe I have with this is that certain bugs stay uncovered
> (eg. the via c7 CAR thing). But granted, they're very rare (basically:
> when a printk_* call is in a place where function calls won't work).

Could you please explain? Outside ROMCC compiled code (and arguably even
in ROMCC compiled code), there is not a single place where function
calls are allowed to fail. At least that's the impression I got in v3.
Since this is v2, I hope it acts sanely as well.
> Option #3 would be to just drop all the blocks. Someone with more
> taste than I should decide on this.

I'd rather keep them, but I won't veto any change.

Regards,
Carl-Daniel

[Myles Watson]

On Mon, Apr 27, 2009 at 3:30 PM, Carl-Daniel Hailfinger
 wrote:
> On 27.04.2009 20:41, Patrick Georgi wrote:
> > Am 27.04.2009 20:35, schrieb Carl-Daniel Hailfinger:
> > > Let me propose an alternative which does not have an empty printk call,
> > > yet keeps the side effects of all parameters.
> > >
> > > Signed-off-by: Carl-Daniel Hailfinger
> > >
> > > Index:
> > > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > ===================================================================
> > >
> > > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > (Revision 4217)
> > > +++
> > > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > (Arbeitskopie)
> > > @@ -13,39 +13,39 @@
> > >
> > > #if MAXIMUM_CONSOLE_LOGLEVEL<= BIOS_EMERG
> > >   #undef  printk_emerg
> > > -#define printk_emerg(fmt, arg...)   do {} while(0)
> > > +#define printk_emerg(fmt, arg...)   do { arg; } while(0)
> >
> > ...
> >
> > The only gripe I have with this is that certain bugs stay uncovered
> > (eg. the via c7 CAR thing). But granted, they're very rare (basically:
> > when a printk_* call is in a place where function calls won't work).
>
> Could you please explain? Outside ROMCC compiled code (and arguably even
> in ROMCC compiled code), there is not a single place where function
> calls are allowed to fail. At least that's the impression I got in v3.
> Since this is v2, I hope it acts sanely as well.

It wasn't that they were allowed to fail, it was a coding error.  The
stack wasn't set up, so the function calls failed.  The problem was
that the printk calls only failed sometimes (when they weren't
optimized out), which is unacceptable for debugging.

Hopefully that was the answer to your question.

Thanks,
Myles

[Carl-Daniel Hailfinger]

On 27.04.2009 23:58, Myles Watson wrote:
> On Mon, Apr 27, 2009 at 3:30 PM, Carl-Daniel Hailfinger
>  wrote:
> > On 27.04.2009 20:41, Patrick Georgi wrote:
> > > Am 27.04.2009 20:35, schrieb Carl-Daniel Hailfinger:
> > > > Let me propose an alternative which does not have an empty printk call,
> > > > yet keeps the side effects of all parameters.
> > > >
> > > > Signed-off-by: Carl-Daniel Hailfinger
> > > >
> > > > Index:
> > > > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > > ===================================================================
> > > >
> > > > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > > (Revision 4217)
> > > > +++
> > > > LinuxBIOSv2-printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > > (Arbeitskopie)
> > > > @@ -13,39 +13,39 @@
> > > >
> > > > #if MAXIMUM_CONSOLE_LOGLEVEL<= BIOS_EMERG
> > > >   #undef  printk_emerg
> > > > -#define printk_emerg(fmt, arg...)   do {} while(0)
> > > > +#define printk_emerg(fmt, arg...)   do { arg; } while(0)
> > >
> > > ...
> > >
> > > The only gripe I have with this is that certain bugs stay uncovered
> > > (eg. the via c7 CAR thing). But granted, they're very rare (basically:
> > > when a printk_* call is in a place where function calls won't work).
> >
> > Could you please explain? Outside ROMCC compiled code (and arguably even
> > in ROMCC compiled code), there is not a single place where function
> > calls are allowed to fail. At least that's the impression I got in v3.
> > Since this is v2, I hope it acts sanely as well.
>
> It wasn't that they were allowed to fail, it was a coding error.  The
> stack wasn't set up, so the function calls failed.  The problem was
> that the printk calls only failed sometimes (when they weren't
> optimized out), which is unacceptable for debugging.

Thanks, it is now completely clear.
That's why the v3 qemu target has lots of stack debugging at the
beginning and end of CAR. Maybe we want to do something similar here as
well?
> Hopefully that was the answer to your question.

Yes, indeed.

Regards,
Carl-Daniel

[Myles Watson]

> -----Original Message-----
> From: Carl-Daniel Hailfinger [mailto:[e-mail]]
> Sent: Tuesday, April 28, 2009 7:00 AM
> To: Myles Watson
> Cc: Patrick Georgi; [e-mail]
> Subject: Re: [coreboot] [PATCH]More consistent behaviour for printk_*
>
> On 27.04.2009 23:58, Myles Watson wrote:
> > On Mon, Apr 27, 2009 at 3:30 PM, Carl-Daniel Hailfinger
> >  wrote:
> > > On 27.04.2009 20:41, Patrick Georgi wrote:
> > > > Am 27.04.2009 20:35, schrieb Carl-Daniel Hailfinger:
> > > > > Let me propose an alternative which does not have an empty printk
>
> call,
> > > > > yet keeps the side effects of all parameters.
> > > > >
> > > > > Signed-off-by: Carl-Daniel Hailfinger<c-
>
> [e-mail]>
> > > > > Index:
> > > > > LinuxBIOSv2-
>
> printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > > > ===================================================================
> > > > >
> > > > > LinuxBIOSv2-
>
> printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > > > (Revision 4217)
> > > > > +++
> > > > > LinuxBIOSv2-
>
> printk_level_side_effects/src/arch/i386/lib/console_printk.c
> > > > > (Arbeitskopie)
> > > > > @@ -13,39 +13,39 @@
> > > > >
> > > > > #if MAXIMUM_CONSOLE_LOGLEVEL<= BIOS_EMERG
> > > > >   #undef  printk_emerg
> > > > > -#define printk_emerg(fmt, arg...)   do {} while(0)
> > > > > +#define printk_emerg(fmt, arg...)   do { arg; } while(0)
> > > >
> > > > ...
> > > >
> > > > The only gripe I have with this is that certain bugs stay uncovered
> > > > (eg. the via c7 CAR thing). But granted, they're very rare (basically:
> > > > when a printk_* call is in a place where function calls won't work).
> > >
> > > Could you please explain? Outside ROMCC compiled code (and arguably
>
> even
> > > in ROMCC compiled code), there is not a single place where function
> > > calls are allowed to fail. At least that's the impression I got in v3.
> > > Since this is v2, I hope it acts sanely as well.
> >
> > It wasn't that they were allowed to fail, it was a coding error.  The
> > stack wasn't set up, so the function calls failed.  The problem was
> > that the printk calls only failed sometimes (when they weren't
> > optimized out), which is unacceptable for debugging.
>
> Thanks, it is now completely clear.
> That's why the v3 qemu target has lots of stack debugging at the
> beginning and end of CAR. Maybe we want to do something similar here as
> well?

Good question.  I think if a printk will catch it every time that seems good
enough.  Adding complexity adds more ways for it to break.

Thanks,
Myles