[PATCH 0/3] kobject tracepoints

[PATCH 0/3] kobject tracepoints

[Shuah Khan]

Add kobject trace points to track kobject operations: init, add, set_name,
init_and_add, create_and_add, move, rename, get, put, cleanup, and del.

Kobject trace points can aid in debugging, generating status and graphs
on kobjects in the kernel and their hierarchy.

This patch series adds kobject tracepoints and adds calls to tracepoints
from kobject init, add, set_name, init_and_add, create_and_add, move,
rename, get, put, cleanup, and del operations.

A suggestion to provide more visibility into kboject lifetimes came out of
a discussion at my Embedded data structure lifetime talk at LinuxCon NA in
Toronto. As I thought about on how to provide visibility, I decided adding
traces provides a boot and run-time facility to trace kobject operations
without needing compile special kernels and also without impacting run-time
unless trace is enabled. Hence, this resulting patch series.

Example traces:

<...>-13632 [003] d... 11296.965114: kobject_get: KOBJECT: 1:0:0:0 (f
fff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
           <...>-13632 [003] d... 11296.965167: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
           <...>-13632 [003] d... 11296.965218: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
           <...>-13632 [003] d... 11296.965269: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 22
          <idle>-0     [006] ..s. 11296.965378: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
          <idle>-0     [006] .Ns. 11296.965542: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
     ksoftirqd/6-46    [006] ..s. 11296.965633: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
     ksoftirqd/6-46    [006] ..s. 11296.965703: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 18

Shuah Khan (3):
  kobject: add kobject trace points
  kobject: add kobject trace prototypes
  kobject: Add calls to kobject trace points

 include/trace/events/kobject.h | 259 +++++++++++++++++++++++++++++++++++++++++
 lib/Makefile                   |   2 +-
 lib/kobject.c                  |  22 ++++
 lib/kobject_traces.c           |  32 +++++
 4 files changed, 314 insertions(+), 1 deletion(-)
 create mode 100644 include/trace/events/kobject.h
 create mode 100644 lib/kobject_traces.c

-- 
2.7.4

[PATCH 1/3] kobject: add kobject trace points

[Shuah Khan]

Add kobject trace points to track kobject operations: init, add, set_name,
init_and_add, create_and_add, move, rename, get, put, cleanup, and del.

Kobject trace points can aid in debugging, generating status and graphs
on kobjects in the kernel and their hierarchy.

Signed-off-by: Shuah Khan <shuahkh@osg.samsung.com>
---
 include/trace/events/kobject.h | 259 +++++++++++++++++++++++++++++++++++++++++
 1 file changed, 259 insertions(+)
 create mode 100644 include/trace/events/kobject.h

diff --git a/include/trace/events/kobject.h b/include/trace/events/kobject.h
new file mode 100644
index 0000000..6a29665
--- /dev/null
+++ b/include/trace/events/kobject.h
@@ -0,0 +1,259 @@
+/*
+ * kobject trace points
+ *
+ * Copyright (C) 2016 Shuah Khan <shuahkh@osg.samsung.com>
+ *
+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM kobject
+
+#if !defined(_TRACE_KOBJECT_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_KOBJECT_H
+
+#include <linux/tracepoint.h>
+#include <linux/kobject.h>
+
+/* kobject_init_class */
+DECLARE_EVENT_CLASS(kobject_init_class,
+
+	TP_PROTO(struct kobject *kobj),
+
+	TP_ARGS(kobj),
+
+	TP_STRUCT__entry(
+		__field(void *, kobj)
+		__field(int, state_initialized)
+	),
+
+	TP_fast_assign(
+		__entry->kobj = kobj;
+		__entry->state_initialized = kobj->state_initialized;
+	),
+
+	TP_printk("KOBJECT: %p state=%d",
+		  __entry->kobj,
+		  __entry->state_initialized
+	));
+
+/**
+ * kobject_init	- called from kobject_init() when kobject is initialized
+ * @kobj:	- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_init_class, kobject_init,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/* kobject_class */
+DECLARE_EVENT_CLASS(kobject_class,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj),
+
+	TP_STRUCT__entry(
+		__field(void *, kobj)
+		__string(name, kobject_name(kobj))
+		__field(int, state_initialized)
+		__field(void *, parent)
+		__string(pname, kobj->parent ? kobject_name(kobj->parent) : "")
+		__field(int, count)
+	),
+
+	TP_fast_assign(
+		__entry->kobj = kobj;
+		__assign_str(name, kobject_name(kobj));
+		__entry->state_initialized = kobj->state_initialized;
+		__entry->parent = kobj->parent;
+		__assign_str(pname,
+			     kobj->parent ? kobject_name(kobj->parent) : "");
+		__entry->count = atomic_read(&kobj->kref.refcount);
+	),
+
+	TP_printk("KOBJECT: %s (%p) state=%d parent= %s (%p) counter= %d",
+		  __get_str(name),
+		  __entry->kobj,
+		  __entry->state_initialized,
+		  __get_str(pname),
+		  __entry->parent,
+		  __entry->count
+	));
+
+/**
+ * kobject_add	- called from kobject_add() when kobject is added
+ * @kobj:	- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_add,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/**
+ * kobject_init_and_add	- called from kobject_init_and_add()
+ * @kobj:		- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_init_and_add,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/**
+ * kobject_create_and_add	- called from kobject_create_and_add()
+ * @kobj:			- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_create_and_add,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/**
+ * kobject_set_name	- called from kobject_set_name()
+ * @kobj:		- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_set_name,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/**
+ * kobject_del	- called from kobject_del()
+ * @kobj:	- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_del,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/**
+ * kobject_cleanup	- called from kobject_cleanup()
+ * @kobj:		- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_cleanup,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+/**
+ * kobject_get	- called from kobject_get()
+ * @kobj:	- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_class, kobject_get,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj));
+
+/**
+ * kobject_put	- called from kobject_put()
+ * @kobj:	- pointer to struct kobject
+ *
+ * Trace is called before kref_put() to avoid use-after-free on kobj, in case
+ * kobject is released. Decrement the counter before printing the value.
+ */
+TRACE_EVENT(kobject_put,
+
+	TP_PROTO(struct kobject *kobj),
+	TP_ARGS(kobj),
+
+	TP_STRUCT__entry(
+		__field(void *, kobj)
+		__string(name, kobject_name(kobj))
+		__field(int, state_initialized)
+		__field(void *, parent)
+		__string(pname, kobj->parent ? kobject_name(kobj->parent) : "")
+		__field(int, count)
+	),
+
+	TP_fast_assign(
+		__entry->kobj = kobj;
+		__assign_str(name, kobject_name(kobj));
+		__entry->state_initialized = kobj->state_initialized;
+		__entry->parent = kobj->parent;
+		__assign_str(pname,
+			     kobj->parent ? kobject_name(kobj->parent) : "");
+		__entry->count = atomic_read(&kobj->kref.refcount) - 1;
+	),
+
+	TP_printk("KOBJECT: %s (%p) state=%d parent= %s (%p) counter= %d",
+		  __get_str(name),
+		  __entry->kobj,
+		  __entry->state_initialized,
+		  __get_str(pname),
+		  __entry->parent,
+		  __entry->count
+	));
+
+/* kobject_move_class */
+DECLARE_EVENT_CLASS(kobject_move_class,
+
+	TP_PROTO(struct kobject *kobj, struct kobject *old_parent),
+	TP_ARGS(kobj, old_parent),
+
+	TP_STRUCT__entry(
+		__field(void *, kobj)
+		__string(name, kobject_name(kobj))
+		__field(int, state_initialized)
+		__field(void *, parent)
+		__string(pname, kobj->parent ? kobject_name(kobj->parent) : "")
+	),
+
+	TP_fast_assign(
+		__entry->kobj = kobj;
+		__assign_str(name, kobject_name(kobj));
+		__entry->state_initialized = kobj->state_initialized;
+		__entry->parent = kobj->parent;
+		__assign_str(pname,
+			     kobj->parent ? kobject_name(kobj->parent) : "");
+	),
+
+	TP_printk("KOBJECT: %s (%p) state=%d parent= %s (%p)",
+		  __get_str(name),
+		  __entry->kobj,
+		  __entry->state_initialized,
+		  __get_str(pname),
+		  __entry->parent
+	));
+
+/**
+ * kobject_move	- called from kobject_move()
+ * @kobj:	- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_move_class, kobject_move,
+
+	TP_PROTO(struct kobject *kobj, struct kobject *old_parent),
+	TP_ARGS(kobj, old_parent));
+
+/* kobject_rename_class */
+DECLARE_EVENT_CLASS(kobject_rename_class,
+
+	TP_PROTO(struct kobject *kobj, const char *old),
+	TP_ARGS(kobj, old),
+
+	TP_STRUCT__entry(
+		__field(void *, kobj)
+		__string(name, kobject_name(kobj))
+		__string(oldname, old)
+	),
+
+	TP_fast_assign(
+		__entry->kobj = kobj;
+		__assign_str(name, kobject_name(kobj));
+		__assign_str(oldname, old);
+	),
+
+	TP_printk("KOBJECT: %s (%p) oldname= %s",
+		  __get_str(name),
+		  __entry->kobj,
+		  __get_str(oldname)
+	));
+
+/**
+ * kobject_rename	- called from kobject_rename()
+ * @kobj:		- pointer to struct kobject
+ */
+DEFINE_EVENT(kobject_rename_class, kobject_rename,
+
+	TP_PROTO(struct kobject *kobj, const char *old),
+	TP_ARGS(kobj, old));
+
+#endif /* #if !defined(_TRACE_KOBJECT_H) ... */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.7.4

[PATCH 2/3] kobject: add kobject trace prototypes

[Shuah Khan]

Add kobject trace prototypes source file.

Signed-off-by: Shuah Khan <shuahkh@osg.samsung.com>
---
 lib/Makefile         |  2 +-
 lib/kobject_traces.c | 32 ++++++++++++++++++++++++++++++++
 2 files changed, 33 insertions(+), 1 deletion(-)
 create mode 100644 lib/kobject_traces.c

diff --git a/lib/Makefile b/lib/Makefile
index cfa68eb..0d9819c 100644
--- a/lib/Makefile
+++ b/lib/Makefile
@@ -29,7 +29,7 @@ lib-$(CONFIG_MMU) += ioremap.o
 lib-$(CONFIG_SMP) += cpumask.o
 lib-$(CONFIG_HAS_DMA) += dma-noop.o
 
-lib-y	+= kobject.o klist.o
+lib-y	+= kobject_traces.o kobject.o klist.o
 obj-y	+= lockref.o
 
 obj-y += bcd.o div64.o sort.o parser.o halfmd4.o debug_locks.o random32.o \
diff --git a/lib/kobject_traces.c b/lib/kobject_traces.c
new file mode 100644
index 0000000..71b0195
--- /dev/null
+++ b/lib/kobject_traces.c
@@ -0,0 +1,32 @@
+/*
+ * kobject trace points
+ *
+ * Copyright (C) 2016 Shuah Khan <shuahkh@osg.samsung.com>
+ *
+ */
+#include <linux/string.h>
+#include <linux/types.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/kobject.h>
+
+/* kobject_init event */
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_init);
+
+/* kobject_class events */
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_add);
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_init_and_add);
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_create_and_add);
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_set_name);
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_get);
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_del);
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_cleanup);
+
+/* kobject_put() event */
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_put);
+
+/* kobject_move event */
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_move);
+
+/* kobject_rename event */
+EXPORT_TRACEPOINT_SYMBOL_GPL(kobject_rename);
-- 
2.7.4

[PATCH 3/3] kobject: Add calls to kobject trace points

[Shuah Khan]

Add calls to kobject trace points to kobject init, add, init_and_add,
create_and_add, move, set_name, rename, get, put, cleanup, and del.

Signed-off-by: Shuah Khan <shuahkh@osg.samsung.com>
---
 lib/kobject.c | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

diff --git a/lib/kobject.c b/lib/kobject.c
index 445dcae..97ab522 100644
--- a/lib/kobject.c
+++ b/lib/kobject.c
@@ -18,6 +18,7 @@
 #include <linux/stat.h>
 #include <linux/slab.h>
 #include <linux/random.h>
+#include <trace/events/kobject.h>
 
 /**
  * kobject_namespace - return @kobj's namespace tag
@@ -306,6 +307,9 @@ int kobject_set_name(struct kobject *kobj, const char *fmt, ...)
 	retval = kobject_set_name_vargs(kobj, fmt, vargs);
 	va_end(vargs);
 
+	if (!retval)
+		trace_kobject_set_name(kobj);
+
 	return retval;
 }
 EXPORT_SYMBOL(kobject_set_name);
@@ -343,6 +347,7 @@ void kobject_init(struct kobject *kobj, struct kobj_type *ktype)
 
 	kobject_init_internal(kobj);
 	kobj->ktype = ktype;
+	trace_kobject_init(kobj);
 	return;
 
 error:
@@ -411,6 +416,9 @@ int kobject_add(struct kobject *kobj, struct kobject *parent,
 	retval = kobject_add_varg(kobj, parent, fmt, args);
 	va_end(args);
 
+	if (!retval)
+		trace_kobject_add(kobj);
+
 	return retval;
 }
 EXPORT_SYMBOL(kobject_add);
@@ -438,6 +446,9 @@ int kobject_init_and_add(struct kobject *kobj, struct kobj_type *ktype,
 	retval = kobject_add_varg(kobj, parent, fmt, args);
 	va_end(args);
 
+	if (!retval)
+		trace_kobject_init_and_add(kobj);
+
 	return retval;
 }
 EXPORT_SYMBOL_GPL(kobject_init_and_add);
@@ -494,11 +505,14 @@ int kobject_rename(struct kobject *kobj, const char *new_name)
 	dup_name = kobj->name;
 	kobj->name = name;
 
+	trace_kobject_rename(kobj, devpath);
+
 	/* This function is mostly/only used for network interface.
 	 * Some hotplug package track interfaces by their name and
 	 * therefore want to know when the name is changed by the user. */
 	kobject_uevent_env(kobj, KOBJ_MOVE, envp);
 
+
 out:
 	kfree_const(dup_name);
 	kfree(devpath_string);
@@ -553,6 +567,7 @@ int kobject_move(struct kobject *kobj, struct kobject *new_parent)
 	new_parent = NULL;
 	kobject_put(old_parent);
 	kobject_uevent_env(kobj, KOBJ_MOVE, envp);
+	trace_kobject_move(kobj, old_parent);
 out:
 	kobject_put(new_parent);
 	kobject_put(kobj);
@@ -581,6 +596,7 @@ void kobject_del(struct kobject *kobj)
 	kobj_kset_leave(kobj);
 	kobject_put(kobj->parent);
 	kobj->parent = NULL;
+	trace_kobject_del(kobj);
 }
 EXPORT_SYMBOL(kobject_del);
 
@@ -596,6 +612,7 @@ struct kobject *kobject_get(struct kobject *kobj)
 			       "initialized, yet kobject_get() is being "
 			       "called.\n", kobject_name(kobj), kobj);
 		kref_get(&kobj->kref);
+		trace_kobject_get(kobj);
 	}
 	return kobj;
 }
@@ -620,6 +637,8 @@ static void kobject_cleanup(struct kobject *kobj)
 	pr_debug("kobject: '%s' (%p): %s, parent %p\n",
 		 kobject_name(kobj), kobj, __func__, kobj->parent);
 
+	trace_kobject_cleanup(kobj);
+
 	if (t && !t->release)
 		pr_debug("kobject: '%s' (%p): does not have a release() "
 			 "function, it is broken and must be fixed.\n",
@@ -688,6 +707,8 @@ void kobject_put(struct kobject *kobj)
 			WARN(1, KERN_WARNING "kobject: '%s' (%p): is not "
 			       "initialized, yet kobject_put() is being "
 			       "called.\n", kobject_name(kobj), kobj);
+		/* call it now - kobj could get released during kref_put() */
+		trace_kobject_put(kobj);
 		kref_put(&kobj->kref, kobject_release);
 	}
 }
@@ -756,6 +777,7 @@ struct kobject *kobject_create_and_add(const char *name, struct kobject *parent)
 		kobject_put(kobj);
 		kobj = NULL;
 	}
+	trace_kobject_create_and_add(kobj);
 	return kobj;
 }
 EXPORT_SYMBOL_GPL(kobject_create_and_add);
-- 
2.7.4

Re: [PATCH 1/3] kobject: add kobject trace points

[Steven Rostedt]

On Tue,  6 Sep 2016 11:49:23 -0600
Shuah Khan <shuahkh@osg.samsung.com> wrote:

> +#if !defined(_TRACE_KOBJECT_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_KOBJECT_H
> +
> +#include <linux/tracepoint.h>
> +#include <linux/kobject.h>
> +
> +/* kobject_init_class */
> +DECLARE_EVENT_CLASS(kobject_init_class,
> +
> +	TP_PROTO(struct kobject *kobj),
> +
> +	TP_ARGS(kobj),
> +
> +	TP_STRUCT__entry(
> +		__field(void *, kobj)
> +		__field(int, state_initialized)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->kobj = kobj;
> +		__entry->state_initialized = kobj->state_initialized;
> +	),
> +
> +	TP_printk("KOBJECT: %p state=%d",
> +		  __entry->kobj,
> +		  __entry->state_initialized
> +	));
> +
> +/**
> + * kobject_init	- called from kobject_init() when kobject is initialized
> + * @kobj:	- pointer to struct kobject
> + */
> +DEFINE_EVENT(kobject_init_class, kobject_init,
> +
> +	TP_PROTO(struct kobject *kobj),
> +	TP_ARGS(kobj));
> +
> +/* kobject_class */
> +DECLARE_EVENT_CLASS(kobject_class,
> +
> +	TP_PROTO(struct kobject *kobj),
> +	TP_ARGS(kobj),
> +
> +	TP_STRUCT__entry(
> +		__field(void *, kobj)
> +		__string(name, kobject_name(kobj))
> +		__field(int, state_initialized)
> +		__field(void *, parent)
> +		__string(pname, kobj->parent ? kobject_name(kobj->parent) : "")
> +		__field(int, count)
> +	),

state_initialized looks to be a single bit. As you have two dynamic
strings, it may be best to move this around and possibly save 3 bytes.
Also, dynamic strings take 4 bytes, and pointers are 8 bytes on 64 bit
machines, we want to move those too.

	__field(void *, kobj)
	__field(void *, parent)
	__field(int, count)
	__string(name, ...)
	__string(pname, ...)
	__field(char, state_initialized)

This will compact the event a bit better.

-- Steve

> +
> +	TP_fast_assign(
> +		__entry->kobj = kobj;
> +		__assign_str(name, kobject_name(kobj));
> +		__entry->state_initialized = kobj->state_initialized;
> +		__entry->parent = kobj->parent;
> +		__assign_str(pname,
> +			     kobj->parent ? kobject_name(kobj->parent) : "");
> +		__entry->count = atomic_read(&kobj->kref.refcount);
> +	),
> +
> +	TP_printk("KOBJECT: %s (%p) state=%d parent= %s (%p) counter= %d",
> +		  __get_str(name),
> +		  __entry->kobj,
> +		  __entry->state_initialized,
> +		  __get_str(pname),
> +		  __entry->parent,
> +		  __entry->count
> +	));
> +

Re: [PATCH 0/3] kobject tracepoints

[Greg KH]

On Tue, Sep 06, 2016 at 11:49:22AM -0600, Shuah Khan wrote:
> Add kobject trace points to track kobject operations: init, add, set_name,
> init_and_add, create_and_add, move, rename, get, put, cleanup, and del.
> 
> Kobject trace points can aid in debugging, generating status and graphs
> on kobjects in the kernel and their hierarchy.

What type of "graphs"?  Isn't this just too noisy to ever find anything
"real"?

> This patch series adds kobject tracepoints and adds calls to tracepoints
> from kobject init, add, set_name, init_and_add, create_and_add, move,
> rename, get, put, cleanup, and del operations.
> 
> A suggestion to provide more visibility into kboject lifetimes came out of
> a discussion at my Embedded data structure lifetime talk at LinuxCon NA in
> Toronto. As I thought about on how to provide visibility, I decided adding
> traces provides a boot and run-time facility to trace kobject operations
> without needing compile special kernels and also without impacting run-time
> unless trace is enabled. Hence, this resulting patch series.
> 
> Example traces:
> 
> <...>-13632 [003] d... 11296.965114: kobject_get: KOBJECT: 1:0:0:0 (f
> fff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
>            <...>-13632 [003] d... 11296.965167: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
>            <...>-13632 [003] d... 11296.965218: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
>            <...>-13632 [003] d... 11296.965269: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 22
>           <idle>-0     [006] ..s. 11296.965378: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
>           <idle>-0     [006] .Ns. 11296.965542: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
>      ksoftirqd/6-46    [006] ..s. 11296.965633: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
>      ksoftirqd/6-46    [006] ..s. 11296.965703: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 18
> 
> Shuah Khan (3):
>   kobject: add kobject trace points
>   kobject: add kobject trace prototypes
>   kobject: Add calls to kobject trace points
> 
>  include/trace/events/kobject.h | 259 +++++++++++++++++++++++++++++++++++++++++
>  lib/Makefile                   |   2 +-
>  lib/kobject.c                  |  22 ++++
>  lib/kobject_traces.c           |  32 +++++
>  4 files changed, 314 insertions(+), 1 deletion(-)
>  create mode 100644 include/trace/events/kobject.h
>  create mode 100644 lib/kobject_traces.c

I've strongly resisted tracepoints in the driver core, and kobjects,
because of the implicit "userspace API" guarantees that some people see
these as.  I notice that Al Viro just posted a proposal to the ksummit
mailing list to potentially talk about this very issue.

I'm really curious as to exactly what these tracepoints can buy us,
other than drowning in them as devices are added and removed from the
system?  Isn't this just too noisy for any real use?

And again, I worry about people relying on them, as we have changed the
internals of kobjects at times over the years, I don't want to have to
worry about somehow keeping these tracepoints "identical" for the next
40+ years.

thanks,

greg k-h

Re: [PATCH 0/3] kobject tracepoints

[Shuah Khan]

On 09/06/2016 01:30 PM, Greg KH wrote:
> On Tue, Sep 06, 2016 at 11:49:22AM -0600, Shuah Khan wrote:
>> Add kobject trace points to track kobject operations: init, add, set_name,
>> init_and_add, create_and_add, move, rename, get, put, cleanup, and del.
>>
>> Kobject trace points can aid in debugging, generating status and graphs
>> on kobjects in the kernel and their hierarchy.
> 
> What type of "graphs"?  Isn't this just too noisy to ever find anything
> "real"?

Parent and child relationship between kobjects can be useful information
for debugging.

> 
>> This patch series adds kobject tracepoints and adds calls to tracepoints
>> from kobject init, add, set_name, init_and_add, create_and_add, move,
>> rename, get, put, cleanup, and del operations.
>>
>> A suggestion to provide more visibility into kboject lifetimes came out of
>> a discussion at my Embedded data structure lifetime talk at LinuxCon NA in
>> Toronto. As I thought about on how to provide visibility, I decided adding
>> traces provides a boot and run-time facility to trace kobject operations
>> without needing compile special kernels and also without impacting run-time
>> unless trace is enabled. Hence, this resulting patch series.
>>
>> Example traces:
>>
>> <...>-13632 [003] d... 11296.965114: kobject_get: KOBJECT: 1:0:0:0 (f
>> fff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
>>            <...>-13632 [003] d... 11296.965167: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
>>            <...>-13632 [003] d... 11296.965218: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
>>            <...>-13632 [003] d... 11296.965269: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 22
>>           <idle>-0     [006] ..s. 11296.965378: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
>>           <idle>-0     [006] .Ns. 11296.965542: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
>>      ksoftirqd/6-46    [006] ..s. 11296.965633: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
>>      ksoftirqd/6-46    [006] ..s. 11296.965703: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 18
>>
>> Shuah Khan (3):
>>   kobject: add kobject trace points
>>   kobject: add kobject trace prototypes
>>   kobject: Add calls to kobject trace points
>>
>>  include/trace/events/kobject.h | 259 +++++++++++++++++++++++++++++++++++++++++
>>  lib/Makefile                   |   2 +-
>>  lib/kobject.c                  |  22 ++++
>>  lib/kobject_traces.c           |  32 +++++
>>  4 files changed, 314 insertions(+), 1 deletion(-)
>>  create mode 100644 include/trace/events/kobject.h
>>  create mode 100644 lib/kobject_traces.c
> 
> I've strongly resisted tracepoints in the driver core, and kobjects,
> because of the implicit "userspace API" guarantees that some people see
> these as.  I notice that Al Viro just posted a proposal to the ksummit
> mailing list to potentially talk about this very issue.

Yes. I saw that discussion topic coming in. I honestly didn't think that
my patch series will result in a special KS topic :) However, I think it
is a good idea to discuss it as general topic for what kind of kernel
information should/should not be made visible via tracepoints.

We do support a wide range of tracepoints and events in various sub-systems
skb.h, pagemap.h, and pagemap.h so on. Maybe it would be helpful to agree
on some sort of guidelines for exposure.

> 
> I'm really curious as to exactly what these tracepoints can buy us,
> other than drowning in them as devices are added and removed from the
> system?  Isn't this just too noisy for any real use?

My main objective is for debugging lifetime related problems without
adding debug overhead. Being able to debug unbalanced gets and puts
for example. Yes this can get noisy for certain objects. 

> 
> And again, I worry about people relying on them, as we have changed the
> internals of kobjects at times over the years, I don't want to have to
> worry about somehow keeping these tracepoints "identical" for the next
> 40+ years.

Guess I never considered tracepoints as userspace API, anymore than debug
messages. It is part of debug and only visible to root.

In my mind it is mainly a debug information that would only make sense to
kernel developers. That is why I didn't think about needing to keep the
tracepoints identical. That said, if it is generally agreed that we shouldn't
expose this kind of information to userspace, I will look into doing this
in a different way.

thanks,
-- Shuah

Re: [PATCH 0/3] kobject tracepoints

[Greg KH]

On Tue, Sep 06, 2016 at 02:19:17PM -0600, Shuah Khan wrote:
> On 09/06/2016 01:30 PM, Greg KH wrote:
> > On Tue, Sep 06, 2016 at 11:49:22AM -0600, Shuah Khan wrote:
> >> Add kobject trace points to track kobject operations: init, add, set_name,
> >> init_and_add, create_and_add, move, rename, get, put, cleanup, and del.
> >>
> >> Kobject trace points can aid in debugging, generating status and graphs
> >> on kobjects in the kernel and their hierarchy.
> > 
> > What type of "graphs"?  Isn't this just too noisy to ever find anything
> > "real"?
> 
> Parent and child relationship between kobjects can be useful information
> for debugging.

Sure, but those show up in sysfs already :)

> >> This patch series adds kobject tracepoints and adds calls to tracepoints
> >> from kobject init, add, set_name, init_and_add, create_and_add, move,
> >> rename, get, put, cleanup, and del operations.
> >>
> >> A suggestion to provide more visibility into kboject lifetimes came out of
> >> a discussion at my Embedded data structure lifetime talk at LinuxCon NA in
> >> Toronto. As I thought about on how to provide visibility, I decided adding
> >> traces provides a boot and run-time facility to trace kobject operations
> >> without needing compile special kernels and also without impacting run-time
> >> unless trace is enabled. Hence, this resulting patch series.
> >>
> >> Example traces:
> >>
> >> <...>-13632 [003] d... 11296.965114: kobject_get: KOBJECT: 1:0:0:0 (f
> >> fff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
> >>            <...>-13632 [003] d... 11296.965167: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
> >>            <...>-13632 [003] d... 11296.965218: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
> >>            <...>-13632 [003] d... 11296.965269: kobject_get: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 22
> >>           <idle>-0     [006] ..s. 11296.965378: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 21
> >>           <idle>-0     [006] .Ns. 11296.965542: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 20
> >>      ksoftirqd/6-46    [006] ..s. 11296.965633: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 19
> >>      ksoftirqd/6-46    [006] ..s. 11296.965703: kobject_put: KOBJECT: 1:0:0:0 (ffff88034aeb1348) state=1 parent= target1:0:0 (ffff88038c875db8) counter= 18
> >>
> >> Shuah Khan (3):
> >>   kobject: add kobject trace points
> >>   kobject: add kobject trace prototypes
> >>   kobject: Add calls to kobject trace points
> >>
> >>  include/trace/events/kobject.h | 259 +++++++++++++++++++++++++++++++++++++++++
> >>  lib/Makefile                   |   2 +-
> >>  lib/kobject.c                  |  22 ++++
> >>  lib/kobject_traces.c           |  32 +++++
> >>  4 files changed, 314 insertions(+), 1 deletion(-)
> >>  create mode 100644 include/trace/events/kobject.h
> >>  create mode 100644 lib/kobject_traces.c
> > 
> > I've strongly resisted tracepoints in the driver core, and kobjects,
> > because of the implicit "userspace API" guarantees that some people see
> > these as.  I notice that Al Viro just posted a proposal to the ksummit
> > mailing list to potentially talk about this very issue.
> 
> Yes. I saw that discussion topic coming in. I honestly didn't think that
> my patch series will result in a special KS topic :) However, I think it
> is a good idea to discuss it as general topic for what kind of kernel
> information should/should not be made visible via tracepoints.

Yes, your patchset just brought up the old topic again, it isn't
specific to these changes.

> We do support a wide range of tracepoints and events in various sub-systems
> skb.h, pagemap.h, and pagemap.h so on. Maybe it would be helpful to agree
> on some sort of guidelines for exposure.

I agree.  Until then I would like to hold off on these changes to
kobjects, or any other core bits I maintain.

> > I'm really curious as to exactly what these tracepoints can buy us,
> > other than drowning in them as devices are added and removed from the
> > system?  Isn't this just too noisy for any real use?
> 
> My main objective is for debugging lifetime related problems without
> adding debug overhead. Being able to debug unbalanced gets and puts
> for example. Yes this can get noisy for certain objects. 

You can always enable CONFIG_DEBUG_KOBJECT to see much of what you
wanted here, in the kernel log.  Not as "nice" as a tracepoint I know,
but it is there for debugging.

And almost no one should be worrying about the kobject level, that's
usually rare.  'struct device' lifetime rules are more common, but even
then, that's at the bus level so it too can be rare for developers to
care about once the bus code is up and running properly.

> > And again, I worry about people relying on them, as we have changed the
> > internals of kobjects at times over the years, I don't want to have to
> > worry about somehow keeping these tracepoints "identical" for the next
> > 40+ years.
> 
> Guess I never considered tracepoints as userspace API, anymore than debug
> messages. It is part of debug and only visible to root.

See the conversation on ksummit-discuss, they have been used as
userspace APIs in the past, and could not be changed because userspace
tools relied on them, and the field size/structures.  I don't want to
have that happen here as I saw all of the problems that occured then.

> In my mind it is mainly a debug information that would only make sense to
> kernel developers. That is why I didn't think about needing to keep the
> tracepoints identical. That said, if it is generally agreed that we shouldn't
> expose this kind of information to userspace, I will look into doing this
> in a different way.

CONFIG_DEBUG_KOBJECT?  :)

thanks,

greg k-h

Re: [PATCH 1/3] kobject: add kobject trace points

[Shuah Khan]

[-- Attachment #1.1: Type: text/plain, Size: 2352 bytes --]

On 09/06/2016 12:05 PM, Steven Rostedt wrote:
> On Tue,  6 Sep 2016 11:49:23 -0600
> Shuah Khan <shuahkh@osg.samsung.com> wrote:
> 
>> +#if !defined(_TRACE_KOBJECT_H) || defined(TRACE_HEADER_MULTI_READ)
>> +#define _TRACE_KOBJECT_H
>> +
>> +#include <linux/tracepoint.h>
>> +#include <linux/kobject.h>
>> +
>> +/* kobject_init_class */
>> +DECLARE_EVENT_CLASS(kobject_init_class,
>> +
>> +	TP_PROTO(struct kobject *kobj),
>> +
>> +	TP_ARGS(kobj),
>> +
>> +	TP_STRUCT__entry(
>> +		__field(void *, kobj)
>> +		__field(int, state_initialized)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__entry->kobj = kobj;
>> +		__entry->state_initialized = kobj->state_initialized;
>> +	),
>> +
>> +	TP_printk("KOBJECT: %p state=%d",
>> +		  __entry->kobj,
>> +		  __entry->state_initialized
>> +	));
>> +
>> +/**
>> + * kobject_init	- called from kobject_init() when kobject is initialized
>> + * @kobj:	- pointer to struct kobject
>> + */
>> +DEFINE_EVENT(kobject_init_class, kobject_init,
>> +
>> +	TP_PROTO(struct kobject *kobj),
>> +	TP_ARGS(kobj));
>> +
>> +/* kobject_class */
>> +DECLARE_EVENT_CLASS(kobject_class,
>> +
>> +	TP_PROTO(struct kobject *kobj),
>> +	TP_ARGS(kobj),
>> +
>> +	TP_STRUCT__entry(
>> +		__field(void *, kobj)
>> +		__string(name, kobject_name(kobj))
>> +		__field(int, state_initialized)
>> +		__field(void *, parent)
>> +		__string(pname, kobj->parent ? kobject_name(kobj->parent) : "")
>> +		__field(int, count)
>> +	),
> 
> state_initialized looks to be a single bit. As you have two dynamic
> strings, it may be best to move this around and possibly save 3 bytes.
> Also, dynamic strings take 4 bytes, and pointers are 8 bytes on 64 bit
> machines, we want to move those too.
> 
> 	__field(void *, kobj)
> 	__field(void *, parent)
> 	__field(int, count)
> 	__string(name, ...)
> 	__string(pname, ...)
> 	__field(char, state_initialized)
> 
> This will compact the event a bit better.
> 
> -- Steve
> 

Nice. I should start thinking about efficient data structure packing
again. Used to do that a lot in the past when I worked on small embedded
systems.

I made the change and patch is ready, but holding off on sending the v2
of this patch until we conclude our tracepoint discussion at the kernel
summit and make some decisions.

thanks,
-- Shuah



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]