PM: trace events for suspend/resume

PATCH Superseded Todd E Brandt 2 participants 6 messages May 31, 2014 – Jun 6, 2014

Subsystems (7)

ACPI Tracing Driver core Suspend to RAM +3 more subsystems

lore

Share & tools

lore

Todd E Brandt

author

2014-05-31 01:52 UTC #0 lore raw

PATCH v2 1/1 PM: trace events for suspend/resume

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 <[email protected]>

----

 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

drivers/acpi/nvs.c +7 -0

index de4fe03..4e7e59f 100644
@@ -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

drivers/base/power/main.c +16 -0

index 86d5e4f..2d66cd0 100644
@@ -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;
 }

drivers/base/syscore.c +5 -0

index e8d11b6..8cd1d6e 100644
@@ -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 */

include/trace/events/power.h +22 ~~-17~~

index 9a7e08d..2cafb43 100644
@@ -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),

kernel/cpu.c +5 -0

index a9e710e..f3688a4 100644
@@ -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;

kernel/power/process.c +3 -0

index 06ec886..fc60619 100644
@@ -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)

kernel/power/suspend.c +8 -2

index 8233cd4..c216fbf 100644
@@ -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);

Steven Rostedt

maintainer

2014-05-31 02:33 UTC #1 lore raw

Quoted 51 lines · On Fri, 30 May 2014 18:52:47 -0700 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 <[email protected]>
----
 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
drivers/acpi/nvs.c +1 -0
index de4fe03..4e7e59f 100644
@@ -12,6 +12,7 @@
 #include <linux/mm.h>
 #include <linux/slab.h>
 #include <linux/acpi.h>
+#include <trace/events/power.h>
 
 #include "internal.h"
 

drivers/acpi/nvs.c int suspend_nvs_save(void) · line 175

Quoted 4 lines

drivers/acpi/nvs.c +1 -0

@@ -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?

Quoted 16 lines

drivers/acpi/nvs.c +2 -0

 	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,

drivers/acpi/nvs.c TRACE_EVENT(device_pm_report_time, · line 139

Quoted 6 lines

drivers/acpi/nvs.c +3 -0

@@ -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"

drivers/acpi/nvs.c TRACE_EVENT(device_pm_report_time, · line 144

Quoted 5 lines

drivers/acpi/nvs.c +5 -0

+
+	TP_ARGS(action, val, start),
+
+	TP_STRUCT__entry(
+		__string(action, action)

You wouldn't need __string(), you could then have:

__field(const char *, action)

drivers/acpi/nvs.c TRACE_EVENT(device_pm_report_time, · line 155

Quoted 11 lines

drivers/acpi/nvs.c +11 -0

+		__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

Quoted 6 lines

drivers/acpi/nvs.c +3 -0

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

Steven Rostedt

maintainer

2014-05-31 02:36 UTC #2 lore raw

Quoted 3 lines · On Fri, 30 May 2014 22:33:49 -0400 Steven Rostedt <[email protected]> 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

Todd E Brandt

author

2014-05-31 02:58 UTC #3 lore raw

In reply to Steven Rostedt

Quoted 72 lines · Steven Rostedt

Quoted 51 lines · On Fri, 30 May 2014 18:52:47 -0700 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 <[email protected]>
----
 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
drivers/acpi/nvs.c +1 -0
index de4fe03..4e7e59f 100644
@@ -12,6 +12,7 @@
 #include <linux/mm.h>
 #include <linux/slab.h>
 #include <linux/acpi.h>
+#include <trace/events/power.h>
 
 #include "internal.h"
 
drivers/acpi/nvs.c int suspend_nvs_save(void) · line 175
Quoted 4 lines
drivers/acpi/nvs.c +1 -0
@@ -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:

Quoted 8 lines

  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.

Quoted 3 lines

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.

Quoted 52 lines

Quoted 17 lines
drivers/acpi/nvs.c +2 -0
 	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,
drivers/acpi/nvs.c TRACE_EVENT(device_pm_report_time, · line 139
Quoted 6 lines
drivers/acpi/nvs.c +3 -0
@@ -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"
drivers/acpi/nvs.c TRACE_EVENT(device_pm_report_time, · line 144
Quoted 5 lines
drivers/acpi/nvs.c +5 -0
+
+	TP_ARGS(action, val, start),
+
+	TP_STRUCT__entry(
+		__string(action, action)
You wouldn't need __string(), you could then have:
__field(const char *, action)
drivers/acpi/nvs.c TRACE_EVENT(device_pm_report_time, · line 155
Quoted 11 lines
drivers/acpi/nvs.c +11 -0
+		__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:

Quoted 4 lines

	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.

Quoted 11 lines

-- Steve

Quoted 6 lines

drivers/acpi/nvs.c +3 -0

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

Steven Rostedt

maintainer

2014-05-31 03:07 UTC #4 lore raw

Quoted 5 lines · On Fri, 30 May 2014 19:58:52 -0700 Todd E Brandt…

Quoted 2 lines
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.

Quoted 9 lines

Quoted 4 lines
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.

Quoted 7 lines

Quoted 6 lines
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.

Quoted 7 lines

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

Todd E Brandt

author

2014-06-06 06:46 UTC #5 lore raw

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.

Quoted 47 lines · Steven Rostedt

Quoted 5 lines · On Fri, 30 May 2014 19:58:52 -0700 Todd E Brandt…
Quoted 2 lines
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.
Quoted 9 lines
Quoted 4 lines
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.
Quoted 7 lines
Quoted 6 lines
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.
Quoted 7 lines
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