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

2018-05-15 Thread Paul E. McKenney
On Tue, May 15, 2018 at 02:11:48PM -0700, Joe Perches wrote:
> On Tue, 2018-05-15 at 12:28 -0700, Paul E. McKenney wrote:
> > On Mon, May 14, 2018 at 05:32:05PM -0700, Paul E. McKenney wrote:
> > > On Mon, May 14, 2018 at 05:23:59PM -0700, Joe Perches wrote:
> > > > On Mon, 2018-05-14 at 16:58 -0700, Paul E. McKenney wrote:
> > > > > OK, so if I define pr_fmt as follows, I get the old behavior?
> > > > > 
> > > > >   #define pr_fmt(fmt) fmt
> > > > 
> > > > yes.
> > > 
> > > OK, then I will queue patches with this for the near term for
> > > the various torture files.
> > 
> > And here is the patch.  Thoughts?
> 
> Seems sensible.
> Perhaps still do the pr_alert->pr_cont conversions.

Agreed, and I have those queued as shown below.  Please let me know
if I missed something.

Thanx, Paul



commit adf02580b79ba77156bf60ccd338d9f49eaf8eb3
Author: Joe Perches 
Date:   Mon May 14 13:27:33 2018 -0700

rcu: Use pr_fmt to prefix "rcu: " to logging output

This commit also adjusts some whitespace while in the area.

Signed-off-by: Joe Perches 
Signed-off-by: Paul E. McKenney 
[ paulmck: Revert string-breaking %s as requested by Andy Shevchenko. ]

diff --git a/kernel/rcu/rcuperf.c b/kernel/rcu/rcuperf.c
index 479820d231bf..9047e5439e46 100644
--- a/kernel/rcu/rcuperf.c
+++ b/kernel/rcu/rcuperf.c
@@ -663,12 +663,11 @@ rcu_perf_init(void)
break;
}
if (i == ARRAY_SIZE(perf_ops)) {
-   pr_alert("rcu-perf: invalid perf type: \"%s\"\n",
-perf_type);
+   pr_alert("rcu-perf: invalid perf type: \"%s\"\n", perf_type);
pr_alert("rcu-perf types:");
for (i = 0; i < ARRAY_SIZE(perf_ops); i++)
-   pr_alert(" %s", perf_ops[i]->name);
-   pr_alert("\n");
+   pr_cont(" %s", perf_ops[i]->name);
+   pr_cont("\n");
firsterr = -EINVAL;
goto unwind;
}
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index ba82285a023a..9d80245b2a1c 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -1744,8 +1744,8 @@ rcu_torture_init(void)
 torture_type);
pr_alert("rcu-torture types:");
for (i = 0; i < ARRAY_SIZE(torture_ops); i++)
-   pr_alert(" %s", torture_ops[i]->name);
-   pr_alert("\n");
+   pr_cont(" %s", torture_ops[i]->name);
+   pr_cont("\n");
firsterr = -EINVAL;
goto unwind;
}
diff --git a/kernel/rcu/srcutree.c b/kernel/rcu/srcutree.c
index ff894ae6d386..031d2713701f 100644
--- a/kernel/rcu/srcutree.c
+++ b/kernel/rcu/srcutree.c
@@ -26,6 +26,8 @@
  *
  */
 
+#define pr_fmt(fmt) "rcu: " fmt
+
 #include 
 #include 
 #include 
@@ -390,7 +392,8 @@ void _cleanup_srcu_struct(struct srcu_struct *sp, bool 
quiesced)
}
if (WARN_ON(rcu_seq_state(READ_ONCE(sp->srcu_gp_seq)) != 
SRCU_STATE_IDLE) ||
WARN_ON(srcu_readers_active(sp))) {
-   pr_info("%s: Active srcu_struct %p state: %d\n", __func__, sp, 
rcu_seq_state(READ_ONCE(sp->srcu_gp_seq)));
+   pr_info("%s: Active srcu_struct %p state: %d\n",
+   __func__, sp, 
rcu_seq_state(READ_ONCE(sp->srcu_gp_seq)));
return; /* Caller forgot to stop doing call_srcu()? */
}
free_percpu(sp->sda);
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index 23b855f5c5cb..3826ce90fd6e 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -27,6 +27,9 @@
  * For detailed explanation of Read-Copy Update mechanism see -
  * Documentation/RCU
  */
+
+#define pr_fmt(fmt) "rcu: " fmt
+
 #include 
 #include 
 #include 
@@ -1352,8 +1355,7 @@ static void print_other_cpu_stall(struct rcu_state *rsp, 
unsigned long gp_seq)
 * See Documentation/RCU/stallwarn.txt for info on how to debug
 * RCU CPU stall warnings.
 */
-   pr_err("INFO: %s detected stalls on CPUs/tasks:",
-  rsp->name);
+   pr_err("INFO: %s detected stalls on CPUs/tasks:", rsp->name);
print_cpu_stall_info_begin();
rcu_for_each_leaf_node(rsp, rnp) {
raw_spin_lock_irqsave_rcu_node(rnp, flags);
@@ -3996,7 +3998,7 @@ static void __init rcu_init_geometry(void)
if (rcu_fanout_leaf == RCU_FANOUT_LEAF &&
nr_cpu_ids == NR_CPUS)
return;
-   pr_info("RCU: Adjusting geometry for rcu_fanout_leaf=%d, 
nr_cpu_ids=%u\n",
+   pr_info("Adjusting geometry for rcu_fanout_leaf=%d, nr_cpu_ids=%u\n",
rcu_fanout_leaf, nr_cpu_ids);
 
/*
diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
index 54a251640f53..dbfe90191e19 100644
--- a/kernel/rcu/tree_plugin.h

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

2018-05-15 Thread Joe Perches
On Tue, 2018-05-15 at 12:28 -0700, Paul E. McKenney wrote:
> On Mon, May 14, 2018 at 05:32:05PM -0700, Paul E. McKenney wrote:
> > On Mon, May 14, 2018 at 05:23:59PM -0700, Joe Perches wrote:
> > > On Mon, 2018-05-14 at 16:58 -0700, Paul E. McKenney wrote:
> > > > OK, so if I define pr_fmt as follows, I get the old behavior?
> > > > 
> > > > #define pr_fmt(fmt) fmt
> > > 
> > > yes.
> > 
> > OK, then I will queue patches with this for the near term for
> > the various torture files.
> 
> And here is the patch.  Thoughts?

Seems sensible.
Perhaps still do the pr_alert->pr_cont conversions.

cheers, Joe


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

2018-05-15 Thread Paul E. McKenney
On Mon, May 14, 2018 at 05:32:05PM -0700, Paul E. McKenney wrote:
> On Mon, May 14, 2018 at 05:23:59PM -0700, Joe Perches wrote:
> > On Mon, 2018-05-14 at 16:58 -0700, Paul E. McKenney wrote:
> > > OK, so if I define pr_fmt as follows, I get the old behavior?
> > > 
> > >   #define pr_fmt(fmt) fmt
> > 
> > yes.
> 
> OK, then I will queue patches with this for the near term for
> the various torture files.

And here is the patch.  Thoughts?

Thanx, Paul



commit de94f0b65dd4dcb7e651e2d85df9d9bc86b5bf23
Author: Paul E. McKenney 
Date:   Tue May 15 12:25:05 2018 -0700

torture: Keep old-school dmesg format

This commit adds "#define pr_fmt(fmt) fmt" to the torture-test files
in order to keep the current dmesg format.  Once Joe's commits have
hit mainline, these definitions will be changed in order to automatically
generate the dmesg line prefix that the scripts expect.  This will have
the beneficial side-effect of allowing printk() formats to be used more
widely and of shortening some pr_*() lines.

Signed-off-by: Paul E. McKenney 
Cc: Joe Perches 

diff --git a/kernel/locking/locktorture.c b/kernel/locking/locktorture.c
index 6d42670a1c70..5f00e5a2ef3b 100644
--- a/kernel/locking/locktorture.c
+++ b/kernel/locking/locktorture.c
@@ -21,6 +21,9 @@
  *  Davidlohr Bueso 
  * Based on kernel/rcu/torture.c.
  */
+
+#define pr_fmt(fmt) fmt
+
 #include 
 #include 
 #include 
diff --git a/kernel/rcu/rcuperf.c b/kernel/rcu/rcuperf.c
index 9047e5439e46..791f8ae7ce20 100644
--- a/kernel/rcu/rcuperf.c
+++ b/kernel/rcu/rcuperf.c
@@ -19,6 +19,9 @@
  *
  * Authors: Paul E. McKenney 
  */
+
+#define pr_fmt(fmt) fmt
+
 #include 
 #include 
 #include 
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 9d80245b2a1c..ca08e6733fa2 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -22,6 +22,9 @@
  *
  * See also:  Documentation/RCU/torture.txt
  */
+
+#define pr_fmt(fmt) fmt
+
 #include 
 #include 
 #include 
diff --git a/kernel/torture.c b/kernel/torture.c
index 840fd33c1cda..1ac24a826589 100644
--- a/kernel/torture.c
+++ b/kernel/torture.c
@@ -20,6 +20,9 @@
  * Author: Paul E. McKenney 
  * Based on kernel/rcu/torture.c.
  */
+
+#define pr_fmt(fmt) fmt
+
 #include 
 #include 
 #include 



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

2018-05-14 Thread Paul E. McKenney
On Mon, May 14, 2018 at 06:22:02PM -0700, Joe Perches wrote:
> On Mon, 2018-05-14 at 17:32 -0700, Paul E. McKenney wrote:
> > So this change does not affect WARN_ON_ONCE() and friends?
> 
> Changing define pr_fmt does not modify WARN_ON output.

Very good, I removed my --squash patch adding pr_fmt() to the file
kernel/rcu/rcu_segcblist.c.

Thanx, Paul



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

2018-05-14 Thread Joe Perches
On Mon, 2018-05-14 at 17:32 -0700, Paul E. McKenney wrote:
> So this change does not affect WARN_ON_ONCE() and friends?

Changing define pr_fmt does not modify WARN_ON output.



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

2018-05-14 Thread Paul E. McKenney
On Mon, May 14, 2018 at 05:23:59PM -0700, Joe Perches wrote:
> On Mon, 2018-05-14 at 16:58 -0700, Paul E. McKenney wrote:
> > OK, so if I define pr_fmt as follows, I get the old behavior?
> > 
> > #define pr_fmt(fmt) fmt
> 
> yes.

OK, then I will queue patches with this for the near term for
the various torture files.

> > 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
> 
> Well, I don't actually remember why the define
> was added to rcu_segcblist.c.
> 
> Most of this was done via a script which looked
> for pr_ uses without a pr_fmt in the same
> file.
> 
> Dunno why rcu_segcblist was modified.
> Maybe it was a braino.

So this change does not affect WARN_ON_ONCE() and friends?  (That was
my guess.)  If not, I will revert my squash patch.

And it could also be that the files changed between your running the
script and sending the patch.

Thanx, Paul



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

2018-05-14 Thread Joe Perches
On Mon, 2018-05-14 at 16:58 -0700, Paul E. McKenney wrote:
> OK, so if I define pr_fmt as follows, I get the old behavior?
> 
>   #define pr_fmt(fmt) fmt

yes.

> 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

Well, I don't actually remember why the define
was added to rcu_segcblist.c.

Most of this was done via a script which looked
for pr_ uses without a pr_fmt in the same
file.

Dunno why rcu_segcblist was modified.
Maybe it was a braino.


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

2018-05-14 Thread 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 
> > > > 
> > > > 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 
> > > > >   */
> > > > > +
> > > > > +#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_ 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

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

2018-05-14 Thread 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 
> > > 
> > > 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 
> > > >   */
> > > > +
> > > > +#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_ 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 els

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

2018-05-14 Thread Paul E. McKenney
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 
> > 
> > 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 
> > >   */
> > > +
> > > +#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_ 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.

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.

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

> > > @@ -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?  Plus with your change, I apparently get quite a few
semi-duplicated prefixes, which I would rather avoid, as it would add
pointless thrash to my rcutorture scripting.

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

Thanx, Paul



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

2018-05-14 Thread Joe Perches
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 
> 
> 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 
> >   */
> > +
> > +#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_ output.

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

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

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

cheers, Joe
> 


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

2018-05-14 Thread Paul E. McKenney
On Mon, May 14, 2018 at 11:37:56PM +0300, Andy Shevchenko wrote:
> On Mon, May 14, 2018 at 11:29 PM, Paul E. McKenney
>  wrote:
> > On Thu, May 10, 2018 at 08:45:44AM -0700, Joe Perches wrote:
> 
> > And I took this (but kept the period), plus used "%s" to make it fit in
> > 80 characters:
> >
> > pr_info("\tRCU restricting CPUs from %s=%d to %s=%u.\n",
> > "NR_CPUS", NR_CPUS, "nr_cpu_ids", nr_cpu_ids);
> 
> Why do care about 80 characters for string literals? (Checkpatch
> dropped this limit long time ago after some discussions)
> I think it's better to find line if more context given (this my
> objection agains %s for string literals).

Good point!  I am reverting that portion of the commit with attribution,
thank you!

Thanx, Paul



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

2018-05-14 Thread Paul E. McKenney
On Mon, May 14, 2018 at 01:52:48PM -0700, Randy Dunlap wrote:
> On 05/14/2018 01:29 PM, 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 
> > 
> > I took parts of this (thank you!) but have concerns about other parts.
> > 
> >> ---
> >>  kernel/rcu/rcu_segcblist.c |  2 ++
> >>  kernel/rcu/rcuperf.c   | 10 ---
> >>  kernel/rcu/rcutorture.c| 46 +++
> >>  kernel/rcu/srcutiny.c  |  2 ++
> >>  kernel/rcu/srcutree.c  |  5 +++-
> >>  kernel/rcu/tiny.c  |  3 +++
> >>  kernel/rcu/tree.c  |  8 +++---
> >>  kernel/rcu/tree_plugin.h   | 67 
> >> +++---
> >>  kernel/rcu/update.c| 19 -
> >>  9 files changed, 96 insertions(+), 66 deletions(-)
> >>
> 
> >> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> >> index 648e1c25707d..45d98ff0d5b8 100644
> >> --- a/kernel/rcu/rcutorture.c
> >> +++ b/kernel/rcu/rcutorture.c
> >> @@ -22,6 +22,7 @@
> >>   *
> >>   * See also:  Documentation/RCU/torture.txt
> >>   */
> >> +
> >>  #include 
> >>  #include 
> >>  #include 
> >> @@ -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);
> >>
> >>/* Initialize synctype[] array.  If none set, take default. */
> >> @@ -916,27 +917,27 @@ rcu_torture_writer(void *arg)
> >>gp_cond1 = gp_exp1 = gp_normal1 = gp_sync1 = true;
> >>if (gp_cond1 && cur_ops->get_state && cur_ops->cond_sync) {
> >>synctype[nsynctypes++] = RTWS_COND_GET;
> >> -  pr_info("%s: Testing conditional GPs.\n", __func__);
> >> +  pr_info("%s: Testing conditional GPs\n", __func__);
> >>} else if (gp_cond && (!cur_ops->get_state || !cur_ops->cond_sync)) {
> >> -  pr_alert("%s: gp_cond without primitives.\n", __func__);
> >> +  pr_alert("%s: gp_cond without primitives\n", __func__);
> >>}
> >>if (gp_exp1 && cur_ops->exp_sync) {
> >>synctype[nsynctypes++] = RTWS_EXP_SYNC;
> >> -  pr_info("%s: Testing expedited GPs.\n", __func__);
> >> +  pr_info("%s: Testing expedited GPs\n", __func__);
> >>} else if (gp_exp && !cur_ops->exp_sync) {
> >> -  pr_alert("%s: gp_exp without primitives.\n", __func__);
> >> +  pr_alert("%s: gp_exp without primitives\n", __func__);
> 
> Unlike some of the others, the one above is not a sentence, so it doesn't
> _need_ a period ... except for consistency.
> 
> But I don't care either way. :)

;-) ;-) ;-)

Thanx, Paul

> >>}
> >>if (gp_normal1 && cur_ops->deferred_free) {
> >>synctype[nsynctypes++] = RTWS_DEF_FREE;
> >> -  pr_info("%s: Testing asynchronous GPs.\n", __func__);
> >> +  pr_info("%s: Testing asynchronous GPs\n", __func__);
> >>} else if (gp_normal && !cur_ops->deferred_free) {
> >> -  pr_alert("%s: gp_normal without primitives.\n", __func__);
> >> +  pr_alert("%s: gp_normal without primitives\n", __func__);
> >>}
> >>if (gp_sync1 && cur_ops->sync) {
> >>synctype[nsynctypes++] = RTWS_SYNC;
> >> -  pr_info("%s: Testing normal GPs.\n", __func__);
> >> +  pr_info("%s: Testing normal GPs\n", __func__);
> >>} 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__);
> 
> 
> 
> 
> 
> 
> 
> 
> -- 
> ~Randy
> 



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

2018-05-14 Thread Randy Dunlap
On 05/14/2018 01:29 PM, 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 
> 
> I took parts of this (thank you!) but have concerns about other parts.
> 
>> ---
>>  kernel/rcu/rcu_segcblist.c |  2 ++
>>  kernel/rcu/rcuperf.c   | 10 ---
>>  kernel/rcu/rcutorture.c| 46 +++
>>  kernel/rcu/srcutiny.c  |  2 ++
>>  kernel/rcu/srcutree.c  |  5 +++-
>>  kernel/rcu/tiny.c  |  3 +++
>>  kernel/rcu/tree.c  |  8 +++---
>>  kernel/rcu/tree_plugin.h   | 67 
>> +++---
>>  kernel/rcu/update.c| 19 -
>>  9 files changed, 96 insertions(+), 66 deletions(-)
>>

>> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
>> index 648e1c25707d..45d98ff0d5b8 100644
>> --- a/kernel/rcu/rcutorture.c
>> +++ b/kernel/rcu/rcutorture.c
>> @@ -22,6 +22,7 @@
>>   *
>>   * See also:  Documentation/RCU/torture.txt
>>   */
>> +
>>  #include 
>>  #include 
>>  #include 
>> @@ -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);
>>
>>  /* Initialize synctype[] array.  If none set, take default. */
>> @@ -916,27 +917,27 @@ rcu_torture_writer(void *arg)
>>  gp_cond1 = gp_exp1 = gp_normal1 = gp_sync1 = true;
>>  if (gp_cond1 && cur_ops->get_state && cur_ops->cond_sync) {
>>  synctype[nsynctypes++] = RTWS_COND_GET;
>> -pr_info("%s: Testing conditional GPs.\n", __func__);
>> +pr_info("%s: Testing conditional GPs\n", __func__);
>>  } else if (gp_cond && (!cur_ops->get_state || !cur_ops->cond_sync)) {
>> -pr_alert("%s: gp_cond without primitives.\n", __func__);
>> +pr_alert("%s: gp_cond without primitives\n", __func__);
>>  }
>>  if (gp_exp1 && cur_ops->exp_sync) {
>>  synctype[nsynctypes++] = RTWS_EXP_SYNC;
>> -pr_info("%s: Testing expedited GPs.\n", __func__);
>> +pr_info("%s: Testing expedited GPs\n", __func__);
>>  } else if (gp_exp && !cur_ops->exp_sync) {
>> -pr_alert("%s: gp_exp without primitives.\n", __func__);
>> +pr_alert("%s: gp_exp without primitives\n", __func__);

Unlike some of the others, the one above is not a sentence, so it doesn't
_need_ a period ... except for consistency.

But I don't care either way. :)

>>  }
>>  if (gp_normal1 && cur_ops->deferred_free) {
>>  synctype[nsynctypes++] = RTWS_DEF_FREE;
>> -pr_info("%s: Testing asynchronous GPs.\n", __func__);
>> +pr_info("%s: Testing asynchronous GPs\n", __func__);
>>  } else if (gp_normal && !cur_ops->deferred_free) {
>> -pr_alert("%s: gp_normal without primitives.\n", __func__);
>> +pr_alert("%s: gp_normal without primitives\n", __func__);
>>  }
>>  if (gp_sync1 && cur_ops->sync) {
>>  synctype[nsynctypes++] = RTWS_SYNC;
>> -pr_info("%s: Testing normal GPs.\n", __func__);
>> +pr_info("%s: Testing normal GPs\n", __func__);
>>  } 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__);








-- 
~Randy


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

2018-05-14 Thread Andy Shevchenko
On Mon, May 14, 2018 at 11:29 PM, Paul E. McKenney
 wrote:
> On Thu, May 10, 2018 at 08:45:44AM -0700, Joe Perches wrote:

> And I took this (but kept the period), plus used "%s" to make it fit in
> 80 characters:
>
> pr_info("\tRCU restricting CPUs from %s=%d to %s=%u.\n",
> "NR_CPUS", NR_CPUS, "nr_cpu_ids", nr_cpu_ids);

Why do care about 80 characters for string literals? (Checkpatch
dropped this limit long time ago after some discussions)
I think it's better to find line if more context given (this my
objection agains %s for string literals).

-- 
With Best Regards,
Andy Shevchenko


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

2018-05-14 Thread Paul E. McKenney
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 

I took parts of this (thank you!) but have concerns about other parts.

> ---
>  kernel/rcu/rcu_segcblist.c |  2 ++
>  kernel/rcu/rcuperf.c   | 10 ---
>  kernel/rcu/rcutorture.c| 46 +++
>  kernel/rcu/srcutiny.c  |  2 ++
>  kernel/rcu/srcutree.c  |  5 +++-
>  kernel/rcu/tiny.c  |  3 +++
>  kernel/rcu/tree.c  |  8 +++---
>  kernel/rcu/tree_plugin.h   | 67 
> +++---
>  kernel/rcu/update.c| 19 -
>  9 files changed, 96 insertions(+), 66 deletions(-)
> 
> diff --git a/kernel/rcu/rcu_segcblist.c b/kernel/rcu/rcu_segcblist.c
> index 5aff271adf1e..b5f0e7234c4b 100644
> --- a/kernel/rcu/rcu_segcblist.c
> +++ b/kernel/rcu/rcu_segcblist.c
> @@ -20,6 +20,8 @@
>   * Authors: Paul E. McKenney 
>   */
> 
> +#define pr_fmt(fmt) "rcu: " fmt

Given that this file has no printk()s, how is this helping?  Interactions with
WARN_ON() or some such?

> +
>  #include 
>  #include 
>  #include 
> 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 
>   */
> +
> +#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.

> +
>  #include 
>  #include 
>  #include 
> @@ -663,12 +666,11 @@ rcu_perf_init(void)
>   break;
>   }
>   if (i == ARRAY_SIZE(perf_ops)) {
> - pr_alert("rcu-perf: invalid perf type: \"%s\"\n",
> -  perf_type);
> + pr_alert("rcu-perf: invalid perf type: \"%s\"\n", perf_type);
>   pr_alert("rcu-perf types:");
>   for (i = 0; i < ARRAY_SIZE(perf_ops); i++)
> - pr_alert(" %s", perf_ops[i]->name);
> - pr_alert("\n");
> + pr_cont(" %s", perf_ops[i]->name);
> + pr_cont("\n");

However, I did take the above changes, good catch!

>   firsterr = -EINVAL;
>   goto unwind;
>   }
> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index 648e1c25707d..45d98ff0d5b8 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -22,6 +22,7 @@
>   *
>   * See also:  Documentation/RCU/torture.txt
>   */
> +
>  #include 
>  #include 
>  #include 
> @@ -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);
> 
>   /* Initialize synctype[] array.  If none set, take default. */
> @@ -916,27 +917,27 @@ rcu_torture_writer(void *arg)
>   gp_cond1 = gp_exp1 = gp_normal1 = gp_sync1 = true;
>   if (gp_cond1 && cur_ops->get_state && cur_ops->cond_sync) {
>   synctype[nsynctypes++] = RTWS_COND_GET;
> - pr_info("%s: Testing conditional GPs.\n", __func__);
> + pr_info("%s: Testing conditional GPs\n", __func__);
>   } else if (gp_cond && (!cur_ops->get_state || !cur_ops->cond_sync)) {
> - pr_alert("%s: gp_cond without primitives.\n", __func__);
> + pr_alert("%s: gp_cond without primitives\n", __func__);
>   }
>   if (gp_exp1 && cur_ops->exp_sync) {
>   synctype[nsynctypes++] = RTWS_EXP_SYNC;
> - pr_info("%s: Testing expedited GPs.\n", __func__);
> + pr_info("%s: Testing expedited GPs\n", __func__);
>   } else if (gp_exp && !cur_ops->exp_sync) {
> - pr_alert("%s: gp_exp without primitives.\n", __func__);
> + pr_alert("%s: gp_exp without primitives\n", __func__);
>   }
>   if (gp_normal1 && cur_ops->deferred_free) {
>   synctype[nsynctypes++] = RTWS_DEF_FREE;
> - pr_info("%s: Testing asynchronous GPs.\n", __func__);
> + pr_info("%s: Testing asynchronous GPs\n", __func__);
>   } else if (gp_normal && !cur_ops->deferred_free) {
> - pr_alert("%s: gp_normal without primitives.\n", __func__);
> + pr_alert("%s: gp_normal without primitives\n", __func__);
>   }
>   if (gp_sync1 && cur_ops->sync) {
>   synctype[nsynctypes++] = RTWS_SYNC;
> - pr_info("%s: Testing normal GPs.\n", __func__);
> + pr_info("%s: Testing normal GPs\n", __func__);
>   } else if (gp_sync && !cur_ops->sync) {
> - pr_alert("%s: gp_sync without primitives.\n", _

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

2018-05-10 Thread Joe Perches
Use a consistent logging prefix for all rcu related output.

Signed-off-by: Joe Perches 
---
 kernel/rcu/rcu_segcblist.c |  2 ++
 kernel/rcu/rcuperf.c   | 10 ---
 kernel/rcu/rcutorture.c| 46 +++
 kernel/rcu/srcutiny.c  |  2 ++
 kernel/rcu/srcutree.c  |  5 +++-
 kernel/rcu/tiny.c  |  3 +++
 kernel/rcu/tree.c  |  8 +++---
 kernel/rcu/tree_plugin.h   | 67 +++---
 kernel/rcu/update.c| 19 -
 9 files changed, 96 insertions(+), 66 deletions(-)

diff --git a/kernel/rcu/rcu_segcblist.c b/kernel/rcu/rcu_segcblist.c
index 5aff271adf1e..b5f0e7234c4b 100644
--- a/kernel/rcu/rcu_segcblist.c
+++ b/kernel/rcu/rcu_segcblist.c
@@ -20,6 +20,8 @@
  * Authors: Paul E. McKenney 
  */
 
+#define pr_fmt(fmt) "rcu: " fmt
+
 #include 
 #include 
 #include 
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 
  */
+
+#define pr_fmt(fmt) "rcu: " fmt
+
 #include 
 #include 
 #include 
@@ -663,12 +666,11 @@ rcu_perf_init(void)
break;
}
if (i == ARRAY_SIZE(perf_ops)) {
-   pr_alert("rcu-perf: invalid perf type: \"%s\"\n",
-perf_type);
+   pr_alert("rcu-perf: invalid perf type: \"%s\"\n", perf_type);
pr_alert("rcu-perf types:");
for (i = 0; i < ARRAY_SIZE(perf_ops); i++)
-   pr_alert(" %s", perf_ops[i]->name);
-   pr_alert("\n");
+   pr_cont(" %s", perf_ops[i]->name);
+   pr_cont("\n");
firsterr = -EINVAL;
goto unwind;
}
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 648e1c25707d..45d98ff0d5b8 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -22,6 +22,7 @@
  *
  * See also:  Documentation/RCU/torture.txt
  */
+
 #include 
 #include 
 #include 
@@ -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);
 
/* Initialize synctype[] array.  If none set, take default. */
@@ -916,27 +917,27 @@ rcu_torture_writer(void *arg)
gp_cond1 = gp_exp1 = gp_normal1 = gp_sync1 = true;
if (gp_cond1 && cur_ops->get_state && cur_ops->cond_sync) {
synctype[nsynctypes++] = RTWS_COND_GET;
-   pr_info("%s: Testing conditional GPs.\n", __func__);
+   pr_info("%s: Testing conditional GPs\n", __func__);
} else if (gp_cond && (!cur_ops->get_state || !cur_ops->cond_sync)) {
-   pr_alert("%s: gp_cond without primitives.\n", __func__);
+   pr_alert("%s: gp_cond without primitives\n", __func__);
}
if (gp_exp1 && cur_ops->exp_sync) {
synctype[nsynctypes++] = RTWS_EXP_SYNC;
-   pr_info("%s: Testing expedited GPs.\n", __func__);
+   pr_info("%s: Testing expedited GPs\n", __func__);
} else if (gp_exp && !cur_ops->exp_sync) {
-   pr_alert("%s: gp_exp without primitives.\n", __func__);
+   pr_alert("%s: gp_exp without primitives\n", __func__);
}
if (gp_normal1 && cur_ops->deferred_free) {
synctype[nsynctypes++] = RTWS_DEF_FREE;
-   pr_info("%s: Testing asynchronous GPs.\n", __func__);
+   pr_info("%s: Testing asynchronous GPs\n", __func__);
} else if (gp_normal && !cur_ops->deferred_free) {
-   pr_alert("%s: gp_normal without primitives.\n", __func__);
+   pr_alert("%s: gp_normal without primitives\n", __func__);
}
if (gp_sync1 && cur_ops->sync) {
synctype[nsynctypes++] = RTWS_SYNC;
-   pr_info("%s: Testing normal GPs.\n", __func__);
+   pr_info("%s: Testing normal GPs\n", __func__);
} 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__);
}
if (WARN_ONCE(nsynctypes == 0,
  "rcu_torture_writer: No update-side primitives.\n")) {
@@ -1027,7 +1028,7 @@ rcu_torture_writer(void *arg)
WARN_ON_ONCE(can_expedite && rcu_gp_is_expedited());
if (!can_expedite)
pr_alert("%s" TORTURE_FLAG
-" Dynamic grace-period expediting was disabled.\n",
+" Dynamic grace-period expediting was disabled\n",
 torture_type);
rcu_tort