PM: Asynchronous suspend and resume of devices

From: Rafael J. Wysocki <[email protected]>

Introduce a framework for representing off-tree PM dependencies between devices.

There are PM dependencies between devices that are not reflected by the structure of the device tree. In other words, as far as PM is concerned, a device may depend on some other devices which are not its children and none of which is its parent.

Every such dependency involves two devices, one of which is a "master" and the other of which is a "slave", meaning that the "slave" have to be suspended before the "master" and cannot be woken up before it. Thus every device can be given two lists of "dependency objects", one for the dependencies where the device is the "master" and the other for the dependencies where the device is the "slave". Then, each "dependency object" can be represented as

Index: linux-2.6/drivers/base/power/common.c
===================================================================

drivers/base/power/common.c new file +16 -0

 
+/**
+ * device_for_each_master - Execute given function for each master of a device.
+ * @slave: Device whose masters to execute the function for.
+ * @data: Data pointer to pass to the function.
+ * @fn: Function to execute for each master of @slave.
+ *
+ * The function is executed for the parent of the device, if there is one, and
+ * for each device connected to it via a pm_link object where @slave is the
+ * "slave".
+ */
+int device_for_each_master(struct device *slave, void *data,
+			   int (*fn)(struct device *dev, void *data))
+{
+	struct pm_link *link;
+	int idx;
+	int error = 0;

Quoted 45 lines · Rafael J. Wysocki

From: Rafael J. Wysocki <[email protected]>

Introduce a framework for representing off-tree PM dependencies between devices.

There are PM dependencies between devices that are not reflected by the structure of the device tree. In other words, as far as PM is concerned, a device may depend on some other devices which are not its children and none of which is its parent.

Every such dependency involves two devices, one of which is a "master" and the other of which is a "slave", meaning that the "slave" have to be suspended before the "master" and cannot be woken up before it. Thus every device can be given two lists of "dependency objects", one for the dependencies where the device is the "master" and the other for the dependencies where the device is the "slave". Then, each "dependency object" can be represented as

Index: linux-2.6/drivers/base/power/common.c
===================================================================

drivers/base/power/common.c new file +21 -0

 
+/**
+ * device_for_each_master - Execute given function for each master of a device.
+ * @slave: Device whose masters to execute the function for.
+ * @data: Data pointer to pass to the function.
+ * @fn: Function to execute for each master of @slave.
+ *
+ * The function is executed for the parent of the device, if there is one, and
+ * for each device connected to it via a pm_link object where @slave is the
+ * "slave".
+ */
+int device_for_each_master(struct device *slave, void *data,
+			   int (*fn)(struct device *dev, void *data))
+{
+	struct pm_link *link;
+	int idx;
+	int error = 0;
+
+	if (slave->parent) {
+		error = fn(slave->parent, data);
+		if (error)
+			return error;

drivers/base/power/common.c line 225

Quoted 5 lines

drivers/base/power/common.c new file +5 -0

+	}
+
+	idx = srcu_read_lock(&pm_link_ss);
+
+	list_for_each_entry(link, &slave->power.slave_links, slave_hook) {

This needs to use list_for_each_entry_rcu. Likewise in device_for_each_slave().

Quoted 45 lines · Rafael J. Wysocki

From: Rafael J. Wysocki <[email protected]>

Introduce a framework for representing off-tree PM dependencies between devices.

There are PM dependencies between devices that are not reflected by the structure of the device tree. In other words, as far as PM is concerned, a device may depend on some other devices which are not its children and none of which is its parent.

Every such dependency involves two devices, one of which is a "master" and the other of which is a "slave", meaning that the "slave" have to be suspended before the "master" and cannot be woken up before it. Thus every device can be given two lists of "dependency objects", one for the dependencies where the device is the "master" and the other for the dependencies where the device is the "slave". Then, each "dependency object" can be represented as

Index: linux-2.6/drivers/base/power/common.c
===================================================================

drivers/base/power/common.c new file +21 -0

 
+/**
+ * device_for_each_master - Execute given function for each master of a device.
+ * @slave: Device whose masters to execute the function for.
+ * @data: Data pointer to pass to the function.
+ * @fn: Function to execute for each master of @slave.
+ *
+ * The function is executed for the parent of the device, if there is one, and
+ * for each device connected to it via a pm_link object where @slave is the
+ * "slave".
+ */
+int device_for_each_master(struct device *slave, void *data,
+			   int (*fn)(struct device *dev, void *data))
+{
+	struct pm_link *link;
+	int idx;
+	int error = 0;
+
+	if (slave->parent) {
+		error = fn(slave->parent, data);
+		if (error)
+			return error;

drivers/base/power/common.c line 225

Quoted 5 lines

drivers/base/power/common.c new file +5 -0

+	}
+
+	idx = srcu_read_lock(&pm_link_ss);
+
+	list_for_each_entry(link, &slave->power.slave_links, slave_hook) {

This needs to use list_for_each_entry_rcu. Likewise in device_for_each_slave().

From: Rafael J. Wysocki <[email protected]>

Introduce a framework for representing off-tree PM dependencies between devices.

There are PM dependencies between devices that are not reflected by the structure of the device tree. In other words, as far as PM is concerned, a device may depend on some other devices which are not its children and none of which is its parent.

Every such dependency involves two devices, one of which is a "master" and the other of which is a "slave", meaning that the "slave" have to be suspended before the "master" and cannot be woken up before it. Thus every device can be given two lists of "dependency objects", one for the dependencies where the device is the "master" and the other for the dependencies where the device is the "slave". Then, each "dependency object" can be represented as

Index: linux-2.6/drivers/base/power/common.c
===================================================================

drivers/base/power/common.c new file +16 -0

 
+/**
+ * device_for_each_master - Execute given function for each master of a device.
+ * @slave: Device whose masters to execute the function for.
+ * @data: Data pointer to pass to the function.
+ * @fn: Function to execute for each master of @slave.
+ *
+ * The function is executed for the parent of the device, if there is one, and
+ * for each device connected to it via a pm_link object where @slave is the
+ * "slave".
+ */
+int device_for_each_master(struct device *slave, void *data,
+			   int (*fn)(struct device *dev, void *data))
+{
+	struct pm_link *link;
+	int idx;
+	int error = 0;

From: Rafael J. Wysocki <[email protected]>

Theoretically, the total time of system sleep transitions (suspend to RAM, hibernation) can be reduced by running suspend and resume callbacks of device drivers in parallel with each other. However, there are dependencies between devices such that, for example, we may not be allowed to put one device into a low power state before anohter one has been suspended (e.g. we cannot suspend a bridge before suspending all devices behind it). In particular, we're not allowed to suspend the parent of a device before suspending the device itself. Analogously, we're not allowed to resume a device before resuming its parent.

In this version of the patch the async threads started to execute the resume callbacks of specific device don't exit immediately having done that, but search dpm_list for devices whose PM dependencies have already been satisfied and execute their callbacks without waiting.

Quoted 13 lines · Rafael J. Wysocki

From: Rafael J. Wysocki <[email protected]>

Theoretically, the total time of system sleep transitions (suspend to RAM, hibernation) can be reduced by running suspend and resume callbacks of device drivers in parallel with each other. However, there are dependencies between devices such that, for example, we may not be allowed to put one device into a low power state before anohter one has been suspended (e.g. we cannot suspend a bridge before suspending all devices behind it). In particular, we're not allowed to suspend the parent of a device before suspending the device itself. Analogously, we're not allowed to resume a device before resuming its parent.

Quoted 4 lines

In this version of the patch the async threads started to execute the resume callbacks of specific device don't exit immediately having done that, but search dpm_list for devices whose PM dependencies have already been satisfied and execute their callbacks without waiting.

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

The same goes for the noirq versions.

Quoted 7 lines

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

The same goes for the noirq versions.

I thought about that, but there are a few things to figure out:
- how many threads to start

- when to start them

- stop condition

I had a few ideas, but then I thought it would be simpler to start an async thread when we know there's some async work to do (ie. there's an async device to handle) and make each async thread browse the list just once (the rationale is that we've just handled a device, so there's a chance there are some devices with satisfied dependencies down the list).

Quoted 6 lines · Rafael J. Wysocki

Quoted 6 lines

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

Quoted 4 lines

Quoted 1 line

The same goes for the noirq versions.

I thought about that, but there are a few things to figure out:
- how many threads to start

That's a tough question. Right now you start roughly as many threads as there are async devices. That seems like overkill.

I would expect that a reasonably small number of threads would suffice to achieve most of the possible time savings. Something on the order of 10 should work well. If the majority of the time is spent handling N devices then N+1 threads would be enough. Judging from some of the comments posted earlier, even 4 threads would give a big advantage.

Quoted 1 line

- when to start them

You might as well start them at the beginning of dpm_resume and dpm_resume_noirq. That way they can overlap with the synchronous operations.

Quoted 1 line

- stop condition

When an error occurs or when op_started has been set for every remaining async device.

Quoted 5 lines

I had a few ideas, but then I thought it would be simpler to start an async thread when we know there's some async work to do (ie. there's an async device to handle) and make each async thread browse the list just once (the rationale is that we've just handled a device, so there's a chance there are some devices with satisfied dependencies down the list).

It comes down to this: Should there be many threads, each of which browses the list only once, or should there be a few threads, each of which browses the list many times?

Quoted 8 lines · Alan Stern

Quoted 6 lines · Rafael J. Wysocki

Quoted 6 lines

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

Quoted 7 lines

Quoted 4 lines

Quoted 1 line

The same goes for the noirq versions.

I thought about that, but there are a few things to figure out:
- how many threads to start

That's a tough question. Right now you start roughly as many threads as there are async devices. That seems like overkill.

In fact they are substantially fewer than that, for the following reasons.

First, the async framework will not start more than MAX_THREADS threads, which is 256 at the moment. This number is less than the number of async devices to handle on an average system.

Second, no new async threads are started while the main thread is handling the sync devices , so the existing threads have a chance to do their job. If there's a "cluster" of sync devices in dpm_list, the number of async threads running is likely to drop rapidly while those devices are being handled. (BTW, if there were no sync devices, the whole thing would be much simpler, but I don't think it's realistic to assume we'll be able to get rid of them any time soon).

Finally, but not least importantly, async threads are not started for the async devices that were previously handled "out of order" by the already running async threads (or by async threads that have already finished). My testing shows that there are quite a few of them on the average. For example, on the HP nx6325 typically there are as many as 580 async devices handled "out of order" during a _single_ suspend-resume cycle (including the "early" and "late" phases), while only a few (below 10) devices are waited for by at least one async thread.

I can try to monitor the number of asyn threads started if you're interested.

Quoted 8 lines · Alan Stern

Quoted 6 lines · Rafael J. Wysocki

Quoted 6 lines

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

Quoted 7 lines

Quoted 4 lines

Quoted 1 line

The same goes for the noirq versions.

I thought about that, but there are a few things to figure out:
- how many threads to start

That's a tough question. Right now you start roughly as many threads as there are async devices. That seems like overkill.

In fact they are substantially fewer than that, for the following reasons.

First, the async framework will not start more than MAX_THREADS threads, which is 256 at the moment. This number is less than the number of async devices to handle on an average system.

Second, no new async threads are started while the main thread is handling the sync devices , so the existing threads have a chance to do their job. If there's a "cluster" of sync devices in dpm_list, the number of async threads running is likely to drop rapidly while those devices are being handled. (BTW, if there were no sync devices, the whole thing would be much simpler, but I don't think it's realistic to assume we'll be able to get rid of them any time soon).

Finally, but not least importantly, async threads are not started for the async devices that were previously handled "out of order" by the already running async threads (or by async threads that have already finished). My testing shows that there are quite a few of them on the average. For example, on the HP nx6325 typically there are as many as 580 async devices handled "out of order" during a _single_ suspend-resume cycle (including the "early" and "late" phases), while only a few (below 10) devices are waited for by at least one async thread.

I can try to monitor the number of asyn threads started if you're interested.

Quoted 13 lines · Alan Stern

Quoted 10 lines · Rafael J. Wysocki

Quoted 7 lines

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

The same goes for the noirq versions.

I thought about that, but there are a few things to figure out:
- how many threads to start

Quoted 2 lines

That's a tough question. Right now you start roughly as many threads as there are async devices. That seems like overkill.

In fact they are substantially fewer than that, for the following reasons.

First, the async framework will not start more than MAX_THREADS threads, which is 256 at the moment. This number is less than the number of async devices to handle on an average system.

Second, no new async threads are started while the main thread is handling the sync devices , so the existing threads have a chance to do their job. If there's a "cluster" of sync devices in dpm_list, the number of async threads running is likely to drop rapidly while those devices are being handled. (BTW, if there were no sync devices, the whole thing would be much simpler, but I don't think it's realistic to assume we'll be able to get rid of them any time soon).

Finally, but not least importantly, async threads are not started for the async devices that were previously handled "out of order" by the already running async threads (or by async threads that have already finished). My testing shows that there are quite a few of them on the average. For example, on the HP nx6325 typically there are as many as 580 async devices handled "out of order" during a _single_ suspend-resume cycle (including the "early" and "late" phases), while only a few (below 10) devices are waited for by at least one async thread.

Quoted 6 lines

I would expect that a reasonably small number of threads would suffice to achieve most of the possible time savings. Something on the order of 10 should work well. If the majority of the time is spent handling N devices then N+1 threads would be enough. Judging from some of the comments posted earlier, even 4 threads would give a big advantage.

That unfortunately is not the case with the set of async devices including PCI, ACPI and serio devices only. The average time savings are between 5% to 14%, depending on the system and the phase of the cycle (the relative savings are typically greater for suspend). Still, that amounts to .5 s in some cases.

Quoted 5 lines

Quoted 1 line

- when to start them

You might as well start them at the beginning of dpm_resume and dpm_resume_noirq. That way they can overlap with the synchronous operations.

In that case they would have to wait in the beginning, so I'd need a mechanism to wake them up.

Alternatively, there could be a limit to the number of async threads started within the current design, but I'd prefer to leave that to the async framework (namely, if MAX_THREADS makes sense for boot, it's also likely to make sense for PM).

Quoted 3 lines

It comes down to this: Should there be many threads, each of which browses the list only once, or should there be a few threads, each of which browses the list many times?

Well, quite obviously I prefer the many threads version. :-)

Quoted 19 lines · Rafael J. Wysocki

Quoted 8 lines · Alan Stern

Quoted 6 lines · Rafael J. Wysocki

Quoted 6 lines

Given this design, why bother to invoke device_resume() for the async devices? Why not just start up a bunch of async threads, each of which calls async_resume() repeatedly until everything is finished? (And rearrange async_resume() to scan the list first and do the actual resume second.)

Quoted 7 lines

Quoted 4 lines

Quoted 1 line

The same goes for the noirq versions.

I thought about that, but there are a few things to figure out:
- how many threads to start

That's a tough question. Right now you start roughly as many threads as there are async devices. That seems like overkill.

In fact they are substantially fewer than that, for the following reasons.

Quoted 3 lines

First, the async framework will not start more than MAX_THREADS threads, which is 256 at the moment. This number is less than the number of async devices to handle on an average system.

Okay, but MAX_THREADS isn't under your control. Remember also that each thread takes up some memory, and during hibernation we are in a memory-constrained situation.

Quoted 7 lines

Second, no new async threads are started while the main thread is handling the sync devices , so the existing threads have a chance to do their job. If there's a "cluster" of sync devices in dpm_list, the number of async threads running is likely to drop rapidly while those devices are being handled. (BTW, if there were no sync devices, the whole thing would be much simpler, but I don't think it's realistic to assume we'll be able to get rid of them any time soon).

Perhaps not, but it would be interesting to see what happens if every device is async. Maybe you can try it and get a meaningful result.

Quoted 8 lines

Finally, but not least importantly, async threads are not started for the async devices that were previously handled "out of order" by the already running async threads (or by async threads that have already finished). My testing shows that there are quite a few of them on the average. For example, on the HP nx6325 typically there are as many as 580 async devices handled "out of order" during a _single_ suspend-resume cycle (including the "early" and "late" phases), while only a few (below 10) devices are waited for by at least one async thread.

That is a difficult sort of thing to know in advance. It ought to be highly influenced by the percentage of async devices; that's another reason for wanting to know what happens when every device is async.

Quoted 11 lines

Quoted 6 lines

I would expect that a reasonably small number of threads would suffice to achieve most of the possible time savings. Something on the order of 10 should work well. If the majority of the time is spent handling N devices then N+1 threads would be enough. Judging from some of the comments posted earlier, even 4 threads would give a big advantage.

That unfortunately is not the case with the set of async devices including PCI, ACPI and serio devices only. The average time savings are between 5% to 14%, depending on the system and the phase of the cycle (the relative savings are typically greater for suspend). Still, that amounts to .5 s in some cases.

Without context it's hard to be sure, but I don't think your numbers contradict what I said. If you get between 5% and 14% time savings with 14 threads, then you might get between 4% and 10% savings with only 4 threads.

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

Quoted 8 lines

Quoted 5 lines

Quoted 1 line

- when to start them

You might as well start them at the beginning of dpm_resume and dpm_resume_noirq. That way they can overlap with the synchronous operations.

In that case they would have to wait in the beginning, so I'd need a mechanism to wake them up.

You already have two such mechanisms: dpm_list_mtx and the embedded wait_queue_heads. Although in the scheme I'm proposing, no async threads would ever have to wait on a per-device waitqueue. A system-wide waitqueue might work out better (for use when a thread reaches the end of the list and then waits before starting over at the beginning).

Quoted 4 lines

Alternatively, there could be a limit to the number of async threads started within the current design, but I'd prefer to leave that to the async framework (namely, if MAX_THREADS makes sense for boot, it's also likely to make sense for PM).

Strictly speaking, a new thread should be started only when needed. That is, only when all the existing threads are busy running a callback. It shouldn't be too hard to keep track of when that happens.

On Saturday 29 August 2009, Alan Stern wrote:

Quoted 3 lines

Strictly speaking, a new thread should be started only when needed. That is, only when all the existing threads are busy running a callback. It shouldn't be too hard to keep track of when that happens.

The async framework does that for us. :-)

Quoted 1 line · Rafael J. Wysocki

On Saturday 29 August 2009, Alan Stern wrote:

...

Quoted 5 lines

Quoted 3 lines

Strictly speaking, a new thread should be started only when needed. That is, only when all the existing threads are busy running a callback. It shouldn't be too hard to keep track of when that happens.

The async framework does that for us. :-)

So, when I said "async threads", I should have rather said "async functions", because one async thread can execute multiple functions scheduled with async_schedule().

Taking that into consideration, it all works like this. When there's a new async device to handle and there are no async threads available, a new thread is started and it runs the async function that handles the device and "opportunistically" searches dpm_list (once) for other device that are ready for handling. After this function has returned, the thread goes to sleep and it only exits after being idle for 1 s. In turn, when there's a new async device to handle and there are async threads available, on of them gets the async function to run.

I don't really think we can do much better than this in any other approach.

Quoted 1 line · Rafael J. Wysocki

On Saturday 29 August 2009, Alan Stern wrote:

...

Quoted 5 lines

Quoted 3 lines

Strictly speaking, a new thread should be started only when needed. That is, only when all the existing threads are busy running a callback. It shouldn't be too hard to keep track of when that happens.

The async framework does that for us. :-)

So, when I said "async threads", I should have rather said "async functions", because one async thread can execute multiple functions scheduled with async_schedule().

Taking that into consideration, it all works like this. When there's a new async device to handle and there are no async threads available, a new thread is started and it runs the async function that handles the device and "opportunistically" searches dpm_list (once) for other device that are ready for handling. After this function has returned, the thread goes to sleep and it only exits after being idle for 1 s. In turn, when there's a new async device to handle and there are async threads available, on of them gets the async function to run.

I don't really think we can do much better than this in any other approach.

On Saturday 29 August 2009, Alan Stern wrote:

Quoted 3 lines

Strictly speaking, a new thread should be started only when needed. That is, only when all the existing threads are busy running a callback. It shouldn't be too hard to keep track of when that happens.

The async framework does that for us. :-)

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

There's other all-capitals macros in that code implementing code (and not constants) - is that really justified/clean?

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Quoted 2 lines

There's other all-capitals macros in that code implementing code (and not constants) - is that really justified/clean?

Do you mean the TRACE_* macros? Please ask Linus about that, they are from him. :-)

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Quoted 2 lines

There's other all-capitals macros in that code implementing code (and not constants) - is that really justified/clean?

Do you mean the TRACE_* macros? Please ask Linus about that, they are from him. :-)

Quoted 138 lines · Rafael J. Wysocki

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

On Monday 31 August 2009, Ingo Molnar wrote:

Quoted 8 lines

Quoted 8 lines

Quoted 3 lines

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be
(a) confusing (why define a variable you don't use) and (b) wasteful.

Perhaps the names of the macros should be directly related to debugging?

On Monday 31 August 2009, Ingo Molnar wrote:

Quoted 8 lines

Quoted 8 lines

Quoted 3 lines

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be
(a) confusing (why define a variable you don't use) and (b) wasteful.

Perhaps the names of the macros should be directly related to debugging?

Quoted 141 lines · Ingo Molnar

Quoted 138 lines · Rafael J. Wysocki

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be (a) confusing (why define a variable you don't use) and (b) wasteful.

Quoted 152 lines · Rafael J. Wysocki

Quoted 141 lines · Ingo Molnar

Quoted 138 lines · Rafael J. Wysocki

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Quoted 4 lines

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be (a) confusing (why define a variable you don't use) and (b) wasteful.

Well the compiler will eliminate them, doesnt it?

Quoted 160 lines · Ingo Molnar

Quoted 156 lines · Rafael J. Wysocki

Quoted 141 lines · Ingo Molnar

Quoted 138 lines · Rafael J. Wysocki

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be (a) confusing (why define a variable you don't use) and (b) wasteful.

Quoted 1 line

Well the compiler will eliminate them, doesnt it?

If the compiler is guaranteed to eliminate them (without generating a "variable defined but not used" warning for that matter), then they can be always defined.

Quoted 160 lines · Ingo Molnar

Quoted 156 lines · Rafael J. Wysocki

Quoted 141 lines · Ingo Molnar

Quoted 138 lines · Rafael J. Wysocki

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be (a) confusing (why define a variable you don't use) and (b) wasteful.

Quoted 1 line

Well the compiler will eliminate them, doesnt it?

If the compiler is guaranteed to eliminate them (without generating a "variable defined but not used" warning for that matter), then they can be always defined.

Quoted 163 lines · Rafael J. Wysocki

Quoted 161 lines · Ingo Molnar

Quoted 149 lines · Rafael J. Wysocki

Quoted 141 lines · Ingo Molnar

Quoted 138 lines · Rafael J. Wysocki

Quoted 125 lines · Ingo Molnar

Quoted 122 lines · Rafael J. Wysocki

Quoted 15 lines · Rafael J. Wysocki

Quoted 14 lines · Alan Stern

Quoted 11 lines · Rafael J. Wysocki

I only wanted to say that the advantage is not really that "big". :-)

Quoted 2 lines

I must agree, 14 threads isn't a lot. But at the moment that number is random, not under your control.

It's not directly controlled, but there are some interactions between the async threads, the main threads and the async framework that don't allow this number to grow too much.

IMO it sometimes is better to allow things to work themselves out, as long as they don't explode, than to try to keep everything under strict control. YMMV.

Quoted 8 lines

Quoted 6 lines

For testing purposes it would be nice to have a one-line summary for each device containing a thread ID, start timestamp, end timestamp, and elapsed time. With that information you could evaluate the amount of parallelism and determine where the bottlenecks are. It would give a much more detailed picture of the entire process than the total time of your recent patch 9.

Of course it would. I think I'll implement it.

OK, below is a patch for that. It only prints the time elapsed, because the timestamps themselves can be obtained from the usual kernel timestamping.

It's on top of all the previous patches.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM: Measure suspend and resume times for individual devices

If verbose PM debugging is enabled, measure and print the time of suspending and resuming of individual devices.

Signed-off-by Rafael J. Wysocki <[email protected]>

---
 drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
 kernel/power/swsusp.c     |    2 -
 2 files changed, 47 insertions(+), 6 deletions(-)

Index: linux-2.6/drivers/base/power/main.c
===================================================================

drivers/base/power/main.c +34 -5

@@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
  */
 int pm_time_elapsed(struct timeval *start, struct timeval *stop)
 {
-	s64 elapsed_centisecs64;
+	s64 elapsed_msecs64;
 
-	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
-	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
-	return elapsed_centisecs64;
+	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
+	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
+	return elapsed_msecs64;
 }
 
 static char *pm_verb(int event)

@@ -476,7 +476,7 @@ static char *pm_verb(int event)
 static void dpm_show_time(struct timeval *start, struct timeval *stop,
 			  pm_message_t state, const char *info)
 {
-	int centisecs = pm_time_elapsed(start, stop);
+	int centisecs = pm_time_elapsed(start, stop) / 10;
 
 	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
 		info ? info : "", info ? " " : "", pm_verb(state.event),

@@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
 		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
 }
 
+#ifdef DEBUG
+static void device_show_time(struct timeval *start, struct device *dev,
+			     pm_message_t state, char *info)
+{
+	struct timeval stop;
+	int msecs;
+
+	do_gettimeofday(&stop);
+	msecs = pm_time_elapsed(start, &stop);
+	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
+		task_pid_nr(current), info ? info : "", info ? " " : "",
+		pm_verb(state.event), msecs / 1000, msecs % 1000);
+}
+
+#define TIMER_DECLARE(timer)	struct timeval timer
+#define TIMER_START(timer)	do { \
+		do_gettimeofday(&timer); \
+	} while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { \
+		device_show_time(&timer, dev, state, info); \
+	} while (0)
+#else /* !DEBUG */
+#define TIMER_DECLARE(timer)
+#define TIMER_START(timer)	do { } while (0)
+#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
+#endif /* !DEBUG */
+
 /*------------------------- Resume routines -------------------------*/
 
 /**

@@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
 static int __device_resume_noirq(struct device *dev, pm_message_t state)
 {
 	int error = 0;
+	TIMER_DECLARE(timer);
 
+	TIMER_START(timer);
 	TRACE_DEVICE(dev);
 	TRACE_RESUME(0);
 

@@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
 	wake_up_all(&dev->power.wait_queue);
 

Quoted 7 lines

drivers/base/power/main.c static int __device_resume_noirq(struct · line 556

Quoted 3 lines

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

 	TRACE_RESUME(error);
+	TIMER_STOP(timer, dev, state, "EARLY");
 	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the TIMER_DECLARE() wrapper - if a proper inline function is used there's no need for that.

I need a variable to be declared so that I can save the "start" timestamp in it. I don't need the variable if DEBUG is unset, though.

Quoted 6 lines

Quoted 2 lines

How would you do that without using a macro? Or #ifdef #endif block that would be uglier IMO (which is why I didn't do that)?

Well, why not use an inline function like i suggested? [which does nothing in the !enabled case] You can keep the local variable always defined.

Quoted 7 lines

Well, I used the macros _exactly_ because I didn't want to keep the local variable always defined.

Now, if you think that adding several useless bytes to the stack frame is OK, perhaps it can be always defined. However, IMnsHO that would be (a) confusing (why define a variable you don't use) and (b) wasteful.

Well the compiler will eliminate them, doesnt it?

Quoted 3 lines

If the compiler is guaranteed to eliminate them (without generating a "variable defined but not used" warning for that matter), then they can be always defined.

Why should such a warning be generated if what makes use of it is an inline function?

(it would be generated if it's a macro.)