Re: [PATCH v2] PM: trace events for suspend/resume

[Todd E Brandt <todd.e.brandt@linux.intel.com>]

On Fri, May 30, 2014 at 10:33:49PM -0400, Steven Rostedt wrote:
> On Fri, 30 May 2014 18:52:47 -0700
> Todd E Brandt <todd.e.brandt@linux.intel.com> wrote:
> 
> > Adds trace events that give finer resolution into suspend/resume. These
> > events are graphed in the timelines generated by the analyze_suspend.py
> > script. They represent large areas of time consumed that are typical to
> > suspend and resume.
> > 
> > The event is triggered by calling the function "trace_suspend_resume"
> > with three arguments: a string (the name of the event to be displayed
> > in the timeline), an integer (case specific number, such as the power
> > state or cpu number), and a boolean (where true is used to denote the start
> > of the timeline event, and false to denote the end).
> > 
> > The suspend_resume trace event reproduces the data that the machine_suspend
> > trace event did, so the latter has been removed.
> > 
> > Signed-off-by: Todd Brandt <todd.e.brandt@intel.com>
> > ----
> >  drivers/acpi/nvs.c           |  7 +++++++
> >  drivers/base/power/main.c    | 16 ++++++++++++++++
> >  drivers/base/syscore.c       |  5 +++++
> >  include/trace/events/power.h | 39 ++++++++++++++++++++++-----------------
> >  kernel/cpu.c                 |  5 +++++
> >  kernel/power/process.c       |  3 +++
> >  kernel/power/suspend.c       | 10 ++++++++--
> >  7 files changed, 66 insertions(+), 19 deletions(-)
> > 
> > v2: May 30, 2014
> >  - changed the suspend_resume prototype to include an integer value, this
> >    is so that it can reproduce the machine_suspend calls as well as provide
> >    cpu number info without code modifications
> >  - kernel/cpu.c calls no longer add sprintf's to the code, it's all contained
> >    in the tracepoint prototype
> >  - removed the machine_suspend trace event prototype
> >  - removed the suspend_resume/acpi_os_sleep trace event per Raphael's advice
> >  - added trace points for all dpm calls in main.c
> >  - this patch now provides all data for analyze_suspend except the initcalls
> > v1: May 19, 2014
> >  - first submission
> > 
> > diff --git a/drivers/acpi/nvs.c b/drivers/acpi/nvs.c
> > index de4fe03..4e7e59f 100644
> > --- a/drivers/acpi/nvs.c
> > +++ b/drivers/acpi/nvs.c
> > @@ -12,6 +12,7 @@
> >  #include <linux/mm.h>
> >  #include <linux/slab.h>
> >  #include <linux/acpi.h>
> > +#include <trace/events/power.h>
> >  
> >  #include "internal.h"
> >  
> > @@ -171,6 +172,7 @@ int suspend_nvs_save(void)
> >  {
> >  	struct nvs_page *entry;
> >  
> > +	trace_suspend_resume("save_nvs_memory", 0, true);
> 
> Hmm, if you want to make this a lot faster and put less on the ring
> buffer, you can just record the pointer.
> 
> But if you want trace-cmd and perf to read it, you need to do what RCU
> did.
> 
> If you look in kernel/rcu/tree.c at its tracepoints, you'll notice it's
> used something like this:
> 
>  trace_rcu_grace_period(TPS("rcu_sched"), rdp->gpnum, TPS("cpuqs"));
> 
> Here, you could do the same thing but with:
> 
>   trace_suspend_resume(TPS("save_nvs_memory"), 0, true);
> 
> But you would still need to define TPS():
> 
> #define TPS(x) tracepoint_string(x)
> 
> This will export the strings into debugfs/tracing/printk_formats so
> that the pointer can be mapped to a string.

ahh, ok, yea if there's some performance impact of using tracepoints this
way then I'll definately change that, thanks for the example.

> 
> This is assuming that all of these calls are in core kernel code and
> not in modules. Are they?

No these are all core code. I double-checked all the Kconfigs to make
sure none of those files are configured by tristate options, they're
all bool. I also test ran a few compiles with CONFIG_PM disabled just
to be sure that nothing broke in kernel/cpu.c and all was well.

> 
> >  	printk(KERN_INFO "PM: Saving platform NVS memory\n");
> >  
> >  	list_for_each_entry(entry, &nvs_list, node)
> > @@ -185,11 +187,14 @@ int suspend_nvs_save(void)
> >  			}
> >  			if (!entry->kaddr) {
> >  				suspend_nvs_free();
> > +				trace_suspend_resume("save_nvs_memory",
> > +					0, false);
> >  				return -ENOMEM;
> >  			}
> 
> 
> 
> >  	TP_PROTO(struct device *dev, const char *pm_ops, s64 ops_time,
> > @@ -151,6 +134,28 @@ TRACE_EVENT(device_pm_report_time,
> >  		__entry->ops_time, __entry->error)
> >  );
> >  
> > +TRACE_EVENT(suspend_resume,
> > +
> > +	TP_PROTO(char *action, int val, bool start),
> 
> Regardless of the tracepoint_string() that should be "const char *action"
> 
> 
> > +
> > +	TP_ARGS(action, val, start),
> > +
> > +	TP_STRUCT__entry(
> > +		__string(action, action)
> 
> You wouldn't need __string(), you could then have:
> 
>    __field(const char *, action)
> 
> 
> > +		__field(int, val)
> > +		__field(bool, start)
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__assign_str(action, action);
> > +		__entry->val = val;
> > +		__entry->start = start;
> > +	),
> > +
> > +	TP_printk("%s[%u] %s", __get_str(action),
> 
> Here you would have:
> 
> 	TP_printk("%s[%u] %s", entry->action,
> 
> You just need to add that TPS() around all strings where it is passed
> to the tracepoint and it will still work with trace-cmd and perf.

Is is legal to pass a format string to a tracepoint which then gets fed
into TP_printk? i.e.

TP_printk(__get_str(fmtstring), __entry->val)

I didn't do that since I couldn't find a single example of that in the other
trace events, but theoretically it should be safe.

> 
> -- Steve
> 
> 
> 
> > +		(unsigned int)__entry->val, (__entry->start)?"begin":"end")
> > +);
> > +
> >  DECLARE_EVENT_CLASS(wakeup_source,
> >  
> >  	TP_PROTO(const char *name, unsigned int state),