of: introduce event tracepoints for dynamic device_node lifecyle

This patch introduces event tracepoints for tracking a device_nodes
reference cycle as well as reconfig notifications generated in response
to node/property manipulations.

With the recent upstreaming of the refcount API several device_node
underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
resources at runtime such as cpus or IOAs). These tracepoints provide a
easy and quick mechanism for validating the reference counting of
device_nodes during their lifetime.

Further, when pseries lpars are migrated to a different machine we
perform a live update of our device tree to bring it into alignment with the
configuration of the new machine. The of_reconfig_notify trace point
provides a mechanism that can be turned for debuging the device tree
modifications with out having to build a custom kernel to get at the
DEBUG code introduced by commit 00aa3720.

The following trace events are provided: of_node_get, of_node_put,
of_node_release, and of_reconfig_notify. These trace points require a kernel
built with ftrace support to be enabled. In a typical environment where
debugfs is mounted at /sys/kernel/debug the entire set of tracepoints
can be set with the following:

  echo "of:*" > /sys/kernel/debug/tracing/set_event

or

  echo 1 > /sys/kernel/debug/tracing/of/enable

The following shows the trace point data from a DLPAR remove of a cpu
from a pseries lpar:

cat /sys/kernel/debug/tracing/trace | grep "POWER8@10"

cpuhp/23-147   [023] ....   128.324827:
	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
cpuhp/23-147   [023] ....   128.324829:
	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
cpuhp/23-147   [023] ....   128.324829:
	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
cpuhp/23-147   [023] ....   128.324831:
	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
   drmgr-7284  [009] ....   128.439000:
	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
   drmgr-7284  [009] ....   128.439002:
	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
			    prop->name=null, old_prop->name=null
   drmgr-7284  [009] ....   128.439015:
	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
   drmgr-7284  [009] ....   128.439016:
	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4

Signed-off-by: Tyrel Datwyler <tyreld@linux.vnet.ibm.com>
---
 drivers/of/dynamic.c      | 30 ++++++---------
 include/trace/events/of.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 105 insertions(+), 18 deletions(-)
 create mode 100644 include/trace/events/of.h

FYI, this patch was meant to be sent as an RFC. Looks like the RFC tag
got lost in my last spin.

On 04/17/2017 05:32 PM, Tyrel Datwyler wrote:
> This patch introduces event tracepoints for tracking a device_nodes
> reference cycle as well as reconfig notifications generated in response
> to node/property manipulations.
> 
> With the recent upstreaming of the refcount API several device_node
> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
> resources at runtime such as cpus or IOAs). These tracepoints provide a
> easy and quick mechanism for validating the reference counting of
> device_nodes during their lifetime.
> 
> Further, when pseries lpars are migrated to a different machine we
> perform a live update of our device tree to bring it into alignment with the
> configuration of the new machine. The of_reconfig_notify trace point
> provides a mechanism that can be turned for debuging the device tree
> modifications with out having to build a custom kernel to get at the
> DEBUG code introduced by commit 00aa3720.
> 
> The following trace events are provided: of_node_get, of_node_put,
> of_node_release, and of_reconfig_notify. These trace points require a kernel
> built with ftrace support to be enabled. In a typical environment where
> debugfs is mounted at /sys/kernel/debug the entire set of tracepoints
> can be set with the following:
> 
>   echo "of:*" > /sys/kernel/debug/tracing/set_event
> 
> or
> 
>   echo 1 > /sys/kernel/debug/tracing/of/enable
> 
> The following shows the trace point data from a DLPAR remove of a cpu
> from a pseries lpar:
> 
> cat /sys/kernel/debug/tracing/trace | grep "POWER8@10"
> 
> cpuhp/23-147   [023] ....   128.324827:
> 	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324831:
> 	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439000:
> 	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439002:
> 	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
> 			    prop->name=null, old_prop->name=null
>    drmgr-7284  [009] ....   128.439015:
> 	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439016:
> 	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4
> 
> Signed-off-by: Tyrel Datwyler <tyreld@linux.vnet.ibm.com>
> ---
>  drivers/of/dynamic.c      | 30 ++++++---------
>  include/trace/events/of.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 105 insertions(+), 18 deletions(-)
>  create mode 100644 include/trace/events/of.h
> 
> diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
> index 888fdbc..85c0966 100644
> --- a/drivers/of/dynamic.c
> +++ b/drivers/of/dynamic.c
> @@ -16,6 +16,9 @@
> 
>  #include "of_private.h"
> 
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/of.h>
> +
>  /**
>   * of_node_get() - Increment refcount of a node
>   * @node:	Node to inc refcount, NULL is supported to simplify writing of
> @@ -25,8 +28,10 @@
>   */
>  struct device_node *of_node_get(struct device_node *node)
>  {
> -	if (node)
> +	if (node) {
>  		kobject_get(&node->kobj);
> +		trace_of_node_get(refcount_read(&node->kobj.kref.refcount), node->full_name);
> +	}
>  	return node;
>  }
>  EXPORT_SYMBOL(of_node_get);
> @@ -38,8 +43,10 @@ struct device_node *of_node_get(struct device_node *node)
>   */
>  void of_node_put(struct device_node *node)
>  {
> -	if (node)
> +	if (node) {
> +		trace_of_node_put(refcount_read(&node->kobj.kref.refcount) - 1, node->full_name);
>  		kobject_put(&node->kobj);
> +	}
>  }
>  EXPORT_SYMBOL(of_node_put);
> 
> @@ -92,24 +99,9 @@ int of_reconfig_notifier_unregister(struct notifier_block *nb)
>  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 %s\n", action_names[action],
> -			pr->dn->full_name);
> -		break;
> -	case OF_RECONFIG_ADD_PROPERTY:
> -	case OF_RECONFIG_REMOVE_PROPERTY:
> -	case OF_RECONFIG_UPDATE_PROPERTY:
> -		pr_debug("notify %-15s %s:%s\n", action_names[action],
> -			pr->dn->full_name, pr->prop->name);
> -		break;
> +	trace_of_reconfig_notify(action, p);
> 
> -	}
> -#endif
>  	rc = blocking_notifier_call_chain(&of_reconfig_chain, action, p);
>  	return notifier_to_errno(rc);
>  }
> @@ -326,6 +318,8 @@ void of_node_release(struct kobject *kobj)
>  	struct device_node *node = kobj_to_device_node(kobj);
>  	struct property *prop = node->properties;
> 
> +	trace_of_node_release(node);
> +
>  	/* We should never be releasing nodes that haven't been detached. */
>  	if (!of_node_check_flag(node, OF_DETACHED)) {
>  		pr_err("ERROR: Bad of_node_put() on %s\n", node->full_name);
> diff --git a/include/trace/events/of.h b/include/trace/events/of.h
> new file mode 100644
> index 0000000..0d53271
> --- /dev/null
> +++ b/include/trace/events/of.h
> @@ -0,0 +1,93 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM of
> +
> +#if !defined(_TRACE_OF_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_OF_H
> +
> +#include <linux/of.h>
> +#include <linux/tracepoint.h>
> +
> +DECLARE_EVENT_CLASS(of_node_ref_template,
> +
> +	TP_PROTO(int refcount, const char* dn_name),
> +
> +	TP_ARGS(refcount, dn_name),
> +
> +	TP_STRUCT__entry(
> +		__string(dn_name, dn_name)
> +		__field(int, refcount)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(dn_name, dn_name);
> +		__entry->refcount = refcount;
> +	),
> +
> +	TP_printk("refcount=%d, dn->full_name=%s",
> +		  __entry->refcount, __get_str(dn_name))
> +);
> +
> +DEFINE_EVENT(of_node_ref_template, of_node_get,
> +	     TP_PROTO(int refcount, const char* dn_name),
> +	     TP_ARGS(refcount, dn_name));
> +
> +DEFINE_EVENT(of_node_ref_template, of_node_put,
> +	     TP_PROTO(int refcount, const char* dn_name),
> +	     TP_ARGS(refcount, dn_name));
> +
> +TRACE_EVENT(of_node_release,
> +
> +	TP_PROTO(struct device_node *dn),
> +
> +	TP_ARGS(dn),
> +
> +	TP_STRUCT__entry(
> +		__string(dn_name, dn->full_name)
> +		__field(unsigned long, flags)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(dn_name, dn->full_name);
> +		__entry->flags = dn->_flags;
> +	),
> +
> +	TP_printk("dn->full_name=%s, dn->_flags=%lu", 
> +		  __get_str(dn_name), __entry->flags)
> +);
> +
> +#define of_reconfig_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"}
> +
> +TRACE_EVENT(of_reconfig_notify,
> +
> +	TP_PROTO(unsigned long action, struct of_reconfig_data *ord),
> +
> +	TP_ARGS(action, ord),
> +
> +	TP_STRUCT__entry(
> +		__field(unsigned long, action)
> +		__string(dn_name, ord->dn->full_name)
> +		__string(prop_name, ord->prop ? ord->prop->name : "null")
> +		__string(oldprop_name, ord->old_prop ? ord->old_prop->name : "null")
> +	),
> +
> +	TP_fast_assign(
> +		__entry->action = action;
> +		__assign_str(dn_name, ord->dn->full_name);
> +		__assign_str(prop_name, ord->prop ? ord->prop->name : "null");
> +		__assign_str(oldprop_name, ord->old_prop ? ord->old_prop->name : "null");
> +	),
> +
> +	TP_printk("action=%s, dn->full_name=%s, prop->name=%s, old_prop->name=%s",
> +		  __print_symbolic(__entry->action, of_reconfig_action_names),
> +		  __get_str(dn_name), __get_str(prop_name), __get_str(oldprop_name))
> +);
> +
> +#endif /*	_TRACE_OF_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
>

On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
<tyreld@linux.vnet.ibm.com> wrote:
> This patch introduces event tracepoints for tracking a device_nodes
> reference cycle as well as reconfig notifications generated in response
> to node/property manipulations.
>
> With the recent upstreaming of the refcount API several device_node
> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
> resources at runtime such as cpus or IOAs). These tracepoints provide a
> easy and quick mechanism for validating the reference counting of
> device_nodes during their lifetime.

Not really relevant for this patch, but since you are looking at
pseries and refcounting, the refcounting largely exists for pseries.
It's also hard to get right as this type of fix is fairly common. It's
now used for overlays, but we really probably only need to refcount
the overlays or changesets as a whole, not at a node level. If you
have any thoughts on how a different model of refcounting could work
for pseries, I'd like to discuss it.

> Further, when pseries lpars are migrated to a different machine we
> perform a live update of our device tree to bring it into alignment with the
> configuration of the new machine. The of_reconfig_notify trace point
> provides a mechanism that can be turned for debuging the device tree
> modifications with out having to build a custom kernel to get at the
> DEBUG code introduced by commit 00aa3720.
>
> The following trace events are provided: of_node_get, of_node_put,
> of_node_release, and of_reconfig_notify. These trace points require a kernel
> built with ftrace support to be enabled. In a typical environment where
> debugfs is mounted at /sys/kernel/debug the entire set of tracepoints
> can be set with the following:
>
>   echo "of:*" > /sys/kernel/debug/tracing/set_event
>
> or
>
>   echo 1 > /sys/kernel/debug/tracing/of/enable
>
> The following shows the trace point data from a DLPAR remove of a cpu
> from a pseries lpar:
>
> cat /sys/kernel/debug/tracing/trace | grep "POWER8@10"
>
> cpuhp/23-147   [023] ....   128.324827:
>         of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
>         of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
>         of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324831:
>         of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439000:
>         of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439002:
>         of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
>                             prop->name=null, old_prop->name=null
>    drmgr-7284  [009] ....   128.439015:
>         of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439016:
>         of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4
>
> Signed-off-by: Tyrel Datwyler <tyreld@linux.vnet.ibm.com>
> ---
>  drivers/of/dynamic.c      | 30 ++++++---------
>  include/trace/events/of.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 105 insertions(+), 18 deletions(-)
>  create mode 100644 include/trace/events/of.h
>
> diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
> index 888fdbc..85c0966 100644
> --- a/drivers/of/dynamic.c
> +++ b/drivers/of/dynamic.c
> @@ -16,6 +16,9 @@
>
>  #include "of_private.h"
>
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/of.h>
> +
>  /**
>   * of_node_get() - Increment refcount of a node
>   * @node:      Node to inc refcount, NULL is supported to simplify writing of
> @@ -25,8 +28,10 @@
>   */
>  struct device_node *of_node_get(struct device_node *node)
>  {
> -       if (node)
> +       if (node) {
>                 kobject_get(&node->kobj);
> +               trace_of_node_get(refcount_read(&node->kobj.kref.refcount), node->full_name);

Seems like there should be a kobj wrapper to read the refcount.

> +       }
>         return node;
>  }
>  EXPORT_SYMBOL(of_node_get);
> @@ -38,8 +43,10 @@ struct device_node *of_node_get(struct device_node *node)
>   */
>  void of_node_put(struct device_node *node)
>  {
> -       if (node)
> +       if (node) {
> +               trace_of_node_put(refcount_read(&node->kobj.kref.refcount) - 1, node->full_name);
>                 kobject_put(&node->kobj);
> +       }
>  }
>  EXPORT_SYMBOL(of_node_put);
>
> @@ -92,24 +99,9 @@ int of_reconfig_notifier_unregister(struct notifier_block *nb)
>  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 %s\n", action_names[action],
> -                       pr->dn->full_name);
> -               break;
> -       case OF_RECONFIG_ADD_PROPERTY:
> -       case OF_RECONFIG_REMOVE_PROPERTY:
> -       case OF_RECONFIG_UPDATE_PROPERTY:
> -               pr_debug("notify %-15s %s:%s\n", action_names[action],
> -                       pr->dn->full_name, pr->prop->name);
> -               break;
> +       trace_of_reconfig_notify(action, p);
>
> -       }
> -#endif
>         rc = blocking_notifier_call_chain(&of_reconfig_chain, action, p);
>         return notifier_to_errno(rc);
>  }
> @@ -326,6 +318,8 @@ void of_node_release(struct kobject *kobj)
>         struct device_node *node = kobj_to_device_node(kobj);
>         struct property *prop = node->properties;
>
> +       trace_of_node_release(node);
> +
>         /* We should never be releasing nodes that haven't been detached. */
>         if (!of_node_check_flag(node, OF_DETACHED)) {
>                 pr_err("ERROR: Bad of_node_put() on %s\n", node->full_name);
> diff --git a/include/trace/events/of.h b/include/trace/events/of.h
> new file mode 100644
> index 0000000..0d53271
> --- /dev/null
> +++ b/include/trace/events/of.h
> @@ -0,0 +1,93 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM of
> +
> +#if !defined(_TRACE_OF_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_OF_H
> +
> +#include <linux/of.h>
> +#include <linux/tracepoint.h>
> +
> +DECLARE_EVENT_CLASS(of_node_ref_template,
> +
> +       TP_PROTO(int refcount, const char* dn_name),
> +
> +       TP_ARGS(refcount, dn_name),
> +
> +       TP_STRUCT__entry(
> +               __string(dn_name, dn_name)
> +               __field(int, refcount)
> +       ),
> +
> +       TP_fast_assign(
> +               __assign_str(dn_name, dn_name);
> +               __entry->refcount = refcount;
> +       ),
> +
> +       TP_printk("refcount=%d, dn->full_name=%s",
> +                 __entry->refcount, __get_str(dn_name))
> +);
> +
> +DEFINE_EVENT(of_node_ref_template, of_node_get,
> +            TP_PROTO(int refcount, const char* dn_name),
> +            TP_ARGS(refcount, dn_name));
> +
> +DEFINE_EVENT(of_node_ref_template, of_node_put,
> +            TP_PROTO(int refcount, const char* dn_name),
> +            TP_ARGS(refcount, dn_name));
> +
> +TRACE_EVENT(of_node_release,
> +
> +       TP_PROTO(struct device_node *dn),
> +
> +       TP_ARGS(dn),
> +
> +       TP_STRUCT__entry(
> +               __string(dn_name, dn->full_name)
> +               __field(unsigned long, flags)
> +       ),
> +
> +       TP_fast_assign(
> +               __assign_str(dn_name, dn->full_name);
> +               __entry->flags = dn->_flags;
> +       ),
> +
> +       TP_printk("dn->full_name=%s, dn->_flags=%lu",
> +                 __get_str(dn_name), __entry->flags)
> +);
> +
> +#define of_reconfig_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"}
> +
> +TRACE_EVENT(of_reconfig_notify,
> +
> +       TP_PROTO(unsigned long action, struct of_reconfig_data *ord),
> +
> +       TP_ARGS(action, ord),
> +
> +       TP_STRUCT__entry(
> +               __field(unsigned long, action)
> +               __string(dn_name, ord->dn->full_name)
> +               __string(prop_name, ord->prop ? ord->prop->name : "null")
> +               __string(oldprop_name, ord->old_prop ? ord->old_prop->name : "null")
> +       ),
> +
> +       TP_fast_assign(
> +               __entry->action = action;
> +               __assign_str(dn_name, ord->dn->full_name);
> +               __assign_str(prop_name, ord->prop ? ord->prop->name : "null");
> +               __assign_str(oldprop_name, ord->old_prop ? ord->old_prop->name : "null");
> +       ),
> +
> +       TP_printk("action=%s, dn->full_name=%s, prop->name=%s, old_prop->name=%s",
> +                 __print_symbolic(__entry->action, of_reconfig_action_names),
> +                 __get_str(dn_name), __get_str(prop_name), __get_str(oldprop_name))
> +);
> +
> +#endif /*      _TRACE_OF_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> --
> 1.8.3.1
>

On 04/17/17 17:32, Tyrel Datwyler wrote:
> This patch introduces event tracepoints for tracking a device_nodes
> reference cycle as well as reconfig notifications generated in response
> to node/property manipulations.
> 
> With the recent upstreaming of the refcount API several device_node
> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
> resources at runtime such as cpus or IOAs). These tracepoints provide a
> easy and quick mechanism for validating the reference counting of
> device_nodes during their lifetime.
> 
> Further, when pseries lpars are migrated to a different machine we
> perform a live update of our device tree to bring it into alignment with the
> configuration of the new machine. The of_reconfig_notify trace point
> provides a mechanism that can be turned for debuging the device tree
> modifications with out having to build a custom kernel to get at the
> DEBUG code introduced by commit 00aa3720.

I do not like changing individual (or small groups of) printk() style
debugging information to tracepoint style.

As far as I know, there is no easy way to combine trace data and printk()
style data to create a single chronology of events.  If some of the
information needed to debug an issue is trace data and some is printk()
style data then it becomes more difficult to understand the overall
situation.

If Rob wants to convert printk() style data to trace data (and I can't
convince him otherwise) then I will have further comments on this specific
patch.

-Frank

> 
> The following trace events are provided: of_node_get, of_node_put,
> of_node_release, and of_reconfig_notify. These trace points require a kernel
> built with ftrace support to be enabled. In a typical environment where
> debugfs is mounted at /sys/kernel/debug the entire set of tracepoints
> can be set with the following:
> 
>   echo "of:*" > /sys/kernel/debug/tracing/set_event
> 
> or
> 
>   echo 1 > /sys/kernel/debug/tracing/of/enable
> 
> The following shows the trace point data from a DLPAR remove of a cpu
> from a pseries lpar:
> 
> cat /sys/kernel/debug/tracing/trace | grep "POWER8@10"
> 
> cpuhp/23-147   [023] ....   128.324827:
> 	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324831:
> 	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439000:
> 	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439002:
> 	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
> 			    prop->name=null, old_prop->name=null
>    drmgr-7284  [009] ....   128.439015:
> 	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439016:
> 	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4
> 
> Signed-off-by: Tyrel Datwyler <tyreld@linux.vnet.ibm.com>
> ---
>  drivers/of/dynamic.c      | 30 ++++++---------
>  include/trace/events/of.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 105 insertions(+), 18 deletions(-)
>  create mode 100644 include/trace/events/of.h
> 

< snip >

Frank Rowand <frowand.list@gmail.com> writes:

> On 04/17/17 17:32, Tyrel Datwyler wrote:
>> This patch introduces event tracepoints for tracking a device_nodes
>> reference cycle as well as reconfig notifications generated in response
>> to node/property manipulations.
>> 
>> With the recent upstreaming of the refcount API several device_node
>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>> easy and quick mechanism for validating the reference counting of
>> device_nodes during their lifetime.
>> 
>> Further, when pseries lpars are migrated to a different machine we
>> perform a live update of our device tree to bring it into alignment with the
>> configuration of the new machine. The of_reconfig_notify trace point
>> provides a mechanism that can be turned for debuging the device tree
>> modifications with out having to build a custom kernel to get at the
>> DEBUG code introduced by commit 00aa3720.
>
> I do not like changing individual (or small groups of) printk() style
> debugging information to tracepoint style.

I'm not quite sure which printks() you're referring to.

The only printks that are removed in this series are under #ifdef DEBUG,
and so are essentially not there unless you build a custom kernel.

They also only cover the reconfig case, which is actually less
interesting than the much more common and bug-prone get/put logic.

> As far as I know, there is no easy way to combine trace data and printk()
> style data to create a single chronology of events.  If some of the
> information needed to debug an issue is trace data and some is printk()
> style data then it becomes more difficult to understand the overall
> situation.

If you enable CONFIG_PRINTK_TIME then you should be able to just sort
the trace and the printk output by the timestamp. If you're really
trying to correlate the two then you should probably just be using
trace_printk().

But IMO this level of detail, tracing every get/put, does not belong in
printk. Trace points are absolutely the right solution for this type of
debugging.

cheers

On 04/18/17 17:07, Frank Rowand wrote:
> On 04/17/17 17:32, Tyrel Datwyler wrote:
>> This patch introduces event tracepoints for tracking a device_nodes
>> reference cycle as well as reconfig notifications generated in response
>> to node/property manipulations.
>>
>> With the recent upstreaming of the refcount API several device_node
>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>> easy and quick mechanism for validating the reference counting of
>> device_nodes during their lifetime.
>>
>> Further, when pseries lpars are migrated to a different machine we
>> perform a live update of our device tree to bring it into alignment with the
>> configuration of the new machine. The of_reconfig_notify trace point
>> provides a mechanism that can be turned for debuging the device tree
>> modifications with out having to build a custom kernel to get at the
>> DEBUG code introduced by commit 00aa3720.
> 
> I do not like changing individual (or small groups of) printk() style
> debugging information to tracepoint style.
> 
> As far as I know, there is no easy way to combine trace data and printk()
> style data to create a single chronology of events.  If some of the
> information needed to debug an issue is trace data and some is printk()
> style data then it becomes more difficult to understand the overall
> situation.

And of course the other issue with using tracepoints is the extra space
required to hold the tracepoint info.  With the pr_debug() approach, the
space usage can be easily removed for a production kernel via a config
option.

Tracepoints are wonderful technology, but not always the proper tool to
use for debug info.

> If Rob wants to convert printk() style data to trace data (and I can't
> convince him otherwise) then I will have further comments on this specific
> patch.
> 
> -Frank
> 
>>
>> The following trace events are provided: of_node_get, of_node_put,
>> of_node_release, and of_reconfig_notify. These trace points require a kernel
>> built with ftrace support to be enabled. In a typical environment where
>> debugfs is mounted at /sys/kernel/debug the entire set of tracepoints
>> can be set with the following:
>>
>>   echo "of:*" > /sys/kernel/debug/tracing/set_event
>>
>> or
>>
>>   echo 1 > /sys/kernel/debug/tracing/of/enable
>>
>> The following shows the trace point data from a DLPAR remove of a cpu
>> from a pseries lpar:
>>
>> cat /sys/kernel/debug/tracing/trace | grep "POWER8@10"
>>
>> cpuhp/23-147   [023] ....   128.324827:
>> 	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
>> cpuhp/23-147   [023] ....   128.324829:
>> 	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
>> cpuhp/23-147   [023] ....   128.324829:
>> 	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
>> cpuhp/23-147   [023] ....   128.324831:
>> 	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
>>    drmgr-7284  [009] ....   128.439000:
>> 	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
>>    drmgr-7284  [009] ....   128.439002:
>> 	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
>> 			    prop->name=null, old_prop->name=null
>>    drmgr-7284  [009] ....   128.439015:
>> 	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
>>    drmgr-7284  [009] ....   128.439016:
>> 	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4
>>
>> Signed-off-by: Tyrel Datwyler <tyreld@linux.vnet.ibm.com>
>> ---
>>  drivers/of/dynamic.c      | 30 ++++++---------
>>  include/trace/events/of.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++
>>  2 files changed, 105 insertions(+), 18 deletions(-)
>>  create mode 100644 include/trace/events/of.h
>>
> 
> < snip >
> 
>

On Wed, Apr 19, 2017 at 2:46 AM, Rob Herring <robh+dt@kernel.org> wrote:
> On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
> <tyreld@linux.vnet.ibm.com> wrote:
>> This patch introduces event tracepoints for tracking a device_nodes
>> reference cycle as well as reconfig notifications generated in response
>> to node/property manipulations.
>>
>> With the recent upstreaming of the refcount API several device_node
>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>> easy and quick mechanism for validating the reference counting of
>> device_nodes during their lifetime.
>
> Not really relevant for this patch, but since you are looking at
> pseries and refcounting, the refcounting largely exists for pseries.
> It's also hard to get right as this type of fix is fairly common. It's
> now used for overlays, but we really probably only need to refcount
> the overlays or changesets as a whole, not at a node level. If you
> have any thoughts on how a different model of refcounting could work
> for pseries, I'd like to discuss it.

One idea I've been kicking around is differentiating short and long
term references to a node. I figure most leaks are due to a missing
of_node_put() within a stack frame so it might be possible to use the
ftrace infrastructure to detect and emit warnings if a short term
reference is leaked. Long term references are slightly harder to deal
with, but they're less common so we can add more detailed reference
tracking there (devm_of_get_node?).

Oliver

On 04/18/17 18:31, Michael Ellerman wrote:
> Frank Rowand <frowand.list@gmail.com> writes:
> 
>> On 04/17/17 17:32, Tyrel Datwyler wrote:
>>> This patch introduces event tracepoints for tracking a device_nodes
>>> reference cycle as well as reconfig notifications generated in response
>>> to node/property manipulations.
>>>
>>> With the recent upstreaming of the refcount API several device_node
>>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>>> easy and quick mechanism for validating the reference counting of
>>> device_nodes during their lifetime.
>>>
>>> Further, when pseries lpars are migrated to a different machine we
>>> perform a live update of our device tree to bring it into alignment with the
>>> configuration of the new machine. The of_reconfig_notify trace point
>>> provides a mechanism that can be turned for debuging the device tree
>>> modifications with out having to build a custom kernel to get at the
>>> DEBUG code introduced by commit 00aa3720.
>>
>> I do not like changing individual (or small groups of) printk() style
>> debugging information to tracepoint style.
> 
> I'm not quite sure which printks() you're referring to.
> 
> The only printks that are removed in this series are under #ifdef DEBUG,
> and so are essentially not there unless you build a custom kernel.

Yes, I am talking about pr_debug(), pr_info(), pr_err(), etc.


> 
> They also only cover the reconfig case, which is actually less
> interesting than the much more common and bug-prone get/put logic.

When I was looking at the get/put issue I used pr_debug().


>> As far as I know, there is no easy way to combine trace data and printk()
>> style data to create a single chronology of events.  If some of the
>> information needed to debug an issue is trace data and some is printk()
>> style data then it becomes more difficult to understand the overall
>> situation.
> 
> If you enable CONFIG_PRINTK_TIME then you should be able to just sort
> the trace and the printk output by the timestamp. If you're really
> trying to correlate the two then you should probably just be using
> trace_printk().

Except the existing debug code that uses pr_debug() does not use
trace_printk().

And "just sort" does not apply to multi-line output like:

cpuhp/23-147   [023] ....   128.324827:
	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
cpuhp/23-147   [023] ....   128.324829:
	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
cpuhp/23-147   [023] ....   128.324829:
	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
cpuhp/23-147   [023] ....   128.324831:
	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
   drmgr-7284  [009] ....   128.439000:
	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
   drmgr-7284  [009] ....   128.439002:
	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
			    prop->name=null, old_prop->name=null
   drmgr-7284  [009] ....   128.439015:
	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
   drmgr-7284  [009] ....   128.439016:
	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4

I was kinda hoping that maybe someone had already created a tool to deal
with this issue.  But not too optimistic.


> But IMO this level of detail, tracing every get/put, does not belong in
> printk. Trace points are absolutely the right solution for this type of
> debugging.
> 
> cheers
> .
>

On Tue, 18 Apr 2017 17:07:17 -0700
Frank Rowand <frowand.list@gmail.com> wrote:


> As far as I know, there is no easy way to combine trace data and printk()
> style data to create a single chronology of events.  If some of the
> information needed to debug an issue is trace data and some is printk()
> style data then it becomes more difficult to understand the overall
> situation.

You mean like:

 # echo 1 > /sys/kernel/debug/tracing/events/printk/console/enable

Makes all printks also go into the ftrace ring buffer.

-- Steve

> 
> If Rob wants to convert printk() style data to trace data (and I can't
> convince him otherwise) then I will have further comments on this specific
> patch.
>

On Tue, 18 Apr 2017 18:42:32 -0700
Frank Rowand <frowand.list@gmail.com> wrote:

> And of course the other issue with using tracepoints is the extra space
> required to hold the tracepoint info.  With the pr_debug() approach, the
> space usage can be easily removed for a production kernel via a config
> option.

Now if you are saying you want to be able to enable debugging without
the tracing infrastructure I would agree. As the tracing infrastructure
is large. But I'm working on shrinking it more.

> 
> Tracepoints are wonderful technology, but not always the proper tool to
> use for debug info.

But if you are going to have tracing enabled regardless, adding a few
more tracepoints isn't going to make the difference.

-- Steve

> 
> > If Rob wants to convert printk() style data to trace data (and I can't
> > convince him otherwise) then I will have further comments on this specific
> > patch.
> >

On 04/18/17 19:46, Steven Rostedt wrote:
> On Tue, 18 Apr 2017 17:07:17 -0700
> Frank Rowand <frowand.list@gmail.com> wrote:
> 
> 
>> As far as I know, there is no easy way to combine trace data and printk()
>> style data to create a single chronology of events.  If some of the
>> information needed to debug an issue is trace data and some is printk()
>> style data then it becomes more difficult to understand the overall
>> situation.
> 
> You mean like:
> 
>  # echo 1 > /sys/kernel/debug/tracing/events/printk/console/enable
> 
> Makes all printks also go into the ftrace ring buffer.

Thanks!  I was hoping there was going to be an easy answer like this.


> -- Steve
> 
>>
>> If Rob wants to convert printk() style data to trace data (and I can't
>> convince him otherwise) then I will have further comments on this specific
>> patch.
>>
> .
>

Oliver O'Halloran <oohall@gmail.com> writes:

> On Wed, Apr 19, 2017 at 2:46 AM, Rob Herring <robh+dt@kernel.org> wrote:
>> On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
>> <tyreld@linux.vnet.ibm.com> wrote:
>>> This patch introduces event tracepoints for tracking a device_nodes
>>> reference cycle as well as reconfig notifications generated in response
>>> to node/property manipulations.
>>>
>>> With the recent upstreaming of the refcount API several device_node
>>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>>> easy and quick mechanism for validating the reference counting of
>>> device_nodes during their lifetime.
>>
>> Not really relevant for this patch, but since you are looking at
>> pseries and refcounting, the refcounting largely exists for pseries.
>> It's also hard to get right as this type of fix is fairly common. It's
>> now used for overlays, but we really probably only need to refcount
>> the overlays or changesets as a whole, not at a node level. If you
>> have any thoughts on how a different model of refcounting could work
>> for pseries, I'd like to discuss it.
>
> One idea I've been kicking around is differentiating short and long
> term references to a node.

I actually did this a long time ago, but balked at the size of the patch
to do the conversion. Let me see if I can find it lying around ...

cheers

On 04/17/17 17:32, Tyrel Datwyler wrote:
> This patch introduces event tracepoints for tracking a device_nodes
> reference cycle as well as reconfig notifications generated in response
> to node/property manipulations.
> 
> With the recent upstreaming of the refcount API several device_node
> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
> resources at runtime such as cpus or IOAs). These tracepoints provide a
> easy and quick mechanism for validating the reference counting of
> device_nodes during their lifetime.
> 
> Further, when pseries lpars are migrated to a different machine we
> perform a live update of our device tree to bring it into alignment with the
> configuration of the new machine. The of_reconfig_notify trace point
> provides a mechanism that can be turned for debuging the device tree
> modifications with out having to build a custom kernel to get at the
> DEBUG code introduced by commit 00aa3720.

Is the normal kernel built with CONFIG_DYNAMIC_DEBUG=y?  If so, then
simply removing the "ifdef DEBUG" around the switch in
of_reconfig_notify() would solve that issue.

-Frank


> The following trace events are provided: of_node_get, of_node_put,
> of_node_release, and of_reconfig_notify. These trace points require a kernel
> built with ftrace support to be enabled. In a typical environment where
> debugfs is mounted at /sys/kernel/debug the entire set of tracepoints
> can be set with the following:
> 
>   echo "of:*" > /sys/kernel/debug/tracing/set_event
> 
> or
> 
>   echo 1 > /sys/kernel/debug/tracing/of/enable
> 
> The following shows the trace point data from a DLPAR remove of a cpu
> from a pseries lpar:
> 
> cat /sys/kernel/debug/tracing/trace | grep "POWER8@10"
> 
> cpuhp/23-147   [023] ....   128.324827:
> 	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324831:
> 	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439000:
> 	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439002:
> 	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
> 			    prop->name=null, old_prop->name=null
>    drmgr-7284  [009] ....   128.439015:
> 	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439016:
> 	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4
> 
> Signed-off-by: Tyrel Datwyler <tyreld@linux.vnet.ibm.com>
> ---
>  drivers/of/dynamic.c      | 30 ++++++---------
>  include/trace/events/of.h | 93 +++++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 105 insertions(+), 18 deletions(-)
>  create mode 100644 include/trace/events/of.h
> 
> diff --git a/drivers/of/dynamic.c b/drivers/of/dynamic.c
> index 888fdbc..85c0966 100644
> --- a/drivers/of/dynamic.c
> +++ b/drivers/of/dynamic.c
> @@ -16,6 +16,9 @@
>  
>  #include "of_private.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/of.h>
> +
>  /**
>   * of_node_get() - Increment refcount of a node
>   * @node:	Node to inc refcount, NULL is supported to simplify writing of
> @@ -25,8 +28,10 @@
>   */
>  struct device_node *of_node_get(struct device_node *node)
>  {
> -	if (node)
> +	if (node) {
>  		kobject_get(&node->kobj);
> +		trace_of_node_get(refcount_read(&node->kobj.kref.refcount), node->full_name);
> +	}
>  	return node;
>  }
>  EXPORT_SYMBOL(of_node_get);
> @@ -38,8 +43,10 @@ struct device_node *of_node_get(struct device_node *node)
>   */
>  void of_node_put(struct device_node *node)
>  {
> -	if (node)
> +	if (node) {
> +		trace_of_node_put(refcount_read(&node->kobj.kref.refcount) - 1, node->full_name);
>  		kobject_put(&node->kobj);
> +	}
>  }
>  EXPORT_SYMBOL(of_node_put);
>  
> @@ -92,24 +99,9 @@ int of_reconfig_notifier_unregister(struct notifier_block *nb)
>  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 %s\n", action_names[action],
> -			pr->dn->full_name);
> -		break;
> -	case OF_RECONFIG_ADD_PROPERTY:
> -	case OF_RECONFIG_REMOVE_PROPERTY:
> -	case OF_RECONFIG_UPDATE_PROPERTY:
> -		pr_debug("notify %-15s %s:%s\n", action_names[action],
> -			pr->dn->full_name, pr->prop->name);
> -		break;
> +	trace_of_reconfig_notify(action, p);
>  
> -	}
> -#endif
>  	rc = blocking_notifier_call_chain(&of_reconfig_chain, action, p);
>  	return notifier_to_errno(rc);
>  }
> @@ -326,6 +318,8 @@ void of_node_release(struct kobject *kobj)
>  	struct device_node *node = kobj_to_device_node(kobj);
>  	struct property *prop = node->properties;
>  
> +	trace_of_node_release(node);
> +
>  	/* We should never be releasing nodes that haven't been detached. */
>  	if (!of_node_check_flag(node, OF_DETACHED)) {
>  		pr_err("ERROR: Bad of_node_put() on %s\n", node->full_name);
> diff --git a/include/trace/events/of.h b/include/trace/events/of.h
> new file mode 100644
> index 0000000..0d53271
> --- /dev/null
> +++ b/include/trace/events/of.h
> @@ -0,0 +1,93 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM of
> +
> +#if !defined(_TRACE_OF_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_OF_H
> +
> +#include <linux/of.h>
> +#include <linux/tracepoint.h>
> +
> +DECLARE_EVENT_CLASS(of_node_ref_template,
> +
> +	TP_PROTO(int refcount, const char* dn_name),
> +
> +	TP_ARGS(refcount, dn_name),
> +
> +	TP_STRUCT__entry(
> +		__string(dn_name, dn_name)
> +		__field(int, refcount)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(dn_name, dn_name);
> +		__entry->refcount = refcount;
> +	),
> +
> +	TP_printk("refcount=%d, dn->full_name=%s",
> +		  __entry->refcount, __get_str(dn_name))
> +);
> +
> +DEFINE_EVENT(of_node_ref_template, of_node_get,
> +	     TP_PROTO(int refcount, const char* dn_name),
> +	     TP_ARGS(refcount, dn_name));
> +
> +DEFINE_EVENT(of_node_ref_template, of_node_put,
> +	     TP_PROTO(int refcount, const char* dn_name),
> +	     TP_ARGS(refcount, dn_name));
> +
> +TRACE_EVENT(of_node_release,
> +
> +	TP_PROTO(struct device_node *dn),
> +
> +	TP_ARGS(dn),
> +
> +	TP_STRUCT__entry(
> +		__string(dn_name, dn->full_name)
> +		__field(unsigned long, flags)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(dn_name, dn->full_name);
> +		__entry->flags = dn->_flags;
> +	),
> +
> +	TP_printk("dn->full_name=%s, dn->_flags=%lu", 
> +		  __get_str(dn_name), __entry->flags)
> +);
> +
> +#define of_reconfig_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"}
> +
> +TRACE_EVENT(of_reconfig_notify,
> +
> +	TP_PROTO(unsigned long action, struct of_reconfig_data *ord),
> +
> +	TP_ARGS(action, ord),
> +
> +	TP_STRUCT__entry(
> +		__field(unsigned long, action)
> +		__string(dn_name, ord->dn->full_name)
> +		__string(prop_name, ord->prop ? ord->prop->name : "null")
> +		__string(oldprop_name, ord->old_prop ? ord->old_prop->name : "null")
> +	),
> +
> +	TP_fast_assign(
> +		__entry->action = action;
> +		__assign_str(dn_name, ord->dn->full_name);
> +		__assign_str(prop_name, ord->prop ? ord->prop->name : "null");
> +		__assign_str(oldprop_name, ord->old_prop ? ord->old_prop->name : "null");
> +	),
> +
> +	TP_printk("action=%s, dn->full_name=%s, prop->name=%s, old_prop->name=%s",
> +		  __print_symbolic(__entry->action, of_reconfig_action_names),
> +		  __get_str(dn_name), __get_str(prop_name), __get_str(oldprop_name))
> +);
> +
> +#endif /*	_TRACE_OF_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
>

On 04/18/2017 07:31 PM, Frank Rowand wrote:
> On 04/18/17 18:31, Michael Ellerman wrote:
>> Frank Rowand <frowand.list@gmail.com> writes:
>>
>>> On 04/17/17 17:32, Tyrel Datwyler wrote:
>>>> This patch introduces event tracepoints for tracking a device_nodes
>>>> reference cycle as well as reconfig notifications generated in response
>>>> to node/property manipulations.
>>>>
>>>> With the recent upstreaming of the refcount API several device_node
>>>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>>>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>>>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>>>> easy and quick mechanism for validating the reference counting of
>>>> device_nodes during their lifetime.
>>>>
>>>> Further, when pseries lpars are migrated to a different machine we
>>>> perform a live update of our device tree to bring it into alignment with the
>>>> configuration of the new machine. The of_reconfig_notify trace point
>>>> provides a mechanism that can be turned for debuging the device tree
>>>> modifications with out having to build a custom kernel to get at the
>>>> DEBUG code introduced by commit 00aa3720.
>>>
>>> I do not like changing individual (or small groups of) printk() style
>>> debugging information to tracepoint style.
>>
>> I'm not quite sure which printks() you're referring to.
>>
>> The only printks that are removed in this series are under #ifdef DEBUG,
>> and so are essentially not there unless you build a custom kernel.
> 
> Yes, I am talking about pr_debug(), pr_info(), pr_err(), etc.
> 
> 
>>
>> They also only cover the reconfig case, which is actually less
>> interesting than the much more common and bug-prone get/put logic.
> 
> When I was looking at the get/put issue I used pr_debug().
> 
> 
>>> As far as I know, there is no easy way to combine trace data and printk()
>>> style data to create a single chronology of events.  If some of the
>>> information needed to debug an issue is trace data and some is printk()
>>> style data then it becomes more difficult to understand the overall
>>> situation.
>>
>> If you enable CONFIG_PRINTK_TIME then you should be able to just sort
>> the trace and the printk output by the timestamp. If you're really
>> trying to correlate the two then you should probably just be using
>> trace_printk().
> 
> Except the existing debug code that uses pr_debug() does not use
> trace_printk().
> 
> And "just sort" does not apply to multi-line output like:
> 
> cpuhp/23-147   [023] ....   128.324827:
> 	of_node_put: refcount=5, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=4, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324829:
> 	of_node_put: refcount=3, dn->full_name=/cpus/PowerPC,POWER8@10
> cpuhp/23-147   [023] ....   128.324831:
> 	of_node_put: refcount=2, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439000:
> 	of_node_put: refcount=1, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439002:
> 	of_reconfig_notify: action=DETACH_NODE, dn->full_name=/cpus/PowerPC,POWER8@10,
> 			    prop->name=null, old_prop->name=null
>    drmgr-7284  [009] ....   128.439015:
> 	of_node_put: refcount=0, dn->full_name=/cpus/PowerPC,POWER8@10
>    drmgr-7284  [009] ....   128.439016:
> 	of_node_release: dn->full_name=/cpus/PowerPC,POWER8@10, dn->_flags=4
> 
> I was kinda hoping that maybe someone had already created a tool to deal
> with this issue.  But not too optimistic.

This output was actually broken into multiple lines for the commit
message. Each trace point is actually a single line in the trace buffer.
This output was pulled from the trace buffer with the following:

cat /sys/kernel/debug/trace/tracing | grep "POWER8@10"

-Tyrel

> 
> 
>> But IMO this level of detail, tracing every get/put, does not belong in
>> printk. Trace points are absolutely the right solution for this type of
>> debugging.
>>
>> cheers
>> .
>>
>

On 04/18/2017 07:49 PM, Steven Rostedt wrote:
> On Tue, 18 Apr 2017 18:42:32 -0700
> Frank Rowand <frowand.list@gmail.com> wrote:
> 
>> And of course the other issue with using tracepoints is the extra space
>> required to hold the tracepoint info.  With the pr_debug() approach, the
>> space usage can be easily removed for a production kernel via a config
>> option.
> 
> Now if you are saying you want to be able to enable debugging without
> the tracing infrastructure I would agree. As the tracing infrastructure
> is large. But I'm working on shrinking it more.

The primary consumers of OF_DYNAMIC seem to be pseries and powernv where
we are generally going to see the trace infrastructure enabled by
default in production.

-Tyrel

> 
>>
>> Tracepoints are wonderful technology, but not always the proper tool to
>> use for debug info.
> 
> But if you are going to have tracing enabled regardless, adding a few
> more tracepoints isn't going to make the difference.
> 
> -- Steve
> 
>>
>>> If Rob wants to convert printk() style data to trace data (and I can't
>>> convince him otherwise) then I will have further comments on this specific
>>> patch.
>>>

On 04/19/2017 03:13 AM, Michael Ellerman wrote:
> Oliver O'Halloran <oohall@gmail.com> writes:
> 
>> On Wed, Apr 19, 2017 at 2:46 AM, Rob Herring <robh+dt@kernel.org> wrote:
>>> On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
>>> <tyreld@linux.vnet.ibm.com> wrote:
>>>> This patch introduces event tracepoints for tracking a device_nodes
>>>> reference cycle as well as reconfig notifications generated in response
>>>> to node/property manipulations.
>>>>
>>>> With the recent upstreaming of the refcount API several device_node
>>>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>>>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>>>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>>>> easy and quick mechanism for validating the reference counting of
>>>> device_nodes during their lifetime.
>>>
>>> Not really relevant for this patch, but since you are looking at
>>> pseries and refcounting, the refcounting largely exists for pseries.
>>> It's also hard to get right as this type of fix is fairly common. It's
>>> now used for overlays, but we really probably only need to refcount
>>> the overlays or changesets as a whole, not at a node level. If you
>>> have any thoughts on how a different model of refcounting could work
>>> for pseries, I'd like to discuss it.
>>
>> One idea I've been kicking around is differentiating short and long
>> term references to a node.
> 
> I actually did this a long time ago, but balked at the size of the patch
> to do the conversion. Let me see if I can find it lying around ...

It would be interesting to revisit this, and toss around any other ideas
anyone may have.

-Tyrel

> 
> cheers
> --
> To unsubscribe from this list: send the line "unsubscribe devicetree" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

On 04/18/2017 06:31 PM, Michael Ellerman wrote:
> Frank Rowand <frowand.list@gmail.com> writes:
> 
>> On 04/17/17 17:32, Tyrel Datwyler wrote:
>>> This patch introduces event tracepoints for tracking a device_nodes
>>> reference cycle as well as reconfig notifications generated in response
>>> to node/property manipulations.
>>>
>>> With the recent upstreaming of the refcount API several device_node
>>> underflows and leaks have come to my attention in the pseries (DLPAR) dynamic
>>> logical partitioning code (ie. POWER speak for hotplugging virtual and physcial
>>> resources at runtime such as cpus or IOAs). These tracepoints provide a
>>> easy and quick mechanism for validating the reference counting of
>>> device_nodes during their lifetime.
>>>
>>> Further, when pseries lpars are migrated to a different machine we
>>> perform a live update of our device tree to bring it into alignment with the
>>> configuration of the new machine. The of_reconfig_notify trace point
>>> provides a mechanism that can be turned for debuging the device tree
>>> modifications with out having to build a custom kernel to get at the
>>> DEBUG code introduced by commit 00aa3720.
>>
>> I do not like changing individual (or small groups of) printk() style
>> debugging information to tracepoint style.
> 
> I'm not quite sure which printks() you're referring to.
> 
> The only printks that are removed in this series are under #ifdef DEBUG,
> and so are essentially not there unless you build a custom kernel.
> 
> They also only cover the reconfig case, which is actually less
> interesting than the much more common and bug-prone get/put logic.
> 
>> As far as I know, there is no easy way to combine trace data and printk()
>> style data to create a single chronology of events.  If some of the
>> information needed to debug an issue is trace data and some is printk()
>> style data then it becomes more difficult to understand the overall
>> situation.
> 
> If you enable CONFIG_PRINTK_TIME then you should be able to just sort
> the trace and the printk output by the timestamp. If you're really
> trying to correlate the two then you should probably just be using
> trace_printk().
> 
> But IMO this level of detail, tracing every get/put, does not belong in
> printk. Trace points are absolutely the right solution for this type of
> debugging.

Something else to keep in mind is that while pr_debugs could be used to
provide feedback on the reference counts and of_reconfig events they
don't in anyway tell us where they are happening in the kernel. The
trace infrastructure provides the ability to stack trace those events.
The following example provides me a lot more information about who is
doing what and where after I hot-add an ethernet adapter:

# echo stacktrace > /sys/kernel/debug/tracing/trace_options
# cat trace | grep -A6 "/pci@800000020000018"
...
           drmgr-7349  [006] d...  7138.821875: of_node_get: refcount=8,
dn->full_name=/pci@800000020000018
           drmgr-7349  [006] d...  7138.821876: <stack trace>
 => .msi_quota_for_device
 => .rtas_setup_msi_irqs
 => .arch_setup_msi_irqs
 => .__pci_enable_msix
 => .pci_enable_msix_range
--
           drmgr-7349  [006] d...  7138.821876: of_node_put: refcount=2,
dn->full_name=/pci@800000020000018/ethernet@0
           drmgr-7349  [006] d...  7138.821877: <stack trace>
 => .msi_quota_for_device
 => .rtas_setup_msi_irqs
 => .arch_setup_msi_irqs
 => .__pci_enable_msix
 => .pci_enable_msix_range
--
           drmgr-7349  [006] ....  7138.821878: of_node_put: refcount=7,
dn->full_name=/pci@800000020000018
           drmgr-7349  [006] ....  7138.821879: <stack trace>
 => .rtas_setup_msi_irqs
 => .arch_setup_msi_irqs
 => .__pci_enable_msix
 => .pci_enable_msix_range
 => .bnx2x_enable_msix
--

To get that same info as far as I know is to add a dump_stack() after
each pr_debug.

Further, filters can be set on the tracepoint event fields such that
trace data could be restricted to a particular device_node or refcount
threshold. For example:

# cd /sys/kernel/debug/tracing# cat events/of/of_node_get/format
# echo "dn_name == /pci@800000020000018" > events/of/filter

# cat trace
           drmgr-10542 [003] ....  9630.677001: of_node_put: refcount=5,
dn->full_name=/pci@800000020000018
           drmgr-10542 [003] d...  9631.677368: of_node_get: refcount=6,
dn->full_name=/pci@800000020000018
           drmgr-10542 [003] ....  9631.677389: of_node_put: refcount=5,
dn->full_name=/pci@800000020000018
           drmgr-10542 [003] ....  9631.677390: of_reconfig_notify:
action=DETACH_NODE, dn->full_name=/pci@800000020000018, prop->name=null,
old_prop->name=null
           drmgr-10542 [003] .n..  9632.025656: of_node_put: refcount=4,
dn->full_name=/pci@800000020000018
           drmgr-10542 [003] .n..  9632.025657: of_node_put: refcount=3,
dn->full_name=/pci@800000020000018

After setting the filter and doing a hot-remove of the pci device in
question the trace quickly tells me 3 references are being leaked. In
combination with the stacktrace option I can quickly correlate call
sites that take references without releasing them.

-Tyrel

> 
> cheers
> --
> To unsubscribe from this list: send the line "unsubscribe devicetree" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

On Wed, 19 Apr 2017 16:27:10 -0700
Tyrel Datwyler <turtle.in.the.kernel@gmail.com> wrote:

> # echo stacktrace > /sys/kernel/debug/tracing/trace_options
> # cat trace | grep -A6 "/pci@800000020000018"

Just to let you know that there is now stacktrace event triggers, where
you don't need to stacktrace all events, you can pick and choose. And
even filter the stack trace on specific fields of the event.

 # cd /sys/kernel/debug/tracing
 # echo "stacktrace if common_pid == $$ && reason == 3" \
   > events/tlb/tlb_flush/trigger

 # cat trace
            bash-1103  [003] ...1  1290.100133: tlb_flush: pages:-1 reason:local mm shootdown (3)
            bash-1103  [003] ...2  1290.100140: <stack trace>
 => copy_process.part.39
 => _do_fork
 => SyS_clone
 => do_syscall_64
 => return_from_SYSCALL_64

-- Steve

On 04/19/17 11:45, Tyrel Datwyler wrote:
> On 04/18/2017 07:49 PM, Steven Rostedt wrote:
>> On Tue, 18 Apr 2017 18:42:32 -0700
>> Frank Rowand <frowand.list@gmail.com> wrote:
>>
>>> And of course the other issue with using tracepoints is the extra space
>>> required to hold the tracepoint info.  With the pr_debug() approach, the
>>> space usage can be easily removed for a production kernel via a config
>>> option.
>>
>> Now if you are saying you want to be able to enable debugging without
>> the tracing infrastructure I would agree. As the tracing infrastructure
>> is large. But I'm working on shrinking it more.
> 
> The primary consumers of OF_DYNAMIC seem to be pseries and powernv where
> we are generally going to see the trace infrastructure enabled by
> default in production.

Another primary consumer will be overlays for ARM expansion boards.  Still
a work in progress.

-Frank

> 
> -Tyrel
> 
>>
>>>
>>> Tracepoints are wonderful technology, but not always the proper tool to
>>> use for debug info.
>>
>> But if you are going to have tracing enabled regardless, adding a few
>> more tracepoints isn't going to make the difference.
>>
>> -- Steve
>>
>>>
>>>> If Rob wants to convert printk() style data to trace data (and I can't
>>>> convince him otherwise) then I will have further comments on this specific
>>>> patch.
>>>>
> 
> .
>

On 04/19/17 19:33, Steven Rostedt wrote:
> On Wed, 19 Apr 2017 16:27:10 -0700
> Tyrel Datwyler <turtle.in.the.kernel@gmail.com> wrote:
> 
>> # echo stacktrace > /sys/kernel/debug/tracing/trace_options
>> # cat trace | grep -A6 "/pci@800000020000018"
> 
> Just to let you know that there is now stacktrace event triggers, where
> you don't need to stacktrace all events, you can pick and choose. And
> even filter the stack trace on specific fields of the event.
> 
>  # cd /sys/kernel/debug/tracing
>  # echo "stacktrace if common_pid == $$ && reason == 3" \
>    > events/tlb/tlb_flush/trigger
> 
>  # cat trace
>             bash-1103  [003] ...1  1290.100133: tlb_flush: pages:-1 reason:local mm shootdown (3)
>             bash-1103  [003] ...2  1290.100140: <stack trace>
>  => copy_process.part.39
>  => _do_fork
>  => SyS_clone
>  => do_syscall_64
>  => return_from_SYSCALL_64
> 
> -- Steve
> .
> 

Thanks for chiming in.

The power and flexibility of the trace tools is quite amazing
I need to make room in my schedule to catch up on what has been
added in the last several years.

-Frank

On 04/19/2017 07:33 PM, Steven Rostedt wrote:
> On Wed, 19 Apr 2017 16:27:10 -0700
> Tyrel Datwyler <turtle.in.the.kernel@gmail.com> wrote:
> 
>> # echo stacktrace > /sys/kernel/debug/tracing/trace_options
>> # cat trace | grep -A6 "/pci@800000020000018"
> 
> Just to let you know that there is now stacktrace event triggers, where
> you don't need to stacktrace all events, you can pick and choose. And
> even filter the stack trace on specific fields of the event.

This is great, and I did figure that out this afternoon. One thing I was
still trying to determine though was whether its possible to set these
triggers at boot? As far as I could tell I'm still limited to
"trace_options=stacktrace" as a kernel boot parameter to get the stack
for event tracepoints.

-Tyrel

> 
>  # cd /sys/kernel/debug/tracing
>  # echo "stacktrace if common_pid == $$ && reason == 3" \
>    > events/tlb/tlb_flush/trigger
> 
>  # cat trace
>             bash-1103  [003] ...1  1290.100133: tlb_flush: pages:-1 reason:local mm shootdown (3)
>             bash-1103  [003] ...2  1290.100140: <stack trace>
>  => copy_process.part.39
>  => _do_fork
>  => SyS_clone
>  => do_syscall_64
>  => return_from_SYSCALL_64
> 
> -- Steve
>

On 04/19/17 19:37, Frank Rowand wrote:
> On 04/19/17 11:45, Tyrel Datwyler wrote:
>> On 04/18/2017 07:49 PM, Steven Rostedt wrote:
>>> On Tue, 18 Apr 2017 18:42:32 -0700
>>> Frank Rowand <frowand.list@gmail.com> wrote:
>>>
>>>> And of course the other issue with using tracepoints is the extra space
>>>> required to hold the tracepoint info.  With the pr_debug() approach, the
>>>> space usage can be easily removed for a production kernel via a config
>>>> option.
>>>
>>> Now if you are saying you want to be able to enable debugging without
>>> the tracing infrastructure I would agree. As the tracing infrastructure
>>> is large. But I'm working on shrinking it more.
>>
>> The primary consumers of OF_DYNAMIC seem to be pseries and powernv where
>> we are generally going to see the trace infrastructure enabled by
>> default in production.
> 
> Another primary consumer will be overlays for ARM expansion boards.  Still
> a work in progress.

And dynamic configuration for the FPGA folks.


> -Frank
> 
>>
>> -Tyrel
>>
>>>
>>>>
>>>> Tracepoints are wonderful technology, but not always the proper tool to
>>>> use for debug info.
>>>
>>> But if you are going to have tracing enabled regardless, adding a few
>>> more tracepoints isn't going to make the difference.
>>>
>>> -- Steve
>>>
>>>>
>>>>> If Rob wants to convert printk() style data to trace data (and I can't
>>>>> convince him otherwise) then I will have further comments on this specific
>>>>> patch.
>>>>>
>>
>> .
>>
> 
> .
>

On Wed, 19 Apr 2017 22:24:58 -0700
Tyrel Datwyler <turtle.in.the.kernel@gmail.com> wrote:

> On 04/19/2017 07:33 PM, Steven Rostedt wrote:
> > On Wed, 19 Apr 2017 16:27:10 -0700
> > Tyrel Datwyler <turtle.in.the.kernel@gmail.com> wrote:
> >   
> >> # echo stacktrace > /sys/kernel/debug/tracing/trace_options
> >> # cat trace | grep -A6 "/pci@800000020000018"  
> > 
> > Just to let you know that there is now stacktrace event triggers, where
> > you don't need to stacktrace all events, you can pick and choose. And
> > even filter the stack trace on specific fields of the event.  
> 
> This is great, and I did figure that out this afternoon. One thing I was
> still trying to determine though was whether its possible to set these
> triggers at boot? As far as I could tell I'm still limited to
> "trace_options=stacktrace" as a kernel boot parameter to get the stack
> for event tracepoints.

No not yet. But I'll add that to the todo list.

Thanks,

-- Steve