Commit d715a226 authored by Rafael J. Wysocki's avatar Rafael J. Wysocki
Browse files

Merge branch 'pm-sleep' 

* pm-sleep:
  PM / sleep: trace events for device PM callbacks
  PM / sleep: trace events for suspend/resume
parents 589e18a9 e8bca479

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

+26 −4
Original line number Diff line number Diff line
@@ -214,9 +214,6 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime, 
		pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),

			error, (unsigned long long)nsecs >> 10);

	}



	trace_device_pm_report_time(dev, info, nsecs, pm_verb(state.event),

				    error);

}



/**
@@ -387,7 +384,9 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev, 
	calltime = initcall_debug_start(dev);



	pm_dev_dbg(dev, state, info);

	trace_device_pm_callback_start(dev, info, state.event);

	error = cb(dev);

	trace_device_pm_callback_end(dev, error);

	suspend_report_result(cb, error);



	initcall_debug_report(dev, calltime, error, state, info);
@@ -545,6 +544,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 +587,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 +665,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 +705,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 +837,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 +879,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);

}



/**
@@ -913,7 +918,9 @@ static void device_complete(struct device *dev, pm_message_t state) 


	if (callback) {

		pm_dev_dbg(dev, state, info);

		trace_device_pm_callback_start(dev, info, state.event);

		callback(dev);

		trace_device_pm_callback_end(dev, 0);

	}



	device_unlock(dev);
@@ -932,6 +939,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 +959,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 +1095,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 +1136,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 +1233,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 +1269,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;

}
@@ -1295,7 +1308,9 @@ static int legacy_suspend(struct device *dev, pm_message_t state, 


	calltime = initcall_debug_start(dev);



	trace_device_pm_callback_start(dev, info, state.event);

	error = cb(dev, state);

	trace_device_pm_callback_end(dev, error);

	suspend_report_result(cb, error);



	initcall_debug_report(dev, calltime, error, state, info);
@@ -1461,6 +1476,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 +1514,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;

}
@@ -1549,8 +1566,11 @@ static int device_prepare(struct device *dev, pm_message_t state) 
		callback = dev->driver->pm->prepare;

	}



	if (callback)

	if (callback) {

		trace_device_pm_callback_start(dev, info, state.event);

		ret = callback(dev);

		trace_device_pm_callback_end(dev, ret);

	}



	device_unlock(dev);
@@ -1582,6 +1602,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 +1633,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

+58 −26
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,
@@ -90,6 +93,17 @@ TRACE_EVENT(pstate_sample, 
#define PWR_EVENT_EXIT -1

#endif



#define pm_verb_symbolic(event) \

	__print_symbolic(event, \

		{ PM_EVENT_SUSPEND, "suspend" }, \

		{ PM_EVENT_RESUME, "resume" }, \

		{ PM_EVENT_FREEZE, "freeze" }, \

		{ PM_EVENT_QUIESCE, "quiesce" }, \

		{ PM_EVENT_HIBERNATE, "hibernate" }, \

		{ PM_EVENT_THAW, "thaw" }, \

		{ PM_EVENT_RESTORE, "restore" }, \

		{ PM_EVENT_RECOVER, "recover" })



DEFINE_EVENT(cpu, cpu_frequency,



	TP_PROTO(unsigned int frequency, unsigned int cpu_id),
@@ -97,58 +111,76 @@ DEFINE_EVENT(cpu, cpu_frequency, 
	TP_ARGS(frequency, cpu_id)

);



TRACE_EVENT(machine_suspend,

TRACE_EVENT(device_pm_callback_start,



	TP_PROTO(unsigned int state),

	TP_PROTO(struct device *dev, const char *pm_ops, int event),



	TP_ARGS(state),

	TP_ARGS(dev, pm_ops, event),



	TP_STRUCT__entry(

		__field(	u32,		state		)

		__string(device, dev_name(dev))

		__string(driver, dev_driver_string(dev))

		__string(parent, dev->parent ? dev_name(dev->parent) : "none")

		__string(pm_ops, pm_ops ? pm_ops : "none ")

		__field(int, event)

	),



	TP_fast_assign(

		__entry->state = state;

		__assign_str(device, dev_name(dev));

		__assign_str(driver, dev_driver_string(dev));

		__assign_str(parent,

			dev->parent ? dev_name(dev->parent) : "none");

		__assign_str(pm_ops, pm_ops ? pm_ops : "none ");

		__entry->event = event;

	),



	TP_printk("state=%lu", (unsigned long)__entry->state)

	TP_printk("%s %s, parent: %s, %s[%s]", __get_str(driver),

		__get_str(device), __get_str(parent), __get_str(pm_ops),

		pm_verb_symbolic(__entry->event))

);



TRACE_EVENT(device_pm_report_time,

TRACE_EVENT(device_pm_callback_end,



	TP_PROTO(struct device *dev, const char *pm_ops, s64 ops_time,

		 char *pm_event_str, int error),

	TP_PROTO(struct device *dev, int error),



	TP_ARGS(dev, pm_ops, ops_time, pm_event_str, error),

	TP_ARGS(dev, error),



	TP_STRUCT__entry(

		__string(device, dev_name(dev))

		__string(driver, dev_driver_string(dev))

		__string(parent, dev->parent ? dev_name(dev->parent) : "none")

		__string(pm_ops, pm_ops ? pm_ops : "none ")

		__string(pm_event_str, pm_event_str)

		__field(s64, ops_time)

		__field(int, error)

	),



	TP_fast_assign(

		const char *tmp = dev->parent ? dev_name(dev->parent) : "none";

		const char *tmp_i = pm_ops ? pm_ops : "none ";



		__assign_str(device, dev_name(dev));

		__assign_str(driver, dev_driver_string(dev));

		__assign_str(parent, tmp);

		__assign_str(pm_ops, tmp_i);

		__assign_str(pm_event_str, pm_event_str);

		__entry->ops_time = ops_time;

		__entry->error = error;

	),



	/* ops_str has an extra space at the end */

	TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d",

		__get_str(driver), __get_str(device), __get_str(parent),

		__get_str(pm_event_str), __get_str(pm_ops),

		__entry->ops_time, __entry->error)

	TP_printk("%s %s, err=%d",

		__get_str(driver), __get_str(device), __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,

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;