Re: [PATCH 2/5] of: dynamic: Refactor action prints to not use "%pOF" inside devtree_lock

[Rob Herring]

On Fri, Aug 4, 2023 at 12:55 PM Petr Mladek <pmladek@xxxxxxxx> wrote:
>
> On Tue 2023-08-01 15:54:45, Rob Herring wrote:
> > While originally it was fine to format strings using "%pOF" while
> > holding devtree_lock, this now causes a deadlock.  Lockdep reports:
> >
> >     of_get_parent from of_fwnode_get_parent+0x18/0x24
> >     ^^^^^^^^^^^^^
> >     of_fwnode_get_parent from fwnode_count_parents+0xc/0x28
> >     fwnode_count_parents from fwnode_full_name_string+0x18/0xac
> >     fwnode_full_name_string from device_node_string+0x1a0/0x404
> >     device_node_string from pointer+0x3c0/0x534
> >     pointer from vsnprintf+0x248/0x36c
> >     vsnprintf from vprintk_store+0x130/0x3b4
> >
> > To fix this, move the printing in __of_changeset_entry_apply() outside the
> > lock. As there's already similar printing of the same changeset actions,
> > refactor all of them to use a common action print function. This has the
> > side benefit of getting rid of some ifdefs.
> >
> > Fixes: a92eb7621b9fb2c2 ("lib/vsprintf: Make use of fwnode API to obtain node names and separators")
> > Reported-by: Geert Uytterhoeven <geert+renesas@xxxxxxxxx>
> > Signed-off-by: Rob Herring <robh@xxxxxxxxxx>
>
> > --- a/drivers/of/dynamic.c
> > +++ b/drivers/of/dynamic.c
> > @@ -63,37 +63,31 @@ int of_reconfig_notifier_unregister(struct notifier_block *nb)
> >  }
> >  EXPORT_SYMBOL_GPL(of_reconfig_notifier_unregister);
> >
> > -#ifdef DEBUG
> > -const char *action_names[] = {
> > +static const char *action_names[] = {
> >       [OF_RECONFIG_ATTACH_NODE] = "ATTACH_NODE",
> >       [OF_RECONFIG_DETACH_NODE] = "DETACH_NODE",
> >       [OF_RECONFIG_ADD_PROPERTY] = "ADD_PROPERTY",
> >       [OF_RECONFIG_REMOVE_PROPERTY] = "REMOVE_PROPERTY",
> >       [OF_RECONFIG_UPDATE_PROPERTY] = "UPDATE_PROPERTY",
> >  };
> > -#endif
> > +
> > +static void of_changeset_action_print(unsigned long action, struct device_node *np,
> > +                                   const char *prop_name)
> > +{
> > +     if (prop_name)
> > +             pr_cont("%-15s %pOF:%s\n", action_names[action], np, prop_name);
>
> Note that pr_cont() does not guarantee that the message will be appended to the
> previous part. Any message printed from another CPU or interrupt
> context might break the two pieces.
>
> It is better to avoid pr_cont() when possible.

Yeah, I got rid of it in the snippet I posted.

>
> > +     else
> > +             pr_cont("%-15s %pOF\n", action_names[action], np);
> > +}
> >
> >  int of_reconfig_notify(unsigned long action, struct of_reconfig_data *p)
> >  {
> >       int rc;
> > -#ifdef DEBUG
> >       struct of_reconfig_data *pr = p;
> >
> > -     switch (action) {
> > -     case OF_RECONFIG_ATTACH_NODE:
> > -     case OF_RECONFIG_DETACH_NODE:
> > -             pr_debug("notify %-15s %pOF\n", action_names[action],
> > -                     pr->dn);
> > -             break;
> > -     case OF_RECONFIG_ADD_PROPERTY:
> > -     case OF_RECONFIG_REMOVE_PROPERTY:
> > -     case OF_RECONFIG_UPDATE_PROPERTY:
> > -             pr_debug("notify %-15s %pOF:%s\n", action_names[action],
> > -                     pr->dn, pr->prop->name);
> > -             break;
> > +     if (pr_debug("notify "))
> > +             of_changeset_action_print(action, pr->dn, pr->prop ? pr->prop->name : NULL);
>
> If you really want to simplify this, then I would do:
>
>         pr_debug("notify %-15s %pOF%s%s\n",
>                   action_names[action], pr->dn,
>                   pr->prop ? ":" : ",
>                   pr->prop ? pr->prop->name : "");

That's a good idea.

> > -     }
> > -#endif
> >       rc = blocking_notifier_call_chain(&of_reconfig_chain, action, p);
> >       return notifier_to_errno(rc);
> >  }
> > @@ -599,7 +569,8 @@ static int __of_changeset_entry_apply(struct of_changeset_entry *ce)
> >       unsigned long flags;
> >       int ret = 0;
> >
> > -     __of_changeset_entry_dump(ce);
> > +     if (pr_debug("changeset: applying: cset<%p> ", ce))
> > +             of_changeset_action_print(ce->action, ce->np, ce->prop ? ce->prop->name : NULL);
>
> One possibility would be to create a macro for this, something like:
>
> #define of_ce_action_print(printk_level, prefix, ce)            \
>         printk(printk_level "%s cset<%p> %-15s %pOF%s%s\n"      \
>                 prefix, ce, action_names[action], pr->dn,       \
>                   pr->prop ? ":" : ",                           \
>                   pr->prop ? pr->prop->name : "");
>
> And use it like:
>
>         of_ce_action_print(KERN_DEBUG, "changeset: applying:", ce);

The problem there is the debug print is always enabled.

>
> But I am not sure if it is worth it. Sometimes it is better to
> opencode things so that it is clear what is going on.

Maybe so.

Rob