Commit bb3632c6 authored by Todd E Brandt's avatar Todd E Brandt Committed by Rafael J. Wysocki
Browse files

PM / sleep: 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: default avatarTodd Brandt <todd.e.brandt@intel.com>
Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
Signed-off-by: default avatarRafael J. Wysocki <rafael.j.wysocki@intel.com>
parent 3eba148d

drivers/acpi/sleep.c

+3 −0
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ 
#include <linux/acpi.h>

#include <linux/module.h>

#include <asm/io.h>

#include <trace/events/power.h>



#include "internal.h"

#include "sleep.h"
@@ -501,6 +502,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state) 


	ACPI_FLUSH_CPU_CACHE();



	trace_suspend_resume(TPS("acpi_suspend"), acpi_state, true);

	switch (acpi_state) {

	case ACPI_STATE_S1:

		barrier();
@@ -516,6 +518,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state) 
		pr_info(PREFIX "Low-level resume complete\n");

		break;

	}

	trace_suspend_resume(TPS("acpi_suspend"), acpi_state, false);



	/* This violates the spec but is required for bug compatibility. */

	acpi_write_bit_register(ACPI_BITREG_SCI_ENABLE, 1);

drivers/base/power/main.c

+16 −0
Original line number Diff line number Diff line
@@ -545,6 +545,7 @@ static void dpm_resume_noirq(pm_message_t state) 
	struct device *dev;

	ktime_t starttime = ktime_get();



	trace_suspend_resume(TPS("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(TPS("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(TPS("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(TPS("dpm_resume_early"), state.event, false);

}



/**
@@ -834,6 +838,7 @@ void dpm_resume(pm_message_t state) 
	struct device *dev;

	ktime_t starttime = ktime_get();



	trace_suspend_resume(TPS("dpm_resume"), state.event, true);

	might_sleep();



	mutex_lock(&dpm_list_mtx);
@@ -875,6 +880,7 @@ void dpm_resume(pm_message_t state) 
	dpm_show_time(starttime, state, NULL);



	cpufreq_resume();

	trace_suspend_resume(TPS("dpm_resume"), state.event, false);

}



/**
@@ -932,6 +938,7 @@ void dpm_complete(pm_message_t state) 
{

	struct list_head list;



	trace_suspend_resume(TPS("dpm_complete"), state.event, true);

	might_sleep();



	INIT_LIST_HEAD(&list);
@@ -951,6 +958,7 @@ void dpm_complete(pm_message_t state) 
	}

	list_splice(&list, &dpm_list);

	mutex_unlock(&dpm_list_mtx);

	trace_suspend_resume(TPS("dpm_complete"), state.event, false);

}



/**
@@ -1086,6 +1094,7 @@ static int dpm_suspend_noirq(pm_message_t state) 
	ktime_t starttime = ktime_get();

	int error = 0;



	trace_suspend_resume(TPS("dpm_suspend_noirq"), state.event, true);

	cpuidle_pause();

	suspend_device_irqs();

	mutex_lock(&dpm_list_mtx);
@@ -1126,6 +1135,7 @@ static int dpm_suspend_noirq(pm_message_t state) 
	} else {

		dpm_show_time(starttime, state, "noirq");

	}

	trace_suspend_resume(TPS("dpm_suspend_noirq"), state.event, false);

	return error;

}
@@ -1222,6 +1232,7 @@ static int dpm_suspend_late(pm_message_t state) 
	ktime_t starttime = ktime_get();

	int error = 0;



	trace_suspend_resume(TPS("dpm_suspend_late"), state.event, true);

	mutex_lock(&dpm_list_mtx);

	pm_transition = state;

	async_error = 0;
@@ -1257,6 +1268,7 @@ static int dpm_suspend_late(pm_message_t state) 
	} else {

		dpm_show_time(starttime, state, "late");

	}

	trace_suspend_resume(TPS("dpm_suspend_late"), state.event, false);

	return error;

}
@@ -1461,6 +1473,7 @@ int dpm_suspend(pm_message_t state) 
	ktime_t starttime = ktime_get();

	int error = 0;



	trace_suspend_resume(TPS("dpm_suspend"), state.event, true);

	might_sleep();



	cpufreq_suspend();
@@ -1498,6 +1511,7 @@ int dpm_suspend(pm_message_t state) 
		dpm_save_failed_step(SUSPEND_SUSPEND);

	} else

		dpm_show_time(starttime, state, NULL);

	trace_suspend_resume(TPS("dpm_suspend"), state.event, false);

	return error;

}
@@ -1582,6 +1596,7 @@ int dpm_prepare(pm_message_t state) 
{

	int error = 0;



	trace_suspend_resume(TPS("dpm_prepare"), state.event, true);

	might_sleep();



	mutex_lock(&dpm_list_mtx);
@@ -1612,6 +1627,7 @@ int dpm_prepare(pm_message_t state) 
		put_device(dev);

	}

	mutex_unlock(&dpm_list_mtx);

	trace_suspend_resume(TPS("dpm_prepare"), state.event, false);

	return error;

}

drivers/base/syscore.c

+5 −0
Original line number Diff line number Diff line
@@ -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(TPS("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(TPS("syscore_suspend"), 0, false);

	return 0;



 err_out:
@@ -92,6 +95,7 @@ void syscore_resume(void) 
{

	struct syscore_ops *ops;



	trace_suspend_resume(TPS("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(TPS("syscore_resume"), 0, false);

}

EXPORT_SYMBOL_GPL(syscore_resume);

#endif /* CONFIG_PM_SLEEP */

include/trace/events/power.h

+25 −17
Original line number Diff line number Diff line
@@ -7,6 +7,9 @@ 
#include <linux/ktime.h>

#include <linux/pm_qos.h>

#include <linux/tracepoint.h>

#include <linux/ftrace_event.h>



#define TPS(x)  tracepoint_string(x)



DECLARE_EVENT_CLASS(cpu,
@@ -97,23 +100,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 +137,28 @@ TRACE_EVENT(device_pm_report_time, 
		__entry->ops_time, __entry->error)

);



TRACE_EVENT(suspend_resume,



	TP_PROTO(const char *action, int val, bool start),



	TP_ARGS(action, val, start),



	TP_STRUCT__entry(

		__field(const char *, action)

		__field(int, val)

		__field(bool, start)

	),



	TP_fast_assign(

		__entry->action = action;

		__entry->val = val;

		__entry->start = start;

	),



	TP_printk("%s[%u] %s", __entry->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
Original line number Diff line number Diff line
@@ -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(TPS("CPU_OFF"), cpu, true);

		error = _cpu_down(cpu, 1);

		trace_suspend_resume(TPS("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(TPS("CPU_ON"), cpu, true);

		error = _cpu_up(cpu, 1);

		trace_suspend_resume(TPS("CPU_ON"), cpu, false);

		if (!error) {

			printk(KERN_INFO "CPU%d is up\n", cpu);

			continue;

CRA Git | Maintained and supported by SUSTech CRA and CCSE