[PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[tom.leiming]

From: Ming Lei <ming.lei@canonical.com>

This patch introduces 3 trace points to prepare for tracing
rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
trace points to replace the current dev_dbg().

Cc: Steven Rostedt rostedt@goodmis.org
Signed-off-by: Ming Lei <ming.lei@canonical.com>
---
v1: takes Steven's suggestions
	- use __assign_str to dump device name to trace buffer
	- pass _THIS_IP_ to trace_rpm_return_int
---
 include/trace/events/rpm.h |   99 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/Makefile      |    1 +
 kernel/trace/rpm-traces.c  |   21 +++++++++
 3 files changed, 121 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/rpm.h
 create mode 100644 kernel/trace/rpm-traces.c

diff --git a/include/trace/events/rpm.h b/include/trace/events/rpm.h
new file mode 100644
index 0000000..36805d9
--- /dev/null
+++ b/include/trace/events/rpm.h
@@ -0,0 +1,99 @@
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM rpm
+
+#if !defined(_TRACE_RUNTIME_POWER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_RUNTIME_POWER_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+#include <linux/device.h>
+
+/*
+ * The rpm_internal events are used for tracing some important
+ * runtime pm internal functions.
+ */
+DECLARE_EVENT_CLASS(rpm_internal,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags),
+
+	TP_STRUCT__entry(
+		__string(       name,		dev_name(dev)	)
+		__field(        int,            flags           )
+		__field(        int ,   	usage_count	)
+		__field(        int ,   	disable_depth   )
+		__field(        int ,   	runtime_auto	)
+		__field(        int ,   	request_pending	)
+		__field(        int ,   	irq_safe	)
+		__field(        int ,   	child_count 	)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, dev_name(dev));
+		__entry->flags = flags;
+		__entry->usage_count = atomic_read(
+			&dev->power.usage_count);
+		__entry->disable_depth = dev->power.disable_depth;
+		__entry->runtime_auto = dev->power.runtime_auto;
+		__entry->request_pending = dev->power.request_pending;
+		__entry->irq_safe = dev->power.irq_safe;
+		__entry->child_count = atomic_read(
+			&dev->power.child_count);
+	),
+
+	TP_printk("%s flags-%x cnt-%-2d dep-%-2d auto-%-1d p-%-1d"
+			" irq-%-1d child-%d",
+			__get_str(name), __entry->flags,
+			__entry->usage_count,
+			__entry->disable_depth,
+			__entry->runtime_auto,
+			__entry->request_pending,
+			__entry->irq_safe,
+			__entry->child_count
+		 )
+);
+DEFINE_EVENT(rpm_internal, rpm_suspend,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
+DEFINE_EVENT(rpm_internal, rpm_resume,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
+DEFINE_EVENT(rpm_internal, rpm_idle,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
+
+TRACE_EVENT(rpm_return_int,
+	TP_PROTO(struct device *dev, unsigned long ip, int ret),
+	TP_ARGS(dev, ip, ret),
+
+	TP_STRUCT__entry(
+		__string(       name,		dev_name(dev))
+		__field(	unsigned long,		ip	)
+		__field(	int,			ret	)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, dev_name(dev));
+		__entry->ip = ip;
+		__entry->ret = ret;
+	),
+
+	TP_printk("%pS:%s ret=%d", __entry->ip, __get_str(name),
+		__entry->ret)
+);
+
+#endif /* _TRACE_RUNTIME_POWER_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 761c510..56bdab5 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -53,6 +53,7 @@ endif
 obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
 obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
 obj-$(CONFIG_TRACEPOINTS) += power-traces.o
+obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
 ifeq ($(CONFIG_TRACING),y)
 obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
 endif
diff --git a/kernel/trace/rpm-traces.c b/kernel/trace/rpm-traces.c
new file mode 100644
index 0000000..998949e
--- /dev/null
+++ b/kernel/trace/rpm-traces.c
@@ -0,0 +1,21 @@
+/*
+ * Power trace points
+ *
+ * Copyright (C) 2009 Ming Lei <ming.lei@canonical.com>
+ */
+
+#include <linux/string.h>
+#include <linux/types.h>
+#include <linux/workqueue.h>
+#include <linux/sched.h>
+#include <linux/module.h>
+#include <linux/usb.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/rpm.h>
+
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_return_int);
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_idle);
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_suspend);
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_resume);
+
-- 
1.7.5.4

[PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[tom.leiming]

From: Ming Lei <ming.lei@canonical.com>

This patch introduces 3 trace points to prepare for tracing
rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
trace points to replace the current dev_dbg().

Cc: Steven Rostedt rostedt@goodmis.org
Signed-off-by: Ming Lei <ming.lei@canonical.com>
---
v1: takes Steven's suggestions
	- use __assign_str to dump device name to trace buffer
	- pass _THIS_IP_ to trace_rpm_return_int
---
 include/trace/events/rpm.h |   99 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/Makefile      |    1 +
 kernel/trace/rpm-traces.c  |   21 +++++++++
 3 files changed, 121 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/rpm.h
 create mode 100644 kernel/trace/rpm-traces.c

diff --git a/include/trace/events/rpm.h b/include/trace/events/rpm.h
new file mode 100644
index 0000000..36805d9
--- /dev/null
+++ b/include/trace/events/rpm.h
@@ -0,0 +1,99 @@
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM rpm
+
+#if !defined(_TRACE_RUNTIME_POWER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_RUNTIME_POWER_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+#include <linux/device.h>
+
+/*
+ * The rpm_internal events are used for tracing some important
+ * runtime pm internal functions.
+ */
+DECLARE_EVENT_CLASS(rpm_internal,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags),
+
+	TP_STRUCT__entry(
+		__string(       name,		dev_name(dev)	)
+		__field(        int,            flags           )
+		__field(        int ,   	usage_count	)
+		__field(        int ,   	disable_depth   )
+		__field(        int ,   	runtime_auto	)
+		__field(        int ,   	request_pending	)
+		__field(        int ,   	irq_safe	)
+		__field(        int ,   	child_count 	)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, dev_name(dev));
+		__entry->flags = flags;
+		__entry->usage_count = atomic_read(
+			&dev->power.usage_count);
+		__entry->disable_depth = dev->power.disable_depth;
+		__entry->runtime_auto = dev->power.runtime_auto;
+		__entry->request_pending = dev->power.request_pending;
+		__entry->irq_safe = dev->power.irq_safe;
+		__entry->child_count = atomic_read(
+			&dev->power.child_count);
+	),
+
+	TP_printk("%s flags-%x cnt-%-2d dep-%-2d auto-%-1d p-%-1d"
+			" irq-%-1d child-%d",
+			__get_str(name), __entry->flags,
+			__entry->usage_count,
+			__entry->disable_depth,
+			__entry->runtime_auto,
+			__entry->request_pending,
+			__entry->irq_safe,
+			__entry->child_count
+		 )
+);
+DEFINE_EVENT(rpm_internal, rpm_suspend,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
+DEFINE_EVENT(rpm_internal, rpm_resume,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
+DEFINE_EVENT(rpm_internal, rpm_idle,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
+
+TRACE_EVENT(rpm_return_int,
+	TP_PROTO(struct device *dev, unsigned long ip, int ret),
+	TP_ARGS(dev, ip, ret),
+
+	TP_STRUCT__entry(
+		__string(       name,		dev_name(dev))
+		__field(	unsigned long,		ip	)
+		__field(	int,			ret	)
+	),
+
+	TP_fast_assign(
+		__assign_str(name, dev_name(dev));
+		__entry->ip = ip;
+		__entry->ret = ret;
+	),
+
+	TP_printk("%pS:%s ret=%d", __entry->ip, __get_str(name),
+		__entry->ret)
+);
+
+#endif /* _TRACE_RUNTIME_POWER_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 761c510..56bdab5 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -53,6 +53,7 @@ endif
 obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
 obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
 obj-$(CONFIG_TRACEPOINTS) += power-traces.o
+obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
 ifeq ($(CONFIG_TRACING),y)
 obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
 endif
diff --git a/kernel/trace/rpm-traces.c b/kernel/trace/rpm-traces.c
new file mode 100644
index 0000000..998949e
--- /dev/null
+++ b/kernel/trace/rpm-traces.c
@@ -0,0 +1,21 @@
+/*
+ * Power trace points
+ *
+ * Copyright (C) 2009 Ming Lei <ming.lei@canonical.com>
+ */
+
+#include <linux/string.h>
+#include <linux/types.h>
+#include <linux/workqueue.h>
+#include <linux/sched.h>
+#include <linux/module.h>
+#include <linux/usb.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/rpm.h>
+
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_return_int);
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_idle);
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_suspend);
+EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_resume);
+
-- 
1.7.5.4

[PATCH v1 2/2] PM/runtime: replace dev_dbg with trace_rpm_*

[tom.leiming]

From: Ming Lei <ming.lei@canonical.com>

This patch replaces dev_dbg with trace_rpm_* inside
the three important functions:

	rpm_idle
	rpm_suspend
	rpm_resume

Trace points have the below advantages compared with dev_dbg:

	- trace points include much runtime information(such as
	running cpu, current task, ...)

	- most of linux distributions may disable "verbose debug"
	driver debug compile switch, so it is very difficult to
	report/debug runtime pm related problems from distribution
	users without this kind of debug information.

	- for upstream kernel users, enableing the debug switch will
	produce many useless "rpm_resume" output, and it is very noise.

	- dev_dbg inside rpm_suspend/rpm_resume may have some effects
	on runtime pm behaviour of console devicer

Cc: Steven Rostedt rostedt@goodmis.org
Signed-off-by: Ming Lei <ming.lei@canonical.com>
---

v1: takes Steven's suggestions
        - pass _THIS_IP_ to trace_rpm_return_int

---
 drivers/base/power/runtime.c |   11 +++++++----
 1 files changed, 7 insertions(+), 4 deletions(-)

diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
index acb3f83..74013fa 100644
--- a/drivers/base/power/runtime.c
+++ b/drivers/base/power/runtime.c
@@ -9,6 +9,7 @@
 
 #include <linux/sched.h>
 #include <linux/pm_runtime.h>
+#include <trace/events/rpm.h>
 #include "power.h"
 
 static int rpm_resume(struct device *dev, int rpmflags);
@@ -171,6 +172,7 @@ static int rpm_idle(struct device *dev, int rpmflags)
 	int (*callback)(struct device *);
 	int retval;
 
+	trace_rpm_idle(dev, rpmflags);
 	retval = rpm_check_suspend_allowed(dev);
 	if (retval < 0)
 		;	/* Conditions are wrong. */
@@ -243,6 +245,7 @@ static int rpm_idle(struct device *dev, int rpmflags)
 	wake_up_all(&dev->power.wait_queue);
 
  out:
+	trace_rpm_return_int(dev, _THIS_IP_, retval);
 	return retval;
 }
 
@@ -295,7 +298,7 @@ static int rpm_suspend(struct device *dev, int rpmflags)
 	struct device *parent = NULL;
 	int retval;
 
-	dev_dbg(dev, "%s flags 0x%x\n", __func__, rpmflags);
+	trace_rpm_suspend(dev, rpmflags);
 
  repeat:
 	retval = rpm_check_suspend_allowed(dev);
@@ -430,7 +433,7 @@ static int rpm_suspend(struct device *dev, int rpmflags)
 	}
 
  out:
-	dev_dbg(dev, "%s returns %d\n", __func__, retval);
+	trace_rpm_return_int(dev, _THIS_IP_, retval);
 
 	return retval;
 }
@@ -459,7 +462,7 @@ static int rpm_resume(struct device *dev, int rpmflags)
 	struct device *parent = NULL;
 	int retval = 0;
 
-	dev_dbg(dev, "%s flags 0x%x\n", __func__, rpmflags);
+	trace_rpm_resume(dev, rpmflags);
 
  repeat:
 	if (dev->power.runtime_error)
@@ -615,7 +618,7 @@ static int rpm_resume(struct device *dev, int rpmflags)
 		spin_lock_irq(&dev->power.lock);
 	}
 
-	dev_dbg(dev, "%s returns %d\n", __func__, retval);
+	trace_rpm_return_int(dev, _THIS_IP_, retval);
 
 	return retval;
 }
-- 
1.7.5.4

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Rafael J. Wysocki]

On Tuesday, September 27, 2011, tom.leiming@gmail.com wrote:
> From: Ming Lei <ming.lei@canonical.com>
> 
> This patch introduces 3 trace points to prepare for tracing
> rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
> trace points to replace the current dev_dbg().
> 
> Cc: Steven Rostedt rostedt@goodmis.org
> Signed-off-by: Ming Lei <ming.lei@canonical.com>
> ---
> v1: takes Steven's suggestions
> 	- use __assign_str to dump device name to trace buffer
> 	- pass _THIS_IP_ to trace_rpm_return_int

Steven, do the patches look good to you now?

Rafael


> ---
>  include/trace/events/rpm.h |   99 ++++++++++++++++++++++++++++++++++++++++++++
>  kernel/trace/Makefile      |    1 +
>  kernel/trace/rpm-traces.c  |   21 +++++++++
>  3 files changed, 121 insertions(+), 0 deletions(-)
>  create mode 100644 include/trace/events/rpm.h
>  create mode 100644 kernel/trace/rpm-traces.c
> 
> diff --git a/include/trace/events/rpm.h b/include/trace/events/rpm.h
> new file mode 100644
> index 0000000..36805d9
> --- /dev/null
> +++ b/include/trace/events/rpm.h
> @@ -0,0 +1,99 @@
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM rpm
> +
> +#if !defined(_TRACE_RUNTIME_POWER_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_RUNTIME_POWER_H
> +
> +#include <linux/ktime.h>
> +#include <linux/tracepoint.h>
> +#include <linux/device.h>
> +
> +/*
> + * The rpm_internal events are used for tracing some important
> + * runtime pm internal functions.
> + */
> +DECLARE_EVENT_CLASS(rpm_internal,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags),
> +
> +	TP_STRUCT__entry(
> +		__string(       name,		dev_name(dev)	)
> +		__field(        int,            flags           )
> +		__field(        int ,   	usage_count	)
> +		__field(        int ,   	disable_depth   )
> +		__field(        int ,   	runtime_auto	)
> +		__field(        int ,   	request_pending	)
> +		__field(        int ,   	irq_safe	)
> +		__field(        int ,   	child_count 	)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, dev_name(dev));
> +		__entry->flags = flags;
> +		__entry->usage_count = atomic_read(
> +			&dev->power.usage_count);
> +		__entry->disable_depth = dev->power.disable_depth;
> +		__entry->runtime_auto = dev->power.runtime_auto;
> +		__entry->request_pending = dev->power.request_pending;
> +		__entry->irq_safe = dev->power.irq_safe;
> +		__entry->child_count = atomic_read(
> +			&dev->power.child_count);
> +	),
> +
> +	TP_printk("%s flags-%x cnt-%-2d dep-%-2d auto-%-1d p-%-1d"
> +			" irq-%-1d child-%d",
> +			__get_str(name), __entry->flags,
> +			__entry->usage_count,
> +			__entry->disable_depth,
> +			__entry->runtime_auto,
> +			__entry->request_pending,
> +			__entry->irq_safe,
> +			__entry->child_count
> +		 )
> +);
> +DEFINE_EVENT(rpm_internal, rpm_suspend,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags)
> +);
> +DEFINE_EVENT(rpm_internal, rpm_resume,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags)
> +);
> +DEFINE_EVENT(rpm_internal, rpm_idle,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags)
> +);
> +
> +TRACE_EVENT(rpm_return_int,
> +	TP_PROTO(struct device *dev, unsigned long ip, int ret),
> +	TP_ARGS(dev, ip, ret),
> +
> +	TP_STRUCT__entry(
> +		__string(       name,		dev_name(dev))
> +		__field(	unsigned long,		ip	)
> +		__field(	int,			ret	)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, dev_name(dev));
> +		__entry->ip = ip;
> +		__entry->ret = ret;
> +	),
> +
> +	TP_printk("%pS:%s ret=%d", __entry->ip, __get_str(name),
> +		__entry->ret)
> +);
> +
> +#endif /* _TRACE_RUNTIME_POWER_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> index 761c510..56bdab5 100644
> --- a/kernel/trace/Makefile
> +++ b/kernel/trace/Makefile
> @@ -53,6 +53,7 @@ endif
>  obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
>  obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
>  obj-$(CONFIG_TRACEPOINTS) += power-traces.o
> +obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
>  ifeq ($(CONFIG_TRACING),y)
>  obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
>  endif
> diff --git a/kernel/trace/rpm-traces.c b/kernel/trace/rpm-traces.c
> new file mode 100644
> index 0000000..998949e
> --- /dev/null
> +++ b/kernel/trace/rpm-traces.c
> @@ -0,0 +1,21 @@
> +/*
> + * Power trace points
> + *
> + * Copyright (C) 2009 Ming Lei <ming.lei@canonical.com>
> + */
> +
> +#include <linux/string.h>
> +#include <linux/types.h>
> +#include <linux/workqueue.h>
> +#include <linux/sched.h>
> +#include <linux/module.h>
> +#include <linux/usb.h>
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/rpm.h>
> +
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_return_int);
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_idle);
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_suspend);
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_resume);
> +
> 

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Steven Rostedt]

On Tue, 2011-09-27 at 22:06 +0200, Rafael J. Wysocki wrote:
> On Tuesday, September 27, 2011, tom.leiming@gmail.com wrote:
> > From: Ming Lei <ming.lei@canonical.com>
> > 
> > This patch introduces 3 trace points to prepare for tracing
> > rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
> > trace points to replace the current dev_dbg().
> > 
> > Cc: Steven Rostedt rostedt@goodmis.org
> > Signed-off-by: Ming Lei <ming.lei@canonical.com>
> > ---
> > v1: takes Steven's suggestions
> > 	- use __assign_str to dump device name to trace buffer
> > 	- pass _THIS_IP_ to trace_rpm_return_int
> 
> Steven, do the patches look good to you now?

Yep,

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Rafael J. Wysocki]

On Tuesday, September 27, 2011, tom.leiming@gmail.com wrote:
> From: Ming Lei <ming.lei@canonical.com>
> 
> This patch introduces 3 trace points to prepare for tracing
> rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
> trace points to replace the current dev_dbg().
> 
> Cc: Steven Rostedt rostedt@goodmis.org
> Signed-off-by: Ming Lei <ming.lei@canonical.com>

I get the following build warning from it:

  GEN     /home/rafael/src/build/mainline/tosh/Makefile
  CHK     include/linux/version.h
  Using /home/rafael/src/linux as source for kernel
  CHK     include/generated/utsrelease.h
  CALL    /home/rafael/src/linux/scripts/checksyscalls.sh
  CHK     include/generated/compile.h
  CC      drivers/base/power/runtime.o
  CC      kernel/trace/rpm-traces.o
In file included from /home/rafael/src/linux/include/trace/ftrace.h:296:0,
                 from /home/rafael/src/linux/include/trace/define_trace.h:96,
                 from /home/rafael/src/linux/include/trace/events/rpm.h:99,
                 from /home/rafael/src/linux/kernel/trace/rpm-traces.c:15:
/home/rafael/src/linux/include/trace/events/rpm.h: In function ‘ftrace_raw_output_rpm_return_int’:
/home/rafael/src/linux/include/trace/events/rpm.h:76:1: warning: format ‘%p’ expects type ‘void *’, but argument 3 has type ‘long unsigned int’

Care to check?

Rafael


> ---
> v1: takes Steven's suggestions
> 	- use __assign_str to dump device name to trace buffer
> 	- pass _THIS_IP_ to trace_rpm_return_int
> ---
>  include/trace/events/rpm.h |   99 ++++++++++++++++++++++++++++++++++++++++++++
>  kernel/trace/Makefile      |    1 +
>  kernel/trace/rpm-traces.c  |   21 +++++++++
>  3 files changed, 121 insertions(+), 0 deletions(-)
>  create mode 100644 include/trace/events/rpm.h
>  create mode 100644 kernel/trace/rpm-traces.c
> 
> diff --git a/include/trace/events/rpm.h b/include/trace/events/rpm.h
> new file mode 100644
> index 0000000..36805d9
> --- /dev/null
> +++ b/include/trace/events/rpm.h
> @@ -0,0 +1,99 @@
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM rpm
> +
> +#if !defined(_TRACE_RUNTIME_POWER_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_RUNTIME_POWER_H
> +
> +#include <linux/ktime.h>
> +#include <linux/tracepoint.h>
> +#include <linux/device.h>
> +
> +/*
> + * The rpm_internal events are used for tracing some important
> + * runtime pm internal functions.
> + */
> +DECLARE_EVENT_CLASS(rpm_internal,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags),
> +
> +	TP_STRUCT__entry(
> +		__string(       name,		dev_name(dev)	)
> +		__field(        int,            flags           )
> +		__field(        int ,   	usage_count	)
> +		__field(        int ,   	disable_depth   )
> +		__field(        int ,   	runtime_auto	)
> +		__field(        int ,   	request_pending	)
> +		__field(        int ,   	irq_safe	)
> +		__field(        int ,   	child_count 	)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, dev_name(dev));
> +		__entry->flags = flags;
> +		__entry->usage_count = atomic_read(
> +			&dev->power.usage_count);
> +		__entry->disable_depth = dev->power.disable_depth;
> +		__entry->runtime_auto = dev->power.runtime_auto;
> +		__entry->request_pending = dev->power.request_pending;
> +		__entry->irq_safe = dev->power.irq_safe;
> +		__entry->child_count = atomic_read(
> +			&dev->power.child_count);
> +	),
> +
> +	TP_printk("%s flags-%x cnt-%-2d dep-%-2d auto-%-1d p-%-1d"
> +			" irq-%-1d child-%d",
> +			__get_str(name), __entry->flags,
> +			__entry->usage_count,
> +			__entry->disable_depth,
> +			__entry->runtime_auto,
> +			__entry->request_pending,
> +			__entry->irq_safe,
> +			__entry->child_count
> +		 )
> +);
> +DEFINE_EVENT(rpm_internal, rpm_suspend,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags)
> +);
> +DEFINE_EVENT(rpm_internal, rpm_resume,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags)
> +);
> +DEFINE_EVENT(rpm_internal, rpm_idle,
> +
> +	TP_PROTO(struct device *dev, int flags),
> +
> +	TP_ARGS(dev, flags)
> +);
> +
> +TRACE_EVENT(rpm_return_int,
> +	TP_PROTO(struct device *dev, unsigned long ip, int ret),
> +	TP_ARGS(dev, ip, ret),
> +
> +	TP_STRUCT__entry(
> +		__string(       name,		dev_name(dev))
> +		__field(	unsigned long,		ip	)
> +		__field(	int,			ret	)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(name, dev_name(dev));
> +		__entry->ip = ip;
> +		__entry->ret = ret;
> +	),
> +
> +	TP_printk("%pS:%s ret=%d", __entry->ip, __get_str(name),
> +		__entry->ret)
> +);
> +
> +#endif /* _TRACE_RUNTIME_POWER_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
> index 761c510..56bdab5 100644
> --- a/kernel/trace/Makefile
> +++ b/kernel/trace/Makefile
> @@ -53,6 +53,7 @@ endif
>  obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
>  obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
>  obj-$(CONFIG_TRACEPOINTS) += power-traces.o
> +obj-$(CONFIG_TRACEPOINTS) += rpm-traces.o
>  ifeq ($(CONFIG_TRACING),y)
>  obj-$(CONFIG_KGDB_KDB) += trace_kdb.o
>  endif
> diff --git a/kernel/trace/rpm-traces.c b/kernel/trace/rpm-traces.c
> new file mode 100644
> index 0000000..998949e
> --- /dev/null
> +++ b/kernel/trace/rpm-traces.c
> @@ -0,0 +1,21 @@
> +/*
> + * Power trace points
> + *
> + * Copyright (C) 2009 Ming Lei <ming.lei@canonical.com>
> + */
> +
> +#include <linux/string.h>
> +#include <linux/types.h>
> +#include <linux/workqueue.h>
> +#include <linux/sched.h>
> +#include <linux/module.h>
> +#include <linux/usb.h>
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/rpm.h>
> +
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_return_int);
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_idle);
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_suspend);
> +EXPORT_TRACEPOINT_SYMBOL_GPL(rpm_resume);
> +
> 

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Steven Rostedt]

On Tue, 2011-09-27 at 22:29 +0200, Rafael J. Wysocki wrote:
> On Tuesday, September 27, 2011, tom.leiming@gmail.com wrote:
> > From: Ming Lei <ming.lei@canonical.com>
> > 
> > This patch introduces 3 trace points to prepare for tracing
> > rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
> > trace points to replace the current dev_dbg().
> > 
> > Cc: Steven Rostedt rostedt@goodmis.org
> > Signed-off-by: Ming Lei <ming.lei@canonical.com>
> 
> I get the following build warning from it:
> 
>   GEN     /home/rafael/src/build/mainline/tosh/Makefile
>   CHK     include/linux/version.h
>   Using /home/rafael/src/linux as source for kernel
>   CHK     include/generated/utsrelease.h
>   CALL    /home/rafael/src/linux/scripts/checksyscalls.sh
>   CHK     include/generated/compile.h
>   CC      drivers/base/power/runtime.o
>   CC      kernel/trace/rpm-traces.o
> In file included from /home/rafael/src/linux/include/trace/ftrace.h:296:0,
>                  from /home/rafael/src/linux/include/trace/define_trace.h:96,
>                  from /home/rafael/src/linux/include/trace/events/rpm.h:99,
>                  from /home/rafael/src/linux/kernel/trace/rpm-traces.c:15:
> /home/rafael/src/linux/include/trace/events/rpm.h: In function ‘ftrace_raw_output_rpm_return_int’:
> /home/rafael/src/linux/include/trace/events/rpm.h:76:1: warning: format ‘%p’ expects type ‘void *’, but argument 3 has type ‘long unsigned int’
> 
> Care to check?
> 
> Rafael

> > +TRACE_EVENT(rpm_return_int,
> > +	TP_PROTO(struct device *dev, unsigned long ip, int ret),
> > +	TP_ARGS(dev, ip, ret),
> > +
> > +	TP_STRUCT__entry(
> > +		__string(       name,		dev_name(dev))
> > +		__field(	unsigned long,		ip	)
> > +		__field(	int,			ret	)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__assign_str(name, dev_name(dev));
> > +		__entry->ip = ip;
> > +		__entry->ret = ret;
> > +	),
> > +
> > +	TP_printk("%pS:%s ret=%d", __entry->ip, __get_str(name),
> > +		__entry->ret)
> > +);
> > +


	TP_printk("%pS:%s ret=%d", (void *)__entry->ip, __get_str(name),
		__entry->ret)

try that.

-- Steve

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Rafael J. Wysocki]

On Tuesday, September 27, 2011, Steven Rostedt wrote:
> On Tue, 2011-09-27 at 22:29 +0200, Rafael J. Wysocki wrote:
> > On Tuesday, September 27, 2011, tom.leiming@gmail.com wrote:
> > > From: Ming Lei <ming.lei@canonical.com>
> > > 
> > > This patch introduces 3 trace points to prepare for tracing
> > > rpm_idle/rpm_suspend/rpm_resume functions, so we can use these
> > > trace points to replace the current dev_dbg().
> > > 
> > > Cc: Steven Rostedt rostedt@goodmis.org
> > > Signed-off-by: Ming Lei <ming.lei@canonical.com>
> > 
> > I get the following build warning from it:
> > 
> >   GEN     /home/rafael/src/build/mainline/tosh/Makefile
> >   CHK     include/linux/version.h
> >   Using /home/rafael/src/linux as source for kernel
> >   CHK     include/generated/utsrelease.h
> >   CALL    /home/rafael/src/linux/scripts/checksyscalls.sh
> >   CHK     include/generated/compile.h
> >   CC      drivers/base/power/runtime.o
> >   CC      kernel/trace/rpm-traces.o
> > In file included from /home/rafael/src/linux/include/trace/ftrace.h:296:0,
> >                  from /home/rafael/src/linux/include/trace/define_trace.h:96,
> >                  from /home/rafael/src/linux/include/trace/events/rpm.h:99,
> >                  from /home/rafael/src/linux/kernel/trace/rpm-traces.c:15:
> > /home/rafael/src/linux/include/trace/events/rpm.h: In function ‘ftrace_raw_output_rpm_return_int’:
> > /home/rafael/src/linux/include/trace/events/rpm.h:76:1: warning: format ‘%p’ expects type ‘void *’, but argument 3 has type ‘long unsigned int’
> > 
> > Care to check?
> > 
> > Rafael
> 
> > > +TRACE_EVENT(rpm_return_int,
> > > +	TP_PROTO(struct device *dev, unsigned long ip, int ret),
> > > +	TP_ARGS(dev, ip, ret),
> > > +
> > > +	TP_STRUCT__entry(
> > > +		__string(       name,		dev_name(dev))
> > > +		__field(	unsigned long,		ip	)
> > > +		__field(	int,			ret	)
> > > +	),
> > > +
> > > +	TP_fast_assign(
> > > +		__assign_str(name, dev_name(dev));
> > > +		__entry->ip = ip;
> > > +		__entry->ret = ret;
> > > +	),
> > > +
> > > +	TP_printk("%pS:%s ret=%d", __entry->ip, __get_str(name),
> > > +		__entry->ret)
> > > +);
> > > +
> 
> 
> 	TP_printk("%pS:%s ret=%d", (void *)__entry->ip, __get_str(name),
> 		__entry->ret)
> 
> try that.

Well, that certainly will work, but is it the right fix?

Rafael

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Steven Rostedt]

On Tue, 2011-09-27 at 22:36 +0200, Rafael J. Wysocki wrote:

> > 	TP_printk("%pS:%s ret=%d", (void *)__entry->ip, __get_str(name),
> > 		__entry->ret)
> > 
> > try that.
> 
> Well, that certainly will work, but is it the right fix?

Hehe, yes!  The pS means to take a pointer and return the string version
of the address. Like "schedule+0x3a". __entry->ip is the address of the
function that called it __THIS_IP__ but we want to convert that into a
string name.

We use ip because both perf and trace-cmd should be smart enough to
parse it too. As they both store the kallsyms into the data file.

The (void *) is used because pS wants a pointer, and we stored the
address as an unsigned long.

-- Steve

Re: [PATCH v1 1/2] PM/runtime: introduce trace points for tracing rpm_* functions

[Rafael J. Wysocki]

On Tuesday, September 27, 2011, Steven Rostedt wrote:
> On Tue, 2011-09-27 at 22:36 +0200, Rafael J. Wysocki wrote:
> 
> > > 	TP_printk("%pS:%s ret=%d", (void *)__entry->ip, __get_str(name),
> > > 		__entry->ret)
> > > 
> > > try that.
> > 
> > Well, that certainly will work, but is it the right fix?
> 
> Hehe, yes!  The pS means to take a pointer and return the string version
> of the address. Like "schedule+0x3a". __entry->ip is the address of the
> function that called it __THIS_IP__ but we want to convert that into a
> string name.
> 
> We use ip because both perf and trace-cmd should be smart enough to
> parse it too. As they both store the kallsyms into the data file.
> 
> The (void *) is used because pS wants a pointer, and we stored the
> address as an unsigned long.

OK, good.

I've applied both patches (with the above fix folded into the first one)
to linux-pm/pm-runtime (and merged into my linux-next branch), so they will be
pushed for 3.2.

Thanks,
Rafael