LinuxLists.cc - [PATCH] of: introduce event tracepoints for dynamic device

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

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 <[email protected]>
> ---
> 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>
>

2017-04-18 16:47:20

by Rob Herring

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
<[email protected]> 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 <[email protected]>
> ---
> 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
>

2017-04-19 00:07:48

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

2017-04-19 01:31:33

by Michael Ellerman

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

Frank Rowand <[email protected]> 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

2017-04-19 01:43:01

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

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 <[email protected]>
>> ---
>> 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 >
>
>

2017-04-19 02:30:55

by Oliver O'Halloran

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On Wed, Apr 19, 2017 at 2:46 AM, Rob Herring <[email protected]> wrote:
> On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
> <[email protected]> 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

2017-04-19 02:31:50

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/18/17 18:31, Michael Ellerman wrote:
> Frank Rowand <[email protected]> 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
> .
>

2017-04-19 02:47:10

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On Tue, 18 Apr 2017 17:07:17 -0700
Frank Rowand <[email protected]> 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.
>

2017-04-19 02:49:59

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On Tue, 18 Apr 2017 18:42:32 -0700
Frank Rowand <[email protected]> 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.
> >

2017-04-19 03:12:40

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/18/17 19:46, Steven Rostedt wrote:
> On Tue, 18 Apr 2017 17:07:17 -0700
> Frank Rowand <[email protected]> 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.
>>
> .
>

2017-04-19 10:13:43

by Michael Ellerman

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

Oliver O'Halloran <[email protected]> writes:

> On Wed, Apr 19, 2017 at 2:46 AM, Rob Herring <[email protected]> wrote:
>> On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
>> <[email protected]> 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

2017-04-19 17:44:47

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

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 <[email protected]>
> ---
> 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>
>

2017-04-19 18:34:09

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/18/2017 07:31 PM, Frank Rowand wrote:
> On 04/18/17 18:31, Michael Ellerman wrote:
>> Frank Rowand <[email protected]> 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
>> .
>>
>

2017-04-19 18:45:18

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/18/2017 07:49 PM, Steven Rostedt wrote:
> On Tue, 18 Apr 2017 18:42:32 -0700
> Frank Rowand <[email protected]> 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.
>>>

2017-04-19 21:13:58

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/19/2017 03:13 AM, Michael Ellerman wrote:
> Oliver O'Halloran <[email protected]> writes:
>
>> On Wed, Apr 19, 2017 at 2:46 AM, Rob Herring <[email protected]> wrote:
>>> On Mon, Apr 17, 2017 at 7:32 PM, Tyrel Datwyler
>>> <[email protected]> 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 [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>

2017-04-19 23:27:19

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/18/2017 06:31 PM, Michael Ellerman wrote:
> Frank Rowand <[email protected]> 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 [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>

2017-04-20 02:33:48

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On Wed, 19 Apr 2017 16:27:10 -0700
Tyrel Datwyler <[email protected]> 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

2017-04-20 02:38:11

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

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 <[email protected]> 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.
>>>>
>
> .
>

2017-04-20 04:43:51

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/19/17 16:27, Tyrel Datwyler wrote:
> On 04/18/2017 06:31 PM, Michael Ellerman wrote:
>> Frank Rowand <[email protected]> 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

Yes, that is critical information. When there are refcount issues, the
root cause is at varying levels back in the call stack.

> 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

Nice! It is great to have function names in the call stack.

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

Here is a patch that I have used. It is not as user friendly in terms
of human readable stack traces (though a very small user space program
should be able to fix that). The patch is cut and pasted into this
email, so probably white space damaged.

Instead of dumping the stack, each line in the "report" contains
the top six addresses in the call stack. If interesting, they
can be post-processed (as I will show in some examples below).

---
drivers/of/dynamic.c | 29 +++++++++++++++++++++++++++++
1 file changed, 29 insertions(+)

Index: b/drivers/of/dynamic.c
===================================================================
--- a/drivers/of/dynamic.c
+++ b/drivers/of/dynamic.c
@@ -13,6 +13,7 @@
#include <linux/slab.h>
#include <linux/string.h>
#include <linux/proc_fs.h>
+#include <linux/ftrace.h>

#include "of_private.h"

@@ -27,6 +28,20 @@ struct device_node *of_node_get(struct d
{
if (node)
kobject_get(&node->kobj);
+
+ if (node) {
+ int k;
+ int refcount = refcount_read(&node->kobj.kref.refcount);
+ pr_err("XXX get 0x%p %3d [0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx] ",
+ node, refcount,
+ CALLER_ADDR5, CALLER_ADDR4, CALLER_ADDR3,
+ CALLER_ADDR2, CALLER_ADDR1, CALLER_ADDR0);
+ // refcount = (refcount > 20) ? 20 : refcount; /* clamp max */
+ for (k = 0; k < refcount; k++)
+ pr_cont("+");
+ pr_cont(" %s\n", of_node_full_name(node));
+ }
+
return node;
}
EXPORT_SYMBOL(of_node_get);
@@ -38,8 +53,22 @@ EXPORT_SYMBOL(of_node_get);
*/
void of_node_put(struct device_node *node)
{
+ if (node) {
+ int k;
+ int refcount = refcount_read(&node->kobj.kref.refcount);
+ pr_err("XXX put 0x%p %3d [0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx] ",
+ node, refcount,
+ CALLER_ADDR5, CALLER_ADDR4, CALLER_ADDR3,
+ CALLER_ADDR2, CALLER_ADDR1, CALLER_ADDR0);
+ // refcount = (refcount > 20) ? 20 : refcount; /* clamp max */
+ for (k = 0; k < refcount; k++)
+ pr_cont("-");
+ pr_cont(" %s\n", of_node_full_name(node));
+ }
+
if (node)
kobject_put(&node->kobj);
+
}
EXPORT_SYMBOL(of_node_put);

I have used this mostly in the context of boot time, so there is a lot
of output. My notes on configuration needed for my ARM boards are:

FIXME: Currently using pr_err() so I don't need to set loglevel on boot.

So obviously not a user friendly tool!!!
The process is:
- apply patch
- configure, build, boot kernel
- analyze data
- remove patch

LOG_BUF_SHIFT (was 17)
General Setup ->
[select 21] Kernel log buffer size (16 => 64KB, 17 => 128KB)

Device Drivers ->
Device Tree and Open Firmware support ->
Device Tree overlays

Want CONFIG_FRAME_POINTER so that CALLER_ADDR* will work.
To be able to enable CONFIG_FRAME_POINTER, need to disable CONFIG_ARM_UNWIND.

Kernel hacking ->
[unselect] Enable stack unwinding support (EXPERIMENTAL)
CONFIG_FRAME_POINTER will then be selected automatically

The output looks like:

[ 0.231430] OF: XXX get 0xeefeb5dc 2 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e678 0xc080de7c] ++ /smp2p-adsp/slave-kernel
[ 0.231457] OF: XXX get 0xeefeb5dc 3 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814188] +++ /smp2p-adsp/slave-kernel
[ 0.231495] OF: XXX get 0xeefeb5dc 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814258] ++++ /smp2p-adsp/slave-kernel
[ 0.231537] OF: XXX get 0xeefeb244 4 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] ++++ /smp2p-adsp
[ 0.231568] OF: XXX put 0xeefeb5dc 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ---- /smp2p-adsp/slave-kernel
[ 0.231610] OF: XXX get 0xeefe759c 23 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] +++++++++++++++++++++++ /
[ 0.231702] OF: XXX put 0xeefeb244 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ---- /smp2p-adsp
[ 0.231744] OF: XXX put 0xeefe759c 23 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ----------------------- /
[ 0.231881] OF: XXX get 0xeefecb2c 22 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e86c 0xc080e678 0xc080de7c] ++++++++++++++++++++++ /soc/interrupt-controller@f9000000
[ 0.231972] OF: XXX put 0xeefecb2c 22 [0xc080fd94 0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e61c] ---------------------- /soc/interrupt-controller@f9000000
[ 0.232101] OF: XXX get 0xeefeb5dc 4 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e678 0xc080de7c] ++++ /smp2p-adsp/slave-kernel
[ 0.232134] OF: XXX put 0xeefeb5dc 4 [0xc080fd94 0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e61c] ---- /smp2p-adsp/slave-kernel
[ 0.232178] OF: XXX get 0xeefeb5dc 4 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e678 0xc080de7c] ++++ /smp2p-adsp/slave-kernel
[ 0.232211] OF: XXX get 0xeefeb5dc 5 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814188] +++++ /smp2p-adsp/slave-kernel
[ 0.232257] OF: XXX get 0xeefeb5dc 6 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814258] ++++++ /smp2p-adsp/slave-kernel
[ 0.232308] OF: XXX get 0xeefeb244 4 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] ++++ /smp2p-adsp
[ 0.232339] OF: XXX put 0xeefeb5dc 6 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ------ /smp2p-adsp/slave-kernel
[ 0.232390] OF: XXX get 0xeefe759c 23 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] +++++++++++++++++++++++ /
[ 0.232482] OF: XXX put 0xeefeb244 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ---- /smp2p-adsp

But I normally strip off the timestamp, and grep for the "OF: XXX ",
which gets me only the get and put info. It is also easy to grep
for a single node of interest.

The data fields are:
get or put
the struct device_node address
refcount
a 6 caller deep call stack
for get, one '+' per refcount or for put, one '-' per refcount
the full node name

The refcount for get is the post get value, for put is the pre put value,
so they are easy to match up for human scanning. The length of the "++++"
and "----" patterns on the end are also intended for easy human scanning.

Here are two actual refcount issues for the root node on my 4.11-rc1:

OF: XXX get 0xeefe759c 2 [0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813070 0xc080ccc8] ++ /
OF: XXX put 0xeefe759c 2 [0xc031aa28 0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813014] -- /
OF: XXX get 0xeefe759c 2 [0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813070 0xc080ccc8] ++ /
OF: XXX put 0xeefe759c 2 [0xc031aa40 0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813014] -- /
OF: XXX get 0xeefe759c 22 [0xc0308518 0xc09330e0 0xc0d00e3c 0xc03017d0 0xc0d3a1fc 0xc080d948] ++++++++++++++++++++++ /
OF: XXX put 0xeefe759c 22 [0xc0308518 0xc09330e0 0xc0d00e3c 0xc03017d0 0xc0d3a1fc 0xc080d8c8] ---------------------- /
OF: XXX get 0xeefe759c 22 [0xc0d00e3c 0xc03017d0 0xc0d3a234 0xc0810684 0xc081061c 0xc080d928] ++++++++++++++++++++++ /
OF: XXX get 0xeefe759c 23 [0xc08103c4 0xc0810024 0xc080fd84 0xc08137b4 0xc0812c88 0xc080ccc8] +++++++++++++++++++++++ /
OF: XXX put 0xeefe759c 23 [0xc08105d8 0xc08103c4 0xc0810024 0xc080fd84 0xc08137b4 0xc0812cb4] ----------------------- /

The call stack could easily be post-processed, for example using addr2line.
Here is the call stack for when the refcount incremented to 23 from 22 (or
more accurately, to 22 from 21):

0xc0d00e3c Line 857 of "init/main.c"
0xc03017d0 Line 792 of "init/main.c"
0xc0d3a234 Line 528 of "drivers/of/platform.c"
0xc0810684 Line 503 of "drivers/of/platform.c"
0xc081061c Line 267 of "include/linux/of.h"
0xc080d928 Line 815 of "drivers/of/base.c"

Which ends up being this code:

of_platform_default_populate_init()
of_platform_default_populate()
of_platform_populate()
[[ of_find_node_by_path("/") ]]
[[ of_find_node_opts_by_path(path, NULL) ]]
of_node_get(of_root)

Note that some functions can be left out of the ARM call stack, with
a return going back more than one level. The functions in the call
list above that are enclosed in '[[' and ']]' were found by source
inspection in those cases.

It looks like a put is missing, but about 250 get/put pairs later,
of_platform_populate() does the required put on node "/".

Then quite a bit later, after lots of balanced gets and puts, there is an
initcall that does a get on the root without a corresponding put.

The jump from refcount 2 to refcount 22 is an interesting case, insofar as it
is not the result of of_node_get(). It is instead inside a series of calls to
kobject_add():

kernel_init()
kernel_init_freeable()
do_basic_setup()
driver_init()
of_core_init()
for_each_of_allnodes(np)
__of_attach_node_sysfs(np)
kobject_add()

Filtering and reformatting is "easily done" with grep and other
normal unix tools.

For example, a simple stream of command line tools can show a
streamlined report of the refcounts of a single node (in this
case the root node), which can easily be scanned for interesting
events:

[ 0.199569] 2 ++ /
[ 0.199629] 2 -- /
[ 0.199826] 2 ++ /
[ 0.199886] 2 -- /
[ 0.212549] 22 ++++++++++++++++++++++ /
[ 0.212855] 22 ---------------------- /
[ 0.213087] 22 ++++++++++++++++++++++ /
[ 0.213700] 23 +++++++++++++++++++++++ /
[ 0.213797] 23 ----------------------- /
[ 0.213973] 23 +++++++++++++++++++++++ /

... hundreds of boring put/get pairs

[ 0.458737] 23 ----------------------- /
[ 0.458909] 23 +++++++++++++++++++++++ /
[ 0.459035] 23 ----------------------- /
[ 0.459305] 22 ---------------------- /
[ 0.470255] 22 ++++++++++++++++++++++ /

... hundreds of boring put/get pairs

[ 93.110548] 22 ++++++++++++++++++++++ /
[ 93.140046] 22 ---------------------- /
[ 93.264639] 22 ++++++++++++++++++++++ /
[ 93.389530] 23 +++++++++++++++++++++++ /
[ 93.414269] 23 ----------------------- /

You might have noticed that the call trace is not interesting for
most of the gets and puts. There are over 350 get/put pairs for
the root node in the boot that I collected the above examples on,
but only a few instances where the trace matters. Thus leaving
the call stack in a compact format until needed is a feature.

I will be the first to admit that the tool is not polished and not
easy to use, though it is easily extended with post-processing.

I wrote the patch as a proof of concept a while ago and have not
fleshed it out. In fact, calling it a "tool" is overstating what
it is.

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

Thanks for sharing that. It is nice seeing your results.

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

2017-04-20 04:48:25

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/19/17 19:33, Steven Rostedt wrote:
> On Wed, 19 Apr 2017 16:27:10 -0700
> Tyrel Datwyler <[email protected]> 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

2017-04-20 05:13:41

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/19/17 21:43, Frank Rowand wrote:
> On 04/19/17 16:27, Tyrel Datwyler wrote:
>> On 04/18/2017 06:31 PM, Michael Ellerman wrote:

< snip >

>>
>> To get that same info as far as I know is to add a dump_stack() after
>> each pr_debug.
>
> Here is a patch that I have used. It is not as user friendly in terms
> of human readable stack traces (though a very small user space program
> should be able to fix that). The patch is cut and pasted into this
> email, so probably white space damaged.

< snip >

> +
> + if (node) {
> + int k;
> + int refcount = refcount_read(&node->kobj.kref.refcount);
> + pr_err("XXX get 0x%p %3d [0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx] ",
> + node, refcount,

If this was a real patch, meant for people other than myself, the
pr_err() would instead be pr_debug().

-Frank

< snip >

2017-04-20 05:25:04

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/19/2017 07:33 PM, Steven Rostedt wrote:
> On Wed, 19 Apr 2017 16:27:10 -0700
> Tyrel Datwyler <[email protected]> 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
>

2017-04-20 10:45:05

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

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 <[email protected]> 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.
>>>>>
>>
>> .
>>
>
> .
>

2017-04-20 13:37:14

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On Wed, 19 Apr 2017 22:24:58 -0700
Tyrel Datwyler <[email protected]> wrote:

> On 04/19/2017 07:33 PM, Steven Rostedt wrote:
> > On Wed, 19 Apr 2017 16:27:10 -0700
> > Tyrel Datwyler <[email protected]> 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

2017-04-20 16:52:01

[permalink] [raw]

Subject: Re: [PATCH] of: introduce event tracepoints for dynamic device_node lifecyle

On 04/19/2017 09:43 PM, Frank Rowand wrote:

<snip>

>> 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
>
> Yes, that is critical information. When there are refcount issues, the
> root cause is at varying levels back in the call stack.
>
>
>> 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
>
> Nice! It is great to have function names in the call stack.

Agreed.

<snip>

>> To get that same info as far as I know is to add a dump_stack() after
>> each pr_debug.
>
> Here is a patch that I have used. It is not as user friendly in terms
> of human readable stack traces (though a very small user space program
> should be able to fix that). The patch is cut and pasted into this
> email, so probably white space damaged.
>
> Instead of dumping the stack, each line in the "report" contains
> the top six addresses in the call stack. If interesting, they
> can be post-processed (as I will show in some examples below).

Very cool. I wasn't familiar with the CALLER_ADDR* defines. Thanks for
sharing.

>
> ---
> drivers/of/dynamic.c | 29 +++++++++++++++++++++++++++++
> 1 file changed, 29 insertions(+)
>
> Index: b/drivers/of/dynamic.c
> ===================================================================
> --- a/drivers/of/dynamic.c
> +++ b/drivers/of/dynamic.c
> @@ -13,6 +13,7 @@
> #include <linux/slab.h>
> #include <linux/string.h>
> #include <linux/proc_fs.h>
> +#include <linux/ftrace.h>
>
> #include "of_private.h"
>
> @@ -27,6 +28,20 @@ struct device_node *of_node_get(struct d
> {
> if (node)
> kobject_get(&node->kobj);
> +
> + if (node) {
> + int k;
> + int refcount = refcount_read(&node->kobj.kref.refcount);
> + pr_err("XXX get 0x%p %3d [0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx] ",
> + node, refcount,
> + CALLER_ADDR5, CALLER_ADDR4, CALLER_ADDR3,
> + CALLER_ADDR2, CALLER_ADDR1, CALLER_ADDR0);
> + // refcount = (refcount > 20) ? 20 : refcount; /* clamp max */
> + for (k = 0; k < refcount; k++)
> + pr_cont("+");
> + pr_cont(" %s\n", of_node_full_name(node));
> + }
> +
> return node;
> }
> EXPORT_SYMBOL(of_node_get);
> @@ -38,8 +53,22 @@ EXPORT_SYMBOL(of_node_get);
> */
> void of_node_put(struct device_node *node)
> {
> + if (node) {
> + int k;
> + int refcount = refcount_read(&node->kobj.kref.refcount);
> + pr_err("XXX put 0x%p %3d [0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx 0x%08lx] ",
> + node, refcount,
> + CALLER_ADDR5, CALLER_ADDR4, CALLER_ADDR3,
> + CALLER_ADDR2, CALLER_ADDR1, CALLER_ADDR0);
> + // refcount = (refcount > 20) ? 20 : refcount; /* clamp max */
> + for (k = 0; k < refcount; k++)
> + pr_cont("-");
> + pr_cont(" %s\n", of_node_full_name(node));
> + }
> +
> if (node)
> kobject_put(&node->kobj);
> +
> }
> EXPORT_SYMBOL(of_node_put);
>
>
> I have used this mostly in the context of boot time, so there is a lot
> of output. My notes on configuration needed for my ARM boards are:
>
> FIXME: Currently using pr_err() so I don't need to set loglevel on boot.
>
> So obviously not a user friendly tool!!!
> The process is:
> - apply patch
> - configure, build, boot kernel
> - analyze data
> - remove patch
>
> LOG_BUF_SHIFT (was 17)
> General Setup ->
> [select 21] Kernel log buffer size (16 => 64KB, 17 => 128KB)
>
>
> Device Drivers ->
> Device Tree and Open Firmware support ->
> Device Tree overlays
>
>
> Want CONFIG_FRAME_POINTER so that CALLER_ADDR* will work.
> To be able to enable CONFIG_FRAME_POINTER, need to disable CONFIG_ARM_UNWIND.
>
> Kernel hacking ->
> [unselect] Enable stack unwinding support (EXPERIMENTAL)
> CONFIG_FRAME_POINTER will then be selected automatically
>
>
> The output looks like:
>
> [ 0.231430] OF: XXX get 0xeefeb5dc 2 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e678 0xc080de7c] ++ /smp2p-adsp/slave-kernel
> [ 0.231457] OF: XXX get 0xeefeb5dc 3 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814188] +++ /smp2p-adsp/slave-kernel
> [ 0.231495] OF: XXX get 0xeefeb5dc 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814258] ++++ /smp2p-adsp/slave-kernel
> [ 0.231537] OF: XXX get 0xeefeb244 4 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] ++++ /smp2p-adsp
> [ 0.231568] OF: XXX put 0xeefeb5dc 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ---- /smp2p-adsp/slave-kernel
> [ 0.231610] OF: XXX get 0xeefe759c 23 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] +++++++++++++++++++++++ /
> [ 0.231702] OF: XXX put 0xeefeb244 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ---- /smp2p-adsp
> [ 0.231744] OF: XXX put 0xeefe759c 23 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ----------------------- /
> [ 0.231881] OF: XXX get 0xeefecb2c 22 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e86c 0xc080e678 0xc080de7c] ++++++++++++++++++++++ /soc/interrupt-controller@f9000000
> [ 0.231972] OF: XXX put 0xeefecb2c 22 [0xc080fd94 0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e61c] ---------------------- /soc/interrupt-controller@f9000000
> [ 0.232101] OF: XXX get 0xeefeb5dc 4 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e678 0xc080de7c] ++++ /smp2p-adsp/slave-kernel
> [ 0.232134] OF: XXX put 0xeefeb5dc 4 [0xc080fd94 0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e61c] ---- /smp2p-adsp/slave-kernel
> [ 0.232178] OF: XXX get 0xeefeb5dc 4 [0xc0814c58 0xc08148b0 0xc080e970 0xc080e894 0xc080e678 0xc080de7c] ++++ /smp2p-adsp/slave-kernel
> [ 0.232211] OF: XXX get 0xeefeb5dc 5 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814188] +++++ /smp2p-adsp/slave-kernel
> [ 0.232257] OF: XXX get 0xeefeb5dc 6 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814258] ++++++ /smp2p-adsp/slave-kernel
> [ 0.232308] OF: XXX get 0xeefeb244 4 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] ++++ /smp2p-adsp
> [ 0.232339] OF: XXX put 0xeefeb5dc 6 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ------ /smp2p-adsp/slave-kernel
> [ 0.232390] OF: XXX get 0xeefe759c 23 [0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814278 0xc080ccc8] +++++++++++++++++++++++ /
> [ 0.232482] OF: XXX put 0xeefeb244 4 [0xc08103c4 0xc0810024 0xc080fd94 0xc0814c58 0xc08149a8 0xc0814284] ---- /smp2p-adsp
>
>
>
> But I normally strip off the timestamp, and grep for the "OF: XXX ",
> which gets me only the get and put info. It is also easy to grep
> for a single node of interest.
>
> The data fields are:
> get or put
> the struct device_node address
> refcount
> a 6 caller deep call stack
> for get, one '+' per refcount or for put, one '-' per refcount
> the full node name
>
> The refcount for get is the post get value, for put is the pre put value,
> so they are easy to match up for human scanning. The length of the "++++"
> and "----" patterns on the end are also intended for easy human scanning.
>
> Here are two actual refcount issues for the root node on my 4.11-rc1:
>
> OF: XXX get 0xeefe759c 2 [0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813070 0xc080ccc8] ++ /
> OF: XXX put 0xeefe759c 2 [0xc031aa28 0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813014] -- /
> OF: XXX get 0xeefe759c 2 [0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813070 0xc080ccc8] ++ /
> OF: XXX put 0xeefe759c 2 [0xc031aa40 0xc08138bc 0xc08137fc 0xc08136e4 0xc08136b4 0xc0813014] -- /
> OF: XXX get 0xeefe759c 22 [0xc0308518 0xc09330e0 0xc0d00e3c 0xc03017d0 0xc0d3a1fc 0xc080d948] ++++++++++++++++++++++ /
> OF: XXX put 0xeefe759c 22 [0xc0308518 0xc09330e0 0xc0d00e3c 0xc03017d0 0xc0d3a1fc 0xc080d8c8] ---------------------- /
> OF: XXX get 0xeefe759c 22 [0xc0d00e3c 0xc03017d0 0xc0d3a234 0xc0810684 0xc081061c 0xc080d928] ++++++++++++++++++++++ /
> OF: XXX get 0xeefe759c 23 [0xc08103c4 0xc0810024 0xc080fd84 0xc08137b4 0xc0812c88 0xc080ccc8] +++++++++++++++++++++++ /
> OF: XXX put 0xeefe759c 23 [0xc08105d8 0xc08103c4 0xc0810024 0xc080fd84 0xc08137b4 0xc0812cb4] ----------------------- /
>
> The call stack could easily be post-processed, for example using addr2line.
> Here is the call stack for when the refcount incremented to 23 from 22 (or
> more accurately, to 22 from 21):
>
> 0xc0d00e3c Line 857 of "init/main.c"
> 0xc03017d0 Line 792 of "init/main.c"
> 0xc0d3a234 Line 528 of "drivers/of/platform.c"
> 0xc0810684 Line 503 of "drivers/of/platform.c"
> 0xc081061c Line 267 of "include/linux/of.h"
> 0xc080d928 Line 815 of "drivers/of/base.c"
>
> Which ends up being this code:
>
> of_platform_default_populate_init()
> of_platform_default_populate()
> of_platform_populate()
> [[ of_find_node_by_path("/") ]]
> [[ of_find_node_opts_by_path(path, NULL) ]]
> of_node_get(of_root)
>
> Note that some functions can be left out of the ARM call stack, with
> a return going back more than one level. The functions in the call
> list above that are enclosed in '[[' and ']]' were found by source
> inspection in those cases.

The same thing is encountered in ppc64 stack traces. I assume it is
generally inlining of small functions, but I've never actually verified
that theory. Probably should take the time to investigate, or just ask
someone.

>
> It looks like a put is missing, but about 250 get/put pairs later,
> of_platform_populate() does the required put on node "/".
>
> Then quite a bit later, after lots of balanced gets and puts, there is an
> initcall that does a get on the root without a corresponding put.
>
>
> The jump from refcount 2 to refcount 22 is an interesting case, insofar as it
> is not the result of of_node_get(). It is instead inside a series of calls to
> kobject_add():

Took me a hot minute to track this one down when I first encountered the
extreme reference count jump on the root node with no associated
of_node_gets. Luckily, the other nodes with children sent me looking in
the right direction.

>
> kernel_init()
> kernel_init_freeable()
> do_basic_setup()
> driver_init()
> of_core_init()
> for_each_of_allnodes(np)
> __of_attach_node_sysfs(np)
> kobject_add()
>
>
> Filtering and reformatting is "easily done" with grep and other
> normal unix tools.
>
> For example, a simple stream of command line tools can show a
> streamlined report of the refcounts of a single node (in this
> case the root node), which can easily be scanned for interesting
> events:
>
> [ 0.199569] 2 ++ /
> [ 0.199629] 2 -- /
> [ 0.199826] 2 ++ /
> [ 0.199886] 2 -- /
> [ 0.212549] 22 ++++++++++++++++++++++ /
> [ 0.212855] 22 ---------------------- /
> [ 0.213087] 22 ++++++++++++++++++++++ /
> [ 0.213700] 23 +++++++++++++++++++++++ /
> [ 0.213797] 23 ----------------------- /
> [ 0.213973] 23 +++++++++++++++++++++++ /
>
> ... hundreds of boring put/get pairs
>
> [ 0.458737] 23 ----------------------- /
> [ 0.458909] 23 +++++++++++++++++++++++ /
> [ 0.459035] 23 ----------------------- /
> [ 0.459305] 22 ---------------------- /
> [ 0.470255] 22 ++++++++++++++++++++++ /
>
> ... hundreds of boring put/get pairs
>
> [ 93.110548] 22 ++++++++++++++++++++++ /
> [ 93.140046] 22 ---------------------- /
> [ 93.264639] 22 ++++++++++++++++++++++ /
> [ 93.389530] 23 +++++++++++++++++++++++ /
> [ 93.414269] 23 ----------------------- /
>
>
> You might have noticed that the call trace is not interesting for
> most of the gets and puts. There are over 350 get/put pairs for
> the root node in the boot that I collected the above examples on,
> but only a few instances where the trace matters. Thus leaving
> the call stack in a compact format until needed is a feature.
>
> I will be the first to admit that the tool is not polished and not
> easy to use, though it is easily extended with post-processing.
>
> I wrote the patch as a proof of concept a while ago and have not
> fleshed it out. In fact, calling it a "tool" is overstating what
> it is.
>
>
>> 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.
>
> Thanks for sharing that. It is nice seeing your results.

Ditto.

-Tyrel

2017-04-20 19:35:32