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

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

[Todd E Brandt]

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);
 	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;
 			}
 			memcpy(entry->data, entry->kaddr, entry->size);
 		}
 
+	trace_suspend_resume("save_nvs_memory", 0, false);
 	return 0;
 }
 
@@ -203,10 +208,12 @@ void suspend_nvs_restore(void)
 {
 	struct nvs_page *entry;
 
+	trace_suspend_resume("restore_nvs_memory", 0, true);
 	printk(KERN_INFO "PM: Restoring platform NVS memory\n");
 
 	list_for_each_entry(entry, &nvs_list, node)
 		if (entry->data)
 			memcpy(entry->kaddr, entry->data, entry->size);
+	trace_suspend_resume("restore_nvs_memory", 0, false);
 }
 #endif
diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 86d5e4f..2d66cd0 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -545,6 +545,7 @@ static void dpm_resume_noirq(pm_message_t state)
 	struct device *dev;
 	ktime_t starttime = ktime_get();
 
+	trace_suspend_resume("dpm_resume_noirq", state.event, true);
 	mutex_lock(&dpm_list_mtx);
 	pm_transition = state;
 
@@ -587,6 +588,7 @@ static void dpm_resume_noirq(pm_message_t state)
 	dpm_show_time(starttime, state, "noirq");
 	resume_device_irqs();
 	cpuidle_resume();
+	trace_suspend_resume("dpm_resume_noirq", state.event, false);
 }
 
 /**
@@ -664,6 +666,7 @@ static void dpm_resume_early(pm_message_t state)
 	struct device *dev;
 	ktime_t starttime = ktime_get();
 
+	trace_suspend_resume("dpm_resume_early", state.event, true);
 	mutex_lock(&dpm_list_mtx);
 	pm_transition = state;
 
@@ -703,6 +706,7 @@ static void dpm_resume_early(pm_message_t state)
 	mutex_unlock(&dpm_list_mtx);
 	async_synchronize_full();
 	dpm_show_time(starttime, state, "early");
+	trace_suspend_resume("dpm_resume_early", state.event, false);
 }
 
 /**
@@ -828,6 +832,7 @@ void dpm_resume(pm_message_t state)
 	struct device *dev;
 	ktime_t starttime = ktime_get();
 
+	trace_suspend_resume("dpm_resume", state.event, true);
 	might_sleep();
 
 	mutex_lock(&dpm_list_mtx);
@@ -869,6 +874,7 @@ void dpm_resume(pm_message_t state)
 	dpm_show_time(starttime, state, NULL);
 
 	cpufreq_resume();
+	trace_suspend_resume("dpm_resume", state.event, false);
 }
 
 /**
@@ -926,6 +932,7 @@ void dpm_complete(pm_message_t state)
 {
 	struct list_head list;
 
+	trace_suspend_resume("dpm_complete", state.event, true);
 	might_sleep();
 
 	INIT_LIST_HEAD(&list);
@@ -945,6 +952,7 @@ void dpm_complete(pm_message_t state)
 	}
 	list_splice(&list, &dpm_list);
 	mutex_unlock(&dpm_list_mtx);
+	trace_suspend_resume("dpm_complete", state.event, false);
 }
 
 /**
@@ -1080,6 +1088,7 @@ static int dpm_suspend_noirq(pm_message_t state)
 	ktime_t starttime = ktime_get();
 	int error = 0;
 
+	trace_suspend_resume("dpm_suspend_noirq", state.event, true);
 	cpuidle_pause();
 	suspend_device_irqs();
 	mutex_lock(&dpm_list_mtx);
@@ -1120,6 +1129,7 @@ static int dpm_suspend_noirq(pm_message_t state)
 	} else {
 		dpm_show_time(starttime, state, "noirq");
 	}
+	trace_suspend_resume("dpm_suspend_noirq", state.event, false);
 	return error;
 }
 
@@ -1216,6 +1226,7 @@ static int dpm_suspend_late(pm_message_t state)
 	ktime_t starttime = ktime_get();
 	int error = 0;
 
+	trace_suspend_resume("dpm_suspend_late", state.event, true);
 	mutex_lock(&dpm_list_mtx);
 	pm_transition = state;
 	async_error = 0;
@@ -1251,6 +1262,7 @@ static int dpm_suspend_late(pm_message_t state)
 	} else {
 		dpm_show_time(starttime, state, "late");
 	}
+	trace_suspend_resume("dpm_suspend_late", state.event, false);
 	return error;
 }
 
@@ -1435,6 +1447,7 @@ int dpm_suspend(pm_message_t state)
 	ktime_t starttime = ktime_get();
 	int error = 0;
 
+	trace_suspend_resume("dpm_suspend", state.event, true);
 	might_sleep();
 
 	cpufreq_suspend();
@@ -1472,6 +1485,7 @@ int dpm_suspend(pm_message_t state)
 		dpm_save_failed_step(SUSPEND_SUSPEND);
 	} else
 		dpm_show_time(starttime, state, NULL);
+	trace_suspend_resume("dpm_suspend", state.event, false);
 	return error;
 }
 
@@ -1546,6 +1560,7 @@ int dpm_prepare(pm_message_t state)
 {
 	int error = 0;
 
+	trace_suspend_resume("dpm_prepare", state.event, true);
 	might_sleep();
 
 	mutex_lock(&dpm_list_mtx);
@@ -1576,6 +1591,7 @@ int dpm_prepare(pm_message_t state)
 		put_device(dev);
 	}
 	mutex_unlock(&dpm_list_mtx);
+	trace_suspend_resume("dpm_prepare", state.event, false);
 	return error;
 }
 
diff --git a/drivers/base/syscore.c b/drivers/base/syscore.c
index e8d11b6..8cd1d6e 100644
--- a/drivers/base/syscore.c
+++ b/drivers/base/syscore.c
@@ -10,6 +10,7 @@
 #include <linux/mutex.h>
 #include <linux/module.h>
 #include <linux/interrupt.h>
+#include <trace/events/power.h>
 
 static LIST_HEAD(syscore_ops_list);
 static DEFINE_MUTEX(syscore_ops_lock);
@@ -49,6 +50,7 @@ int syscore_suspend(void)
 	struct syscore_ops *ops;
 	int ret = 0;
 
+	trace_suspend_resume("syscore_suspend", 0, true);
 	pr_debug("Checking wakeup interrupts\n");
 
 	/* Return error code if there are any wakeup interrupts pending. */
@@ -70,6 +72,7 @@ int syscore_suspend(void)
 				"Interrupts enabled after %pF\n", ops->suspend);
 		}
 
+	trace_suspend_resume("syscore_suspend", 0, false);
 	return 0;
 
  err_out:
@@ -92,6 +95,7 @@ void syscore_resume(void)
 {
 	struct syscore_ops *ops;
 
+	trace_suspend_resume("syscore_resume", 0, true);
 	WARN_ONCE(!irqs_disabled(),
 		"Interrupts enabled before system core resume.\n");
 
@@ -103,6 +107,7 @@ void syscore_resume(void)
 			WARN_ONCE(!irqs_disabled(),
 				"Interrupts enabled after %pF\n", ops->resume);
 		}
+	trace_suspend_resume("syscore_resume", 0, false);
 }
 EXPORT_SYMBOL_GPL(syscore_resume);
 #endif /* CONFIG_PM_SLEEP */
diff --git a/include/trace/events/power.h b/include/trace/events/power.h
index 9a7e08d..2cafb43 100644
--- a/include/trace/events/power.h
+++ b/include/trace/events/power.h
@@ -97,23 +97,6 @@ DEFINE_EVENT(cpu, cpu_frequency,
 	TP_ARGS(frequency, cpu_id)
 );
 
-TRACE_EVENT(machine_suspend,
-
-	TP_PROTO(unsigned int state),
-
-	TP_ARGS(state),
-
-	TP_STRUCT__entry(
-		__field(	u32,		state		)
-	),
-
-	TP_fast_assign(
-		__entry->state = state;
-	),
-
-	TP_printk("state=%lu", (unsigned long)__entry->state)
-);
-
 TRACE_EVENT(device_pm_report_time,
 
 	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),
+
+	TP_ARGS(action, val, start),
+
+	TP_STRUCT__entry(
+		__string(action, 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),
+		(unsigned int)__entry->val, (__entry->start)?"begin":"end")
+);
+
 DECLARE_EVENT_CLASS(wakeup_source,
 
 	TP_PROTO(const char *name, unsigned int state),
diff --git a/kernel/cpu.c b/kernel/cpu.c
index a9e710e..f3688a4 100644
--- a/kernel/cpu.c
+++ b/kernel/cpu.c
@@ -20,6 +20,7 @@
 #include <linux/gfp.h>
 #include <linux/suspend.h>
 #include <linux/lockdep.h>
+#include <trace/events/power.h>
 
 #include "smpboot.h"
 
@@ -522,7 +523,9 @@ int disable_nonboot_cpus(void)
 	for_each_online_cpu(cpu) {
 		if (cpu == first_cpu)
 			continue;
+		trace_suspend_resume("CPU_OFF", cpu, true);
 		error = _cpu_down(cpu, 1);
+		trace_suspend_resume("CPU_OFF", cpu, false);
 		if (!error)
 			cpumask_set_cpu(cpu, frozen_cpus);
 		else {
@@ -566,7 +569,9 @@ void __ref enable_nonboot_cpus(void)
 	arch_enable_nonboot_cpus_begin();
 
 	for_each_cpu(cpu, frozen_cpus) {
+		trace_suspend_resume("CPU_ON", cpu, true);
 		error = _cpu_up(cpu, 1);
+		trace_suspend_resume("CPU_ON", cpu, false);
 		if (!error) {
 			printk(KERN_INFO "CPU%d is up\n", cpu);
 			continue;
diff --git a/kernel/power/process.c b/kernel/power/process.c
index 06ec886..fc60619 100644
--- a/kernel/power/process.c
+++ b/kernel/power/process.c
@@ -17,6 +17,7 @@
 #include <linux/delay.h>
 #include <linux/workqueue.h>
 #include <linux/kmod.h>
+#include <trace/events/power.h>
 
 /* 
  * Timeout for stopping processes
@@ -175,6 +176,7 @@ void thaw_processes(void)
 	struct task_struct *g, *p;
 	struct task_struct *curr = current;
 
+	trace_suspend_resume("thaw_processes", 0, true);
 	if (pm_freezing)
 		atomic_dec(&system_freezing_cnt);
 	pm_freezing = false;
@@ -201,6 +203,7 @@ void thaw_processes(void)
 
 	schedule();
 	printk("done.\n");
+	trace_suspend_resume("thaw_processes", 0, false);
 }
 
 void thaw_kernel_threads(void)
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 8233cd4..c216fbf 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -147,7 +147,9 @@ static int suspend_prepare(suspend_state_t state)
 	if (error)
 		goto Finish;
 
+	trace_suspend_resume("freeze_processes", 0, true);
 	error = suspend_freeze_processes();
+	trace_suspend_resume("freeze_processes", 0, false);
 	if (!error)
 		return 0;
 
@@ -264,7 +266,7 @@ int suspend_devices_and_enter(suspend_state_t state)
 	if (need_suspend_ops(state) && !suspend_ops)
 		return -ENOSYS;
 
-	trace_machine_suspend(state);
+	trace_suspend_resume("machine_suspend", state, true);
 	if (need_suspend_ops(state) && suspend_ops->begin) {
 		error = suspend_ops->begin(state);
 		if (error)
@@ -294,7 +296,7 @@ int suspend_devices_and_enter(suspend_state_t state)
  Close:
 	if (need_suspend_ops(state) && suspend_ops->end)
 		suspend_ops->end();
-	trace_machine_suspend(PWR_EVENT_EXIT);
+	trace_suspend_resume("machine_suspend", state, false);
 	return error;
 
  Recover_platform:
@@ -328,6 +330,7 @@ static int enter_state(suspend_state_t state)
 {
 	int error;
 
+	trace_suspend_resume("suspend_enter", state, true);
 	if (!valid_state(state))
 		return -ENODEV;
 
@@ -337,9 +340,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_FREEZE)
 		freeze_begin();
 
+	trace_suspend_resume("sync_filesystems", 0, true);
 	printk(KERN_INFO "PM: Syncing filesystems ... ");
 	sys_sync();
 	printk("done.\n");
+	trace_suspend_resume("sync_filesystems", 0, false);
 
 	pr_debug("PM: Preparing system for %s sleep\n", pm_states[state]);
 	error = suspend_prepare(state);
@@ -349,6 +354,7 @@ static int enter_state(suspend_state_t state)
 	if (suspend_test(TEST_FREEZER))
 		goto Finish;
 
+	trace_suspend_resume("suspend_enter", state, false);
 	pr_debug("PM: Entering %s sleep\n", pm_states[state]);
 	pm_restrict_gfp_mask();
 	error = suspend_devices_and_enter(state);

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

[Steven Rostedt]

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.

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

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

-- Steve



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

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

[Steven Rostedt]

On Fri, 30 May 2014 22:33:49 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

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

Reading my comment I wrote about tracepoint_string(), it's OK to be
used even with modules. As long as the strings don't change while the
module is loaded (seems to be the case for all strings here).

-- Steve

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

[Todd E Brandt]

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),

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

[Steven Rostedt]

On Fri, 30 May 2014 19:58:52 -0700
Todd E Brandt <todd.e.brandt@linux.intel.com> wrote:


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

It speeds up the tracing and compacts it a bit. It has no affect when
tracing is disabled.

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

After checking, it didn't really matter if they were used by modules or
not. Just that their strings were all constants.
 
> > 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.

Hmm, was there an example where you wanted that? That's not what I was
suggesting. It may work for a tracepoint, but it will definitely screw
up trace-cmd and perf.

-- Steve

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

[Todd E Brandt]

Upon further reflection I think I want to keep the trace point
as it is: a basic const char string without relying on TPS. Trace 
processing time isn't an issue since each of those is called at 
maximum once per suspend/resume. Also, I'm trying to encourage 
people to add additional instances of suspend_resume trace calls 
to further customize their own analyzesuspend testing (and
having to go through and update the TPS string table each time
makes things alot harder to work with). i.e. it's not really
a fixed table, it's meant to be customizeable.

I think I'll also break out the tracepoint into two versions, one for
cpu trace and one for everything else, that way it will always just
be two args.

On Fri, May 30, 2014 at 11:07:45PM -0400, Steven Rostedt wrote:
> On Fri, 30 May 2014 19:58:52 -0700
> Todd E Brandt <todd.e.brandt@linux.intel.com> wrote:
> 
> 
> > > 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.
> 
> It speeds up the tracing and compacts it a bit. It has no affect when
> tracing is disabled.
> 
> > 
> > > 
> > > 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.
> 
> After checking, it didn't really matter if they were used by modules or
> not. Just that their strings were all constants.
>  
> > > 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.
> 
> Hmm, was there an example where you wanted that? That's not what I was
> suggesting. It may work for a tracepoint, but it will definitely screw
> up trace-cmd and perf.
> 
> -- Steve
>