From mboxrd@z Thu Jan 1 00:00:00 1970 From: Todd E Brandt Subject: Re: [PATCH v2] PM: trace events for suspend/resume Date: Fri, 30 May 2014 19:58:52 -0700 Message-ID: <20140531025852.GA24238@linux.intel.com> References: <20140531015247.GA27737@linux.intel.com> <20140530223349.5f33b0fd@gandalf.local.home> Reply-To: todd.e.brandt@linux.intel.com Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Return-path: Received: from mga02.intel.com ([134.134.136.20]:15583 "EHLO mga02.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932229AbaEaC6w (ORCPT ); Fri, 30 May 2014 22:58:52 -0400 Content-Disposition: inline In-Reply-To: <20140530223349.5f33b0fd@gandalf.local.home> Sender: linux-pm-owner@vger.kernel.org List-Id: linux-pm@vger.kernel.org To: Steven Rostedt Cc: linux-pm@vger.kernel.org, rafael.j.wysocki@intel.com, rjw@rjwysocki.net 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 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 > > ---- > > 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 > > #include > > #include > > +#include > > > > #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),