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

[Paul E. McKenney]

On Mon, May 14, 2018 at 03:54:13PM -0700, Joe Perches wrote:
> 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,

OK.  For rcutorture, there are special prefixes.  More on this at the end.

> > 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.

OK, fair enough.  I will pass.

> > 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.

OK, so if I define pr_fmt as follows, I get the old behavior?

	#define pr_fmt(fmt) fmt

If so, I can add this to the torture files, and then define pr_fmt more
sensibly for the torture files once your changes hit mainline.

Or if we can agree on the defintion, perhaps we get the sensible
definition into your patch series.  But I would much prefer the former
given the high rate of change in RCU at the moment.

Note that my concerns apply only to kernel/torture.c, kernel/rcu/rcuperf.c,
kernel/rcu/rcutorture.c, and kernel/locking/locktorture.c (despite my
earlier ack).  The other RCU files, including kernel/rcu/rcu_segcblist.c,
should be just fine with "#define pr_fmt()" added.  And I just queued
a commit to be squashed into my version of your patch 18/18 that adds
this to kernel/rcu/rcu_segcblist.c.  This joins the ones that your
patch added to kernel/rcu/srcutree.c and kernel/rcu/tree.c.

Should I also add "#define pr_fmt(fmt) "rcu: " fmt" to these files?

kernel/rcu/srcutiny.c
kernel/rcu/sync.c
kernel/rcu/tiny.c

							Thanx, Paul