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 in suspend and resume.

The event is triggered by calling the function "trace_suspend_resume" with two arguments: a string (the name of the event to be displayed in the timeline), and a boolean (where true is used to denote the start of the timeline event, and false to denote the end).

Signed-off-by Todd Brandt <[email protected]>

---
 drivers/acpi/nvs.c           |  6 ++++++
 drivers/acpi/osl.c           |  3 +++
 drivers/base/syscore.c       |  5 +++++
 include/trace/events/power.h | 19 +++++++++++++++++++
 kernel/cpu.c                 |  9 +++++++++
 kernel/power/process.c       |  3 +++
 kernel/power/suspend.c       |  4 ++++
 7 files changed, 49 insertions(+)

For more info see:
https://01.org/suspendresume/blogs/tebrandt/2014/custom-timeline-event-support-0

I'm also interested to know if any tools depend on the machine_suspend tracepoints, as this patch expands on the same info. I'd be willing to merge the existing machine_suspend calls into this patch and rename everything to suspend_resume provided it doesn't hurt any downstream tools.

drivers/acpi/nvs.c +6 -0

index de4fe03..b52b686 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", true);
 	printk(KERN_INFO "PM: Saving platform NVS memory\n");
 
 	list_for_each_entry(entry, &nvs_list, node)

@@ -185,11 +187,13 @@ int suspend_nvs_save(void)
 			}
 			if (!entry->kaddr) {
 				suspend_nvs_free();
+				trace_suspend_resume("save_nvs_memory", false);
 				return -ENOMEM;
 			}
 			memcpy(entry->data, entry->kaddr, entry->size);
 		}
 
+	trace_suspend_resume("save_nvs_memory", false);
 	return 0;
 }
 

@@ -203,10 +207,12 @@ void suspend_nvs_restore(void)
 {
 	struct nvs_page *entry;
 
+	trace_suspend_resume("restore_nvs_memory", 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", false);
 }
 #endif

drivers/acpi/osl.c +1 -0

index 6776c59..b65a77a 100644
@@ -44,6 +44,7 @@
 #include <linux/list.h>
 #include <linux/jiffies.h>
 #include <linux/semaphore.h>
+#include <trace/events/power.h>
 
 #include <asm/io.h>
 #include <asm/uaccess.h>

drivers/acpi/osl.c +0 -0

 void acpi_os_stall(u32 us)

drivers/base/syscore.c +5 -0

index e8d11b6..c2fd5d4 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", 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", false);
 	return 0;
 
  err_out:

@@ -92,6 +95,7 @@ void syscore_resume(void)
 {
 	struct syscore_ops *ops;
 
+	trace_suspend_resume("syscore_resume", 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", false);
 }
 EXPORT_SYMBOL_GPL(syscore_resume);
 #endif /* CONFIG_PM_SLEEP */

include/trace/events/power.h +19 -0

index 9a7e08d..1d9fd76 100644
@@ -151,6 +151,25 @@ TRACE_EVENT(device_pm_report_time,
 		__entry->ops_time, __entry->error)
 );
 
+TRACE_EVENT(suspend_resume,
+
+	TP_PROTO(char *action, bool start),
+
+	TP_ARGS(action, start),
+
+	TP_STRUCT__entry(
+		__string(action, action)
+		__field(bool, start)
+	),
+
+	TP_fast_assign(
+		__assign_str(action, action);
+		__entry->start = start;
+	),
+
+	TP_printk("%s %s", __get_str(action), (__entry->start)?"begin":"end")
+);
+
 DECLARE_EVENT_CLASS(wakeup_source,
 
 	TP_PROTO(const char *name, unsigned int state),

kernel/cpu.c +9 -0

index a9e710e..7aa30ec 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"
 

@@ -509,6 +510,7 @@ static cpumask_var_t frozen_cpus;
 int disable_nonboot_cpus(void)
 {
 	int cpu, first_cpu, error = 0;
+	char buf[12];
 
 	cpu_maps_update_begin();
 	first_cpu = cpumask_first(cpu_online_mask);

@@ -522,7 +524,10 @@ int disable_nonboot_cpus(void)
 	for_each_online_cpu(cpu) {
 		if (cpu == first_cpu)
 			continue;
+		sprintf(buf, "CPU%u_OFF", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_down(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error)
 			cpumask_set_cpu(cpu, frozen_cpus);
 		else {

@@ -554,6 +559,7 @@ void __weak arch_enable_nonboot_cpus_end(void)
 void __ref enable_nonboot_cpus(void)
 {
 	int cpu, error;
+	char buf[10];
 
 	/* Allow everyone to use the CPU hotplug again */
 	cpu_maps_update_begin();

@@ -566,7 +572,10 @@ void __ref enable_nonboot_cpus(void)
 	arch_enable_nonboot_cpus_begin();
 
 	for_each_cpu(cpu, frozen_cpus) {
+		sprintf(buf, "CPU%u_ON", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_up(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error) {
 			printk(KERN_INFO "CPU%d is up\n", cpu);
 			continue;

kernel/power/process.c +3 -0

index 06ec886..4aec2d9 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", 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", false);
 }
 
 void thaw_kernel_threads(void)

kernel/power/suspend.c +4 -1

index 8233cd4..c7e3e9f 100644
@@ -147,7 +147,9 @@ static int suspend_prepare(suspend_state_t state)
 	if (error)
 		goto Finish;
 
+	trace_suspend_resume("freeze_processes", true);
 	error = suspend_freeze_processes();
+	trace_suspend_resume("freeze_processes", false);
 	if (!error)
 		return 0;
 

@@ -337,9 +339,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_FREEZE)
 		freeze_begin();
 
+	trace_suspend_resume("sync_filesystems", true);
 	printk(KERN_INFO "PM: Syncing filesystems ... ");
 	sys_sync();
 	printk("done.\n");
+	trace_suspend_resume("sync_filesystems", false);
 
 	pr_debug("PM: Preparing system for %s sleep\n", pm_states[state]);
 	error = suspend_prepare(state);
--

To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 90 lines · 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 in suspend and resume.

The event is triggered by calling the function "trace_suspend_resume" with two arguments: a string (the name of the event to be displayed in the timeline), and a boolean (where true is used to denote the start of the timeline event, and false to denote the end).

Signed-off-by Todd Brandt <[email protected]>

---
 drivers/acpi/nvs.c           |  6 ++++++
 drivers/acpi/osl.c           |  3 +++
 drivers/base/syscore.c       |  5 +++++
 include/trace/events/power.h | 19 +++++++++++++++++++
 kernel/cpu.c                 |  9 +++++++++
 kernel/power/process.c       |  3 +++
 kernel/power/suspend.c       |  4 ++++
 7 files changed, 49 insertions(+)

For more info see:
https://01.org/suspendresume/blogs/tebrandt/2014/custom-timeline-event-support-0

I'm also interested to know if any tools depend on the machine_suspend tracepoints, as this patch expands on the same info. I'd be willing to merge the existing machine_suspend calls into this patch and rename everything to suspend_resume provided it doesn't hurt any downstream tools.

drivers/acpi/nvs.c +6 -0

index de4fe03..b52b686 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", true);
 	printk(KERN_INFO "PM: Saving platform NVS memory\n");
 
 	list_for_each_entry(entry, &nvs_list, node)

@@ -185,11 +187,13 @@ int suspend_nvs_save(void)
 			}
 			if (!entry->kaddr) {
 				suspend_nvs_free();
+				trace_suspend_resume("save_nvs_memory", false);
 				return -ENOMEM;
 			}
 			memcpy(entry->data, entry->kaddr, entry->size);
 		}
 
+	trace_suspend_resume("save_nvs_memory", false);
 	return 0;
 }
 

@@ -203,10 +207,12 @@ void suspend_nvs_restore(void)
 {
 	struct nvs_page *entry;
 
+	trace_suspend_resume("restore_nvs_memory", 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", false);
 }
 #endif

drivers/acpi/osl.c +1 -0

index 6776c59..b65a77a 100644
@@ -44,6 +44,7 @@
 #include <linux/list.h>
 #include <linux/jiffies.h>
 #include <linux/semaphore.h>
+#include <trace/events/power.h>
 
 #include <asm/io.h>
 #include <asm/uaccess.h>

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 6 lines

drivers/acpi/osl.c +2 -0

 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

Quoted 184 lines

drivers/acpi/osl.c +0 -0

 void acpi_os_stall(u32 us)

drivers/base/syscore.c +5 -0

index e8d11b6..c2fd5d4 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", 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", false);
 	return 0;
 
  err_out:

@@ -92,6 +95,7 @@ void syscore_resume(void)
 {
 	struct syscore_ops *ops;
 
+	trace_suspend_resume("syscore_resume", 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", false);
 }
 EXPORT_SYMBOL_GPL(syscore_resume);
 #endif /* CONFIG_PM_SLEEP */

include/trace/events/power.h +19 -0

index 9a7e08d..1d9fd76 100644
@@ -151,6 +151,25 @@ TRACE_EVENT(device_pm_report_time,
 		__entry->ops_time, __entry->error)
 );
 
+TRACE_EVENT(suspend_resume,
+
+	TP_PROTO(char *action, bool start),
+
+	TP_ARGS(action, start),
+
+	TP_STRUCT__entry(
+		__string(action, action)
+		__field(bool, start)
+	),
+
+	TP_fast_assign(
+		__assign_str(action, action);
+		__entry->start = start;
+	),
+
+	TP_printk("%s %s", __get_str(action), (__entry->start)?"begin":"end")
+);
+
 DECLARE_EVENT_CLASS(wakeup_source,
 
 	TP_PROTO(const char *name, unsigned int state),

kernel/cpu.c +9 -0

index a9e710e..7aa30ec 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"
 

@@ -509,6 +510,7 @@ static cpumask_var_t frozen_cpus;
 int disable_nonboot_cpus(void)
 {
 	int cpu, first_cpu, error = 0;
+	char buf[12];
 
 	cpu_maps_update_begin();
 	first_cpu = cpumask_first(cpu_online_mask);

@@ -522,7 +524,10 @@ int disable_nonboot_cpus(void)
 	for_each_online_cpu(cpu) {
 		if (cpu == first_cpu)
 			continue;
+		sprintf(buf, "CPU%u_OFF", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_down(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error)
 			cpumask_set_cpu(cpu, frozen_cpus);
 		else {

@@ -554,6 +559,7 @@ void __weak arch_enable_nonboot_cpus_end(void)
 void __ref enable_nonboot_cpus(void)
 {
 	int cpu, error;
+	char buf[10];
 
 	/* Allow everyone to use the CPU hotplug again */
 	cpu_maps_update_begin();

@@ -566,7 +572,10 @@ void __ref enable_nonboot_cpus(void)
 	arch_enable_nonboot_cpus_begin();
 
 	for_each_cpu(cpu, frozen_cpus) {
+		sprintf(buf, "CPU%u_ON", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_up(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error) {
 			printk(KERN_INFO "CPU%d is up\n", cpu);
 			continue;

kernel/power/process.c +3 -0

index 06ec886..4aec2d9 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", 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", false);
 }
 
 void thaw_kernel_threads(void)

kernel/power/suspend.c +4 -1

index 8233cd4..c7e3e9f 100644
@@ -147,7 +147,9 @@ static int suspend_prepare(suspend_state_t state)
 	if (error)
 		goto Finish;
 
+	trace_suspend_resume("freeze_processes", true);
 	error = suspend_freeze_processes();
+	trace_suspend_resume("freeze_processes", false);
 	if (!error)
 		return 0;
 

@@ -337,9 +339,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_FREEZE)
 		freeze_begin();
 
+	trace_suspend_resume("sync_filesystems", true);
 	printk(KERN_INFO "PM: Syncing filesystems ... ");
 	sys_sync();
 	printk("done.\n");
+	trace_suspend_resume("sync_filesystems", false);
 
 	pr_debug("PM: Preparing system for %s sleep\n", pm_states[state]);
 	error = suspend_prepare(state);
--

To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Signature · 2 lines

I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

Quoted 5 lines

Quoted 5 lines

#include <asm/io.h>
#include <asm/uaccess.h>

(quoted diff) +0 -0

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 

Quoted 9 lines

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 6 lines

drivers/acpi/osl.c +2 -0

 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

Yea but it really helps you diagnose bad firmware during suspend/resume (for instance when there's just an arbitrary sleep 100ms in the ACPI code). But it doesn't matter for general performance testing, I'll remove it on v2 submit.

Quoted 4 lines

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

Quoted 21 lines · Todd E Brandt

Quoted 5 lines

Quoted 5 lines

#include <asm/io.h>
#include <asm/uaccess.h>

(quoted diff) +0 -0

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 

Quoted 9 lines

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 6 lines

drivers/acpi/osl.c +2 -0

 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

Yea but it really helps you diagnose bad firmware during suspend/resume (for instance when there's just an arbitrary sleep 100ms in the ACPI code). But it doesn't matter for general performance testing, I'll remove it on v2 submit.

Quoted 1 line

Quoted 3 lines

Quoted 3 lines

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

It should be under an ACPI system (if there is one). Looks rather silly to call it for suspend.

Quoted 22 lines · Steven Rostedt

Quoted 21 lines · Todd E Brandt

Quoted 5 lines

Quoted 5 lines

#include <asm/io.h>
#include <asm/uaccess.h>

(quoted diff) +0 -0

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 

Quoted 9 lines

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 6 lines

drivers/acpi/osl.c +2 -0

 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

Yea but it really helps you diagnose bad firmware during suspend/resume (for instance when there's just an arbitrary sleep 100ms in the ACPI code). But it doesn't matter for general performance testing, I'll remove it on v2 submit.

Quoted 1 line

Quoted 6 lines

Quoted 3 lines

Quoted 3 lines

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

It should be under an ACPI system (if there is one). Looks rather silly to call it for suspend.

I meant the rest of the patch, not this particular hunk. :-)

Rafael

Quoted 89 lines · 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 in suspend and resume.

The event is triggered by calling the function "trace_suspend_resume" with two arguments: a string (the name of the event to be displayed in the timeline), and a boolean (where true is used to denote the start of the timeline event, and false to denote the end).

Signed-off-by Todd Brandt <[email protected]>

---
 drivers/acpi/nvs.c           |  6 ++++++
 drivers/acpi/osl.c           |  3 +++
 drivers/base/syscore.c       |  5 +++++
 include/trace/events/power.h | 19 +++++++++++++++++++
 kernel/cpu.c                 |  9 +++++++++
 kernel/power/process.c       |  3 +++
 kernel/power/suspend.c       |  4 ++++
 7 files changed, 49 insertions(+)

For more info see:
https://01.org/suspendresume/blogs/tebrandt/2014/custom-timeline-event-support-0

I'm also interested to know if any tools depend on the machine_suspend tracepoints, as this patch expands on the same info. I'd be willing to merge the existing machine_suspend calls into this patch and rename everything to suspend_resume provided it doesn't hurt any downstream tools.

drivers/acpi/nvs.c +6 -0

index de4fe03..b52b686 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", true);
 	printk(KERN_INFO "PM: Saving platform NVS memory\n");
 
 	list_for_each_entry(entry, &nvs_list, node)

@@ -185,11 +187,13 @@ int suspend_nvs_save(void)
 			}
 			if (!entry->kaddr) {
 				suspend_nvs_free();
+				trace_suspend_resume("save_nvs_memory", false);
 				return -ENOMEM;
 			}
 			memcpy(entry->data, entry->kaddr, entry->size);
 		}
 
+	trace_suspend_resume("save_nvs_memory", false);
 	return 0;
 }
 

@@ -203,10 +207,12 @@ void suspend_nvs_restore(void)
 {
 	struct nvs_page *entry;
 
+	trace_suspend_resume("restore_nvs_memory", 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", false);
 }
 #endif

drivers/acpi/osl.c +1 -0

index 6776c59..b65a77a 100644
@@ -44,6 +44,7 @@
 #include <linux/list.h>
 #include <linux/jiffies.h>
 #include <linux/semaphore.h>
+#include <trace/events/power.h>
 
 #include <asm/io.h>
 #include <asm/uaccess.h>

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 7 lines

drivers/acpi/osl.c +2 -0

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 
 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

Quoted 180 lines

drivers/acpi/osl.c +0 -0

 void acpi_os_stall(u32 us)

drivers/base/syscore.c +5 -0

index e8d11b6..c2fd5d4 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", 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", false);
 	return 0;
 
  err_out:

@@ -92,6 +95,7 @@ void syscore_resume(void)
 {
 	struct syscore_ops *ops;
 
+	trace_suspend_resume("syscore_resume", 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", false);
 }
 EXPORT_SYMBOL_GPL(syscore_resume);
 #endif /* CONFIG_PM_SLEEP */

include/trace/events/power.h +19 -0

index 9a7e08d..1d9fd76 100644
@@ -151,6 +151,25 @@ TRACE_EVENT(device_pm_report_time,
 		__entry->ops_time, __entry->error)
 );
 
+TRACE_EVENT(suspend_resume,
+
+	TP_PROTO(char *action, bool start),
+
+	TP_ARGS(action, start),
+
+	TP_STRUCT__entry(
+		__string(action, action)
+		__field(bool, start)
+	),
+
+	TP_fast_assign(
+		__assign_str(action, action);
+		__entry->start = start;
+	),
+
+	TP_printk("%s %s", __get_str(action), (__entry->start)?"begin":"end")
+);
+
 DECLARE_EVENT_CLASS(wakeup_source,
 
 	TP_PROTO(const char *name, unsigned int state),

kernel/cpu.c +9 -0

index a9e710e..7aa30ec 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"
 

@@ -509,6 +510,7 @@ static cpumask_var_t frozen_cpus;
 int disable_nonboot_cpus(void)
 {
 	int cpu, first_cpu, error = 0;
+	char buf[12];
 
 	cpu_maps_update_begin();
 	first_cpu = cpumask_first(cpu_online_mask);

@@ -522,7 +524,10 @@ int disable_nonboot_cpus(void)
 	for_each_online_cpu(cpu) {
 		if (cpu == first_cpu)
 			continue;
+		sprintf(buf, "CPU%u_OFF", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_down(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error)
 			cpumask_set_cpu(cpu, frozen_cpus);
 		else {

@@ -554,6 +559,7 @@ void __weak arch_enable_nonboot_cpus_end(void)
 void __ref enable_nonboot_cpus(void)
 {
 	int cpu, error;
+	char buf[10];
 
 	/* Allow everyone to use the CPU hotplug again */
 	cpu_maps_update_begin();

@@ -566,7 +572,10 @@ void __ref enable_nonboot_cpus(void)
 	arch_enable_nonboot_cpus_begin();
 
 	for_each_cpu(cpu, frozen_cpus) {
+		sprintf(buf, "CPU%u_ON", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_up(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error) {
 			printk(KERN_INFO "CPU%d is up\n", cpu);
 			continue;

kernel/power/process.c +3 -0

index 06ec886..4aec2d9 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", 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", false);
 }
 
 void thaw_kernel_threads(void)

kernel/power/suspend.c +4 -0

index 8233cd4..c7e3e9f 100644
@@ -147,7 +147,9 @@ static int suspend_prepare(suspend_state_t state)
 	if (error)
 		goto Finish;
 
+	trace_suspend_resume("freeze_processes", true);
 	error = suspend_freeze_processes();
+	trace_suspend_resume("freeze_processes", false);
 	if (!error)
 		return 0;
 

@@ -337,9 +339,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_FREEZE)
 		freeze_begin();
 
+	trace_suspend_resume("sync_filesystems", true);
 	printk(KERN_INFO "PM: Syncing filesystems ... ");
 	sys_sync();
 	printk("done.\n");
+	trace_suspend_resume("sync_filesystems", false);
 
 	pr_debug("PM: Preparing system for %s sleep\n", pm_states[state]);
 	error = suspend_prepare(state);

Hi Todd,

This might be a silly question, but the suspend_enter() function invokes ftrace_stop() before suspending the machine, and restarts ftrace after resume. And your patch seems to instrument code further down (deeper) in the suspend/resume path (such as disable_nonboot_cpus() for example). Doesn't the ftrace stop/start pose any problem for this patch?

Quoted 7 lines · Srivatsa S. Bhat

Hi Todd,

This might be a silly question, but the suspend_enter() function invokes ftrace_stop() before suspending the machine, and restarts ftrace after resume. And your patch seems to instrument code further down (deeper) in the suspend/resume path (such as disable_nonboot_cpus() for example). Doesn't the ftrace stop/start pose any problem for this patch?

ftrace_start/stop() only affects the function tracer and not the tracepoints. Those will still be recorded.

Note, we have an invested interest in getting rid of ftrace_stop/start(). I rather mark all the suspend code with notrace or find another method to protect suspend from function tracing. The ftrace_stop/start() was more of a big hammer approach and I had plans for getting rid of it in the future. That future is approaching fast :-)

Quoted 101 lines · Rafael J. Wysocki

Quoted 89 lines · 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 in suspend and resume.

The event is triggered by calling the function "trace_suspend_resume" with two arguments: a string (the name of the event to be displayed in the timeline), and a boolean (where true is used to denote the start of the timeline event, and false to denote the end).

Signed-off-by Todd Brandt <[email protected]>

---
 drivers/acpi/nvs.c           |  6 ++++++
 drivers/acpi/osl.c           |  3 +++
 drivers/base/syscore.c       |  5 +++++
 include/trace/events/power.h | 19 +++++++++++++++++++
 kernel/cpu.c                 |  9 +++++++++
 kernel/power/process.c       |  3 +++
 kernel/power/suspend.c       |  4 ++++
 7 files changed, 49 insertions(+)

For more info see:
https://01.org/suspendresume/blogs/tebrandt/2014/custom-timeline-event-support-0

I'm also interested to know if any tools depend on the machine_suspend tracepoints, as this patch expands on the same info. I'd be willing to merge the existing machine_suspend calls into this patch and rename everything to suspend_resume provided it doesn't hurt any downstream tools.

drivers/acpi/nvs.c +6 -0

index de4fe03..b52b686 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", true);
 	printk(KERN_INFO "PM: Saving platform NVS memory\n");
 
 	list_for_each_entry(entry, &nvs_list, node)

@@ -185,11 +187,13 @@ int suspend_nvs_save(void)
 			}
 			if (!entry->kaddr) {
 				suspend_nvs_free();
+				trace_suspend_resume("save_nvs_memory", false);
 				return -ENOMEM;
 			}
 			memcpy(entry->data, entry->kaddr, entry->size);
 		}
 
+	trace_suspend_resume("save_nvs_memory", false);
 	return 0;
 }
 

@@ -203,10 +207,12 @@ void suspend_nvs_restore(void)
 {
 	struct nvs_page *entry;
 
+	trace_suspend_resume("restore_nvs_memory", 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", false);
 }
 #endif

drivers/acpi/osl.c +1 -0

index 6776c59..b65a77a 100644
@@ -44,6 +44,7 @@
 #include <linux/list.h>
 #include <linux/jiffies.h>
 #include <linux/semaphore.h>
+#include <trace/events/power.h>
 
 #include <asm/io.h>
 #include <asm/uaccess.h>

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 7 lines

drivers/acpi/osl.c +2 -0

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 
 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

Quoted 4 lines

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

Hi Todd,

This might be a silly question, but the suspend_enter() function invokes ftrace_stop() before suspending the machine, and restarts ftrace after resume. And your patch seems to instrument code further down (deeper) in the suspend/resume path (such as disable_nonboot_cpus() for example). Doesn't the ftrace stop/start pose any problem for this patch?

Regards,
Srivatsa S. Bhat

Quoted 180 lines

Quoted 180 lines

drivers/acpi/osl.c +0 -0

 void acpi_os_stall(u32 us)

drivers/base/syscore.c +5 -0

index e8d11b6..c2fd5d4 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", 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", false);
 	return 0;
 
  err_out:

@@ -92,6 +95,7 @@ void syscore_resume(void)
 {
 	struct syscore_ops *ops;
 
+	trace_suspend_resume("syscore_resume", 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", false);
 }
 EXPORT_SYMBOL_GPL(syscore_resume);
 #endif /* CONFIG_PM_SLEEP */

include/trace/events/power.h +19 -0

index 9a7e08d..1d9fd76 100644
@@ -151,6 +151,25 @@ TRACE_EVENT(device_pm_report_time,
 		__entry->ops_time, __entry->error)
 );
 
+TRACE_EVENT(suspend_resume,
+
+	TP_PROTO(char *action, bool start),
+
+	TP_ARGS(action, start),
+
+	TP_STRUCT__entry(
+		__string(action, action)
+		__field(bool, start)
+	),
+
+	TP_fast_assign(
+		__assign_str(action, action);
+		__entry->start = start;
+	),
+
+	TP_printk("%s %s", __get_str(action), (__entry->start)?"begin":"end")
+);
+
 DECLARE_EVENT_CLASS(wakeup_source,
 
 	TP_PROTO(const char *name, unsigned int state),

kernel/cpu.c +9 -0

index a9e710e..7aa30ec 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"
 

@@ -509,6 +510,7 @@ static cpumask_var_t frozen_cpus;
 int disable_nonboot_cpus(void)
 {
 	int cpu, first_cpu, error = 0;
+	char buf[12];
 
 	cpu_maps_update_begin();
 	first_cpu = cpumask_first(cpu_online_mask);

@@ -522,7 +524,10 @@ int disable_nonboot_cpus(void)
 	for_each_online_cpu(cpu) {
 		if (cpu == first_cpu)
 			continue;
+		sprintf(buf, "CPU%u_OFF", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_down(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error)
 			cpumask_set_cpu(cpu, frozen_cpus);
 		else {

@@ -554,6 +559,7 @@ void __weak arch_enable_nonboot_cpus_end(void)
 void __ref enable_nonboot_cpus(void)
 {
 	int cpu, error;
+	char buf[10];
 
 	/* Allow everyone to use the CPU hotplug again */
 	cpu_maps_update_begin();

@@ -566,7 +572,10 @@ void __ref enable_nonboot_cpus(void)
 	arch_enable_nonboot_cpus_begin();
 
 	for_each_cpu(cpu, frozen_cpus) {
+		sprintf(buf, "CPU%u_ON", cpu);
+		trace_suspend_resume(buf, true);
 		error = _cpu_up(cpu, 1);
+		trace_suspend_resume(buf, false);
 		if (!error) {
 			printk(KERN_INFO "CPU%d is up\n", cpu);
 			continue;

kernel/power/process.c +3 -0

index 06ec886..4aec2d9 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", 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", false);
 }
 
 void thaw_kernel_threads(void)

kernel/power/suspend.c +4 -0

index 8233cd4..c7e3e9f 100644
@@ -147,7 +147,9 @@ static int suspend_prepare(suspend_state_t state)
 	if (error)
 		goto Finish;
 
+	trace_suspend_resume("freeze_processes", true);
 	error = suspend_freeze_processes();
+	trace_suspend_resume("freeze_processes", false);
 	if (!error)
 		return 0;
 

@@ -337,9 +339,11 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_FREEZE)
 		freeze_begin();
 
+	trace_suspend_resume("sync_filesystems", true);
 	printk(KERN_INFO "PM: Syncing filesystems ... ");
 	sys_sync();
 	printk("done.\n");
+	trace_suspend_resume("sync_filesystems", false);
 
 	pr_debug("PM: Preparing system for %s sleep\n", pm_states[state]);
 	error = suspend_prepare(state);

Quoted 107 lines · Srivatsa S. Bhat

Quoted 101 lines · Rafael J. Wysocki

Quoted 89 lines · 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 in suspend and resume.

The event is triggered by calling the function "trace_suspend_resume" with two arguments: a string (the name of the event to be displayed in the timeline), and a boolean (where true is used to denote the start of the timeline event, and false to denote the end).

Signed-off-by Todd Brandt <[email protected]>

---
 drivers/acpi/nvs.c           |  6 ++++++
 drivers/acpi/osl.c           |  3 +++
 drivers/base/syscore.c       |  5 +++++
 include/trace/events/power.h | 19 +++++++++++++++++++
 kernel/cpu.c                 |  9 +++++++++
 kernel/power/process.c       |  3 +++
 kernel/power/suspend.c       |  4 ++++
 7 files changed, 49 insertions(+)

For more info see:
https://01.org/suspendresume/blogs/tebrandt/2014/custom-timeline-event-support-0

I'm also interested to know if any tools depend on the machine_suspend tracepoints, as this patch expands on the same info. I'd be willing to merge the existing machine_suspend calls into this patch and rename everything to suspend_resume provided it doesn't hurt any downstream tools.

drivers/acpi/nvs.c +6 -0

index de4fe03..b52b686 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", true);
 	printk(KERN_INFO "PM: Saving platform NVS memory\n");
 
 	list_for_each_entry(entry, &nvs_list, node)

@@ -185,11 +187,13 @@ int suspend_nvs_save(void)
 			}
 			if (!entry->kaddr) {
 				suspend_nvs_free();
+				trace_suspend_resume("save_nvs_memory", false);
 				return -ENOMEM;
 			}
 			memcpy(entry->data, entry->kaddr, entry->size);
 		}
 
+	trace_suspend_resume("save_nvs_memory", false);
 	return 0;
 }
 

@@ -203,10 +207,12 @@ void suspend_nvs_restore(void)
 {
 	struct nvs_page *entry;
 
+	trace_suspend_resume("restore_nvs_memory", 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", false);
 }
 #endif

drivers/acpi/osl.c +1 -0

index 6776c59..b65a77a 100644
@@ -44,6 +44,7 @@
 #include <linux/list.h>
 #include <linux/jiffies.h>
 #include <linux/semaphore.h>
+#include <trace/events/power.h>
 
 #include <asm/io.h>
 #include <asm/uaccess.h>

drivers/acpi/osl.c acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler) · line 842

Quoted 7 lines

drivers/acpi/osl.c +2 -0

@@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
 
 void acpi_os_sleep(u64 ms)
 {
+	trace_suspend_resume("acpi_os_sleep", true);
 	msleep(ms);
+	trace_suspend_resume("acpi_os_sleep", false);
 }

This function doesn't have anything to do with system suspend/resume. It is for waiting. :-)

Quoted 4 lines

The rest of the patch looks OK to me.

Steven, what about the tracing angle?

Quoted 7 lines

Hi Todd,

This might be a silly question, but the suspend_enter() function invokes ftrace_stop() before suspending the machine, and restarts ftrace after resume. And your patch seems to instrument code further down (deeper) in the suspend/resume path (such as disable_nonboot_cpus() for example). Doesn't the ftrace stop/start pose any problem for this patch?

I put a patch in the kernel a few months back that allowed ftrace to function all the way through to disable/enable_nonboot_cpus. So the actual trace code includes everything up to the actual CPU suspend/resume. And also (as Steven mentioned), the tracepoint activity isn't controlled via ftrace_start/ftrace_stop, those are for tracer based logging.