Re: [PATCH 18/18] rcu: Use pr_fmt to prefix "rcu: " to logging output

[Joe Perches]

On Mon, 2018-05-14 at 15:24 -0700, Paul E. McKenney wrote:
> On Mon, May 14, 2018 at 02:41:59PM -0700, Joe Perches wrote:
> > On Mon, 2018-05-14 at 13:29 -0700, Paul E. McKenney wrote:
> > > On Thu, May 10, 2018 at 08:45:44AM -0700, Joe Perches wrote:
> > > > Use a consistent logging prefix for all rcu related output.
> > > > 
> > > > Signed-off-by: Joe Perches <joe@xxxxxxxxxxx>
> > > 
> > > I took parts of this (thank you!) but have concerns about other parts.
> > 
> > []
> > > > diff --git a/kernel/rcu/rcuperf.c b/kernel/rcu/rcuperf.c
> > > > index 076a50fb22ad..ebdd77b45470 100644
> > > > --- a/kernel/rcu/rcuperf.c
> > > > +++ b/kernel/rcu/rcuperf.c
> > > > @@ -19,6 +19,9 @@
> > > >   *
> > > >   * Authors: Paul E. McKenney <paulmck@xxxxxxxxxx>
> > > >   */
> > > > +
> > > > +#define pr_fmt(fmt) "rcu: " fmt
> > > 
> > > This is going to get us messages of the form "rcu: rcu-perf:", not?
> > > (And other odd combinations, depending on the flavor of RCU under test.)
> > > If so, this does not seem to be an improvement.
> > 
> > That depends on the existing embedded content of the format.
> > This will prefix just "rcu: " to pr_<level> output.
> 
> OK, so to make this work, I need to create special-purpose pr_fmt()
> definitions for torture, rcutorture, locktorture, and rcuperf.  Most
> of the rest don't care.

Yes, or allow the new generic #define for pr_fmt
to set those prefixes for you

#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt

will do the appropriate thing for rcutorture,

> Or am I missing something basic here?
> 
> > > > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > 
> > []
> > > > @@ -908,7 +909,7 @@ rcu_torture_writer(void *arg)
> > > >  	VERBOSE_TOROUT_STRING("rcu_torture_writer task started");
> > > >  	if (!can_expedite)
> > > >  		pr_alert("%s" TORTURE_FLAG
> > > > -			 " GP expediting controlled from boot/sysfs for %s.\n",
> > > > +			 " GP expediting controlled from boot/sysfs for %s\n",
> > > >  			 torture_type, cur_ops->name);
> > 
> > As there is _no_ pr_fmt #defined in this file,
> > output will/could be prefixed with KBUILD_MODNAME ": "
> > (in this case "rcutorture: ") if/when the generic
> > pr_fmt conversion patch is applied.
> 
> Not a fan, NACK.
> 
> > > >  	} else if (gp_sync && !cur_ops->sync) {
> > > > -		pr_alert("%s: gp_sync without primitives.\n", __func__);
> > > > +		pr_alert("%s: gp_sync without primitives\n", __func__);
> > > 
> > > I used a CDC Cyber 73 in the 1970s.
> > 
> > Fancy.  I used a CDC 6400 and an IBM 1620, but
> > those were pretty old when I started.
> 
> ;-)
> 
> > > It had tiny memory by today's
> > > standards, but even it had periods in its error messages.  We can easily
> > > afford them today, especially given that rcutorture is not included in
> > > small-memory Linux configurations.
> > 
> > OK, but I like consistency too.
> > 
> > ~90 percent of linux logging does not use terminating periods.
> > For instance, on my laptop:
> > 
> > $ uptime -p
> > up 1 week, 1 day, 13 hours, 37 minute
> > $ dmesg | wc -l
> > 4240
> > $ dmesg | grep -P "\w\.$"| wc -l
> > 381
> 
> Why is this a problem worth fixing?  From where I sit, it is not.

It's not a _problem_.  It's just an inconsistency.
I modify them passively when I see them.
If you don't like it, don't take it.

> Even assuming that this is somehow worth solving, why is it buried
> in an unrelated patch?

Touches each line fewer times.

> > > > @@ -1711,11 +1712,11 @@ static void rcu_test_debug_objects(void)
> > > > 
> > > >  	/* Wait for them all to get done so we can safely return. */
> > > >  	rcu_barrier();
> > > > -	pr_alert("%s: WARN: Duplicate call_rcu() test complete.\n", KBUILD_MODNAME);
> > > > +	pr_alert("WARN: Duplicate call_rcu() test complete\n");
> > > 
> > > I would like to keep these, as they mark the region of console output where
> > > splats are expected.
> > 
> > The prefixes are still there...
> > 
> > > >  	if (cur_ops->fqs == NULL && fqs_duration != 0) {
> > > > -		pr_alert("rcu-torture: ->fqs NULL and non-zero fqs_duration, fqs disabled.\n");
> > > > +		pr_alert("->fqs NULL and non-zero fqs_duration, fqs disabled\n");
> > > 
> > > This I would like to keep.  Easier to find.
> > 
> > One thing that you could use to validate the
> > output string format is after compilation:
> > 
> > $ strings kernel/rcu/rcutorture.o | grep -P "^[0-6]\w+:"
> > 
> > With your change, you will see duplicated prefixes.
> 
> Except that right now there are not duplicated prefixes.  Those
> apparently only show up after some earlier patch in/before your set is
> applied, correct? 

yes.
[PATCH 03/18] printk: Convert pr_fmt from blank define to KBUILD_MODNAME

> Is there some C-preprocessor macro indicating whether or not your changes
> have been applied?

?  pr_fmt would either be blank or something else.