[PATCHv v3] power: Include additional information in pm_print_times

[PATCHv v3] power: Include additional information in pm_print_times

[Shuah Khan]

Change __device_suspend() path to include driver name and the ops that
get run for a device. This additional information helps associate the
driver and the type of pm_ops the device uses in the suspend path very
quickly, which will aid in debugging problems in suspend and resume paths.
Changed both start and end debug messages to include pm_ops information
and use dev_info() instead of pr_info(). Changed the end message to include
parent device information and have the same format as the start message.

dmesg output before the change:

[  164.390032] calling  1-1+ @ 69, parent: usb1
[  164.390035] call 1-1+ returned 0 after 0 usecs

[  164.390352] calling  00:0a+ @ 2457, parent: pnp0
[  164.390357] call 00:0a+ returned 0 after 3 usecs

[  164.390361] calling  00:09+ @ 2457, parent: pnp0
[  164.496458] call 00:09+ returned 0 after 103500 usecs

[  164.496494] calling  00:05+ @ 2457, parent: pnp0
[  164.496511] call 00:05+ returned 0 after 14 usecs

dmesg output after the change:

[  545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1
[  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0)

[  545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0
[  545.982554] system 00:0a: End  : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0)

[  545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0
[  546.087017] tpm_tis 00:09: End  : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0)

[  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
[  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)

Signed-off-by: Shuah Khan <shuah.kh@samsung.com>
---

v2: Change to use dev_info() instead of pr_info()
v3: Change to add parent info to debug_report and make start and end messages
    look similar have a tighter association.

 drivers/base/power/main.c |   49 +++++++++++++++++++++++++++------------------
 1 file changed, 29 insertions(+), 20 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 5a9b656..c2132b8 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -157,13 +157,14 @@ void device_pm_move_last(struct device *dev)
 	list_move_tail(&dev->power.entry, &dpm_list);
 }
 
-static ktime_t initcall_debug_start(struct device *dev)
+static ktime_t initcall_debug_start(struct device *dev, char *info)
 {
 	ktime_t calltime = ktime_set(0, 0);
 
 	if (pm_print_times_enabled) {
-		pr_info("calling  %s+ @ %i, parent: %s\n",
-			dev_name(dev), task_pid_nr(current),
+		/* string in info has an extra space at the end */
+		dev_info(dev, "Start: %s@ %i, parent: %s\n",
+			info, task_pid_nr(current),
 			dev->parent ? dev_name(dev->parent) : "none");
 		calltime = ktime_get();
 	}
@@ -172,15 +173,19 @@ static ktime_t initcall_debug_start(struct device *dev)
 }
 
 static void initcall_debug_report(struct device *dev, ktime_t calltime,
-				  int error)
+				  int error, char *info)
 {
 	ktime_t delta, rettime;
 
 	if (pm_print_times_enabled) {
 		rettime = ktime_get();
 		delta = ktime_sub(rettime, calltime);
-		pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
-			error, (unsigned long long)ktime_to_ns(delta) >> 10);
+		/* string in info has an extra space at the end */
+		dev_info(dev,
+			"End  : %s@ %i, parent: %s time(%llu usecs) err(%d)\n",
+			info, task_pid_nr(current),
+			dev->parent ? dev_name(dev->parent) : "none",
+			(unsigned long long)ktime_to_ns(delta) >> 10, error);
 	}
 }
 
@@ -373,13 +378,13 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev,
 	if (!cb)
 		return 0;
 
-	calltime = initcall_debug_start(dev);
+	calltime = initcall_debug_start(dev, info);
 
 	pm_dev_dbg(dev, state, info);
 	error = cb(dev);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error);
+	initcall_debug_report(dev, calltime, error, info);
 
 	return error;
 }
@@ -1027,17 +1032,19 @@ EXPORT_SYMBOL_GPL(dpm_suspend_end);
  * @cb: Suspend callback to execute.
  */
 static int legacy_suspend(struct device *dev, pm_message_t state,
-			  int (*cb)(struct device *dev, pm_message_t state))
+			  int (*cb)(struct device *dev, pm_message_t state),
+			  char *info)
 {
 	int error;
 	ktime_t calltime;
 
-	calltime = initcall_debug_start(dev);
+	calltime = initcall_debug_start(dev, info);
 
+	pm_dev_dbg(dev, state, info);
 	error = cb(dev, state);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error);
+	initcall_debug_report(dev, calltime, error, info);
 
 	return error;
 }
@@ -1079,43 +1086,45 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async)
 	device_lock(dev);
 
 	if (dev->pm_domain) {
-		info = "power domain ";
+		info = "power domain pm ops ";
 		callback = pm_op(&dev->pm_domain->ops, state);
 		goto Run;
 	}
 
 	if (dev->type && dev->type->pm) {
-		info = "type ";
+		info = "type pm ops ";
 		callback = pm_op(dev->type->pm, state);
 		goto Run;
 	}
 
 	if (dev->class) {
 		if (dev->class->pm) {
-			info = "class ";
+			info = "class pm ops ";
 			callback = pm_op(dev->class->pm, state);
 			goto Run;
 		} else if (dev->class->suspend) {
-			pm_dev_dbg(dev, state, "legacy class ");
-			error = legacy_suspend(dev, state, dev->class->suspend);
+			info = "legacy class pm ops ";
+			error = legacy_suspend(dev, state, dev->class->suspend,
+				info);
 			goto End;
 		}
 	}
 
 	if (dev->bus) {
 		if (dev->bus->pm) {
-			info = "bus ";
+			info = "bus pm ops ";
 			callback = pm_op(dev->bus->pm, state);
 		} else if (dev->bus->suspend) {
-			pm_dev_dbg(dev, state, "legacy bus ");
-			error = legacy_suspend(dev, state, dev->bus->suspend);
+			info = "legacy bus pm ops ";
+			error = legacy_suspend(dev, state, dev->bus->suspend,
+				info);
 			goto End;
 		}
 	}
 
  Run:
 	if (!callback && dev->driver && dev->driver->pm) {
-		info = "driver ";
+		info = "driver pm ops ";
 		callback = pm_op(dev->driver->pm, state);
 	}
 
-- 
1.7.10.4

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Greg KH]

On Mon, Jun 17, 2013 at 01:36:35PM -0600, Shuah Khan wrote:
> Change __device_suspend() path to include driver name and the ops that
> get run for a device. This additional information helps associate the
> driver and the type of pm_ops the device uses in the suspend path very
> quickly, which will aid in debugging problems in suspend and resume paths.
> Changed both start and end debug messages to include pm_ops information
> and use dev_info() instead of pr_info(). Changed the end message to include
> parent device information and have the same format as the start message.
> 
> dmesg output before the change:
> 
> [  164.390032] calling  1-1+ @ 69, parent: usb1
> [  164.390035] call 1-1+ returned 0 after 0 usecs
> 
> [  164.390352] calling  00:0a+ @ 2457, parent: pnp0
> [  164.390357] call 00:0a+ returned 0 after 3 usecs
> 
> [  164.390361] calling  00:09+ @ 2457, parent: pnp0
> [  164.496458] call 00:09+ returned 0 after 103500 usecs
> 
> [  164.496494] calling  00:05+ @ 2457, parent: pnp0
> [  164.496511] call 00:05+ returned 0 after 14 usecs
> 
> dmesg output after the change:
> 
> [  545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1
> [  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0)
> 
> [  545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  545.982554] system 00:0a: End  : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0)
> 
> [  545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  546.087017] tpm_tis 00:09: End  : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0)
> 
> [  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)
> 
> Signed-off-by: Shuah Khan <shuah.kh@samsung.com>

Acked-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Alan Stern]

On Mon, 17 Jun 2013, Shuah Khan wrote:

> Change __device_suspend() path to include driver name and the ops that
> get run for a device. This additional information helps associate the
> driver and the type of pm_ops the device uses in the suspend path very
> quickly, which will aid in debugging problems in suspend and resume paths.
> Changed both start and end debug messages to include pm_ops information
> and use dev_info() instead of pr_info(). Changed the end message to include
> parent device information and have the same format as the start message.
> 
> dmesg output before the change:
> 
> [  164.390032] calling  1-1+ @ 69, parent: usb1
> [  164.390035] call 1-1+ returned 0 after 0 usecs
> 
> [  164.390352] calling  00:0a+ @ 2457, parent: pnp0
> [  164.390357] call 00:0a+ returned 0 after 3 usecs
> 
> [  164.390361] calling  00:09+ @ 2457, parent: pnp0
> [  164.496458] call 00:09+ returned 0 after 103500 usecs
> 
> [  164.496494] calling  00:05+ @ 2457, parent: pnp0
> [  164.496511] call 00:05+ returned 0 after 14 usecs
> 
> dmesg output after the change:
> 
> [  545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1
> [  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0)
> 
> [  545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  545.982554] system 00:0a: End  : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0)
> 
> [  545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  546.087017] tpm_tis 00:09: End  : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0)
> 
> [  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)

If you don't mind a little more bike-shedding, I suggest formatting the 
return value and time in a shorter format, like this:

[  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 -> 0, 2184 us

Alan Stern

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Shuah Khan]

On 06/17/2013 02:24 PM, Alan Stern wrote:
> On Mon, 17 Jun 2013, Shuah Khan wrote:
>
>> Change __device_suspend() path to include driver name and the ops that
>> get run for a device. This additional information helps associate the
>> driver and the type of pm_ops the device uses in the suspend path very
>> quickly, which will aid in debugging problems in suspend and resume paths.
>> Changed both start and end debug messages to include pm_ops information
>> and use dev_info() instead of pr_info(). Changed the end message to include
>> parent device information and have the same format as the start message.
>>

>>
>> [  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
>> [  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)
>
> If you don't mind a little more bike-shedding, I suggest formatting the
> return value and time in a shorter format, like this:
>
> [  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 -> 0, 2184 us
>
> Alan Stern
>
>

I am leaning towards leaving it the way it is for clarity, even though 
it is a bit longer? Changing it would make it too cryptic especially 
error return.

thanks,
-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Monday, June 17, 2013 01:36:35 PM Shuah Khan wrote:
> Change __device_suspend() path to include driver name and the ops that
> get run for a device. This additional information helps associate the
> driver and the type of pm_ops the device uses in the suspend path very
> quickly, which will aid in debugging problems in suspend and resume paths.
> Changed both start and end debug messages to include pm_ops information
> and use dev_info() instead of pr_info(). Changed the end message to include
> parent device information and have the same format as the start message.
> 
> dmesg output before the change:
> 
> [  164.390032] calling  1-1+ @ 69, parent: usb1
> [  164.390035] call 1-1+ returned 0 after 0 usecs
> 
> [  164.390352] calling  00:0a+ @ 2457, parent: pnp0
> [  164.390357] call 00:0a+ returned 0 after 3 usecs
> 
> [  164.390361] calling  00:09+ @ 2457, parent: pnp0
> [  164.496458] call 00:09+ returned 0 after 103500 usecs
> 
> [  164.496494] calling  00:05+ @ 2457, parent: pnp0
> [  164.496511] call 00:05+ returned 0 after 14 usecs
> 
> dmesg output after the change:
> 
> [  545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1
> [  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0)
> 
> [  545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  545.982554] system 00:0a: End  : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0)
> 
> [  545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  546.087017] tpm_tis 00:09: End  : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0)
> 
> [  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
> [  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)
> 

I was about to apply your patch, but then I noticed something that might cause
problems to happen.

Namely, there are tools that use these messages to create suspend/resume time
charts and they will stop working after the proposed changes.

Please keep the existing formatting the way it is and only append the additional
information at the end of each line.

Thanks,
Rafael


> Signed-off-by: Shuah Khan <shuah.kh@samsung.com>
> ---
> 
> v2: Change to use dev_info() instead of pr_info()
> v3: Change to add parent info to debug_report and make start and end messages
>     look similar have a tighter association.
> 
>  drivers/base/power/main.c |   49 +++++++++++++++++++++++++++------------------
>  1 file changed, 29 insertions(+), 20 deletions(-)
> 
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index 5a9b656..c2132b8 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -157,13 +157,14 @@ void device_pm_move_last(struct device *dev)
>  	list_move_tail(&dev->power.entry, &dpm_list);
>  }
>  
> -static ktime_t initcall_debug_start(struct device *dev)
> +static ktime_t initcall_debug_start(struct device *dev, char *info)
>  {
>  	ktime_t calltime = ktime_set(0, 0);
>  
>  	if (pm_print_times_enabled) {
> -		pr_info("calling  %s+ @ %i, parent: %s\n",
> -			dev_name(dev), task_pid_nr(current),
> +		/* string in info has an extra space at the end */
> +		dev_info(dev, "Start: %s@ %i, parent: %s\n",
> +			info, task_pid_nr(current),
>  			dev->parent ? dev_name(dev->parent) : "none");
>  		calltime = ktime_get();
>  	}
> @@ -172,15 +173,19 @@ static ktime_t initcall_debug_start(struct device *dev)
>  }
>  
>  static void initcall_debug_report(struct device *dev, ktime_t calltime,
> -				  int error)
> +				  int error, char *info)
>  {
>  	ktime_t delta, rettime;
>  
>  	if (pm_print_times_enabled) {
>  		rettime = ktime_get();
>  		delta = ktime_sub(rettime, calltime);
> -		pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
> -			error, (unsigned long long)ktime_to_ns(delta) >> 10);
> +		/* string in info has an extra space at the end */
> +		dev_info(dev,
> +			"End  : %s@ %i, parent: %s time(%llu usecs) err(%d)\n",
> +			info, task_pid_nr(current),
> +			dev->parent ? dev_name(dev->parent) : "none",
> +			(unsigned long long)ktime_to_ns(delta) >> 10, error);
>  	}
>  }
>  
> @@ -373,13 +378,13 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev,
>  	if (!cb)
>  		return 0;
>  
> -	calltime = initcall_debug_start(dev);
> +	calltime = initcall_debug_start(dev, info);
>  
>  	pm_dev_dbg(dev, state, info);
>  	error = cb(dev);
>  	suspend_report_result(cb, error);
>  
> -	initcall_debug_report(dev, calltime, error);
> +	initcall_debug_report(dev, calltime, error, info);
>  
>  	return error;
>  }
> @@ -1027,17 +1032,19 @@ EXPORT_SYMBOL_GPL(dpm_suspend_end);
>   * @cb: Suspend callback to execute.
>   */
>  static int legacy_suspend(struct device *dev, pm_message_t state,
> -			  int (*cb)(struct device *dev, pm_message_t state))
> +			  int (*cb)(struct device *dev, pm_message_t state),
> +			  char *info)
>  {
>  	int error;
>  	ktime_t calltime;
>  
> -	calltime = initcall_debug_start(dev);
> +	calltime = initcall_debug_start(dev, info);
>  
> +	pm_dev_dbg(dev, state, info);
>  	error = cb(dev, state);
>  	suspend_report_result(cb, error);
>  
> -	initcall_debug_report(dev, calltime, error);
> +	initcall_debug_report(dev, calltime, error, info);
>  
>  	return error;
>  }
> @@ -1079,43 +1086,45 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async)
>  	device_lock(dev);
>  
>  	if (dev->pm_domain) {
> -		info = "power domain ";
> +		info = "power domain pm ops ";
>  		callback = pm_op(&dev->pm_domain->ops, state);
>  		goto Run;
>  	}
>  
>  	if (dev->type && dev->type->pm) {
> -		info = "type ";
> +		info = "type pm ops ";
>  		callback = pm_op(dev->type->pm, state);
>  		goto Run;
>  	}
>  
>  	if (dev->class) {
>  		if (dev->class->pm) {
> -			info = "class ";
> +			info = "class pm ops ";
>  			callback = pm_op(dev->class->pm, state);
>  			goto Run;
>  		} else if (dev->class->suspend) {
> -			pm_dev_dbg(dev, state, "legacy class ");
> -			error = legacy_suspend(dev, state, dev->class->suspend);
> +			info = "legacy class pm ops ";
> +			error = legacy_suspend(dev, state, dev->class->suspend,
> +				info);
>  			goto End;
>  		}
>  	}
>  
>  	if (dev->bus) {
>  		if (dev->bus->pm) {
> -			info = "bus ";
> +			info = "bus pm ops ";
>  			callback = pm_op(dev->bus->pm, state);
>  		} else if (dev->bus->suspend) {
> -			pm_dev_dbg(dev, state, "legacy bus ");
> -			error = legacy_suspend(dev, state, dev->bus->suspend);
> +			info = "legacy bus pm ops ";
> +			error = legacy_suspend(dev, state, dev->bus->suspend,
> +				info);
>  			goto End;
>  		}
>  	}
>  
>   Run:
>  	if (!callback && dev->driver && dev->driver->pm) {
> -		info = "driver ";
> +		info = "driver pm ops ";
>  		callback = pm_op(dev->driver->pm, state);
>  	}
>  
> 
-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Shuah Khan]

On 06/21/2013 06:15 PM, Rafael J. Wysocki wrote:
> On Monday, June 17, 2013 01:36:35 PM Shuah Khan wrote:
>> Change __device_suspend() path to include driver name and the ops that
>> get run for a device. This additional information helps associate the
>> driver and the type of pm_ops the device uses in the suspend path very
>> quickly, which will aid in debugging problems in suspend and resume paths.
>> Changed both start and end debug messages to include pm_ops information
>> and use dev_info() instead of pr_info(). Changed the end message to include
>> parent device information and have the same format as the start message.
>>
>> dmesg output before the change:
>>
>> [  164.390032] calling  1-1+ @ 69, parent: usb1
>> [  164.390035] call 1-1+ returned 0 after 0 usecs
>>
>> [  164.390352] calling  00:0a+ @ 2457, parent: pnp0
>> [  164.390357] call 00:0a+ returned 0 after 3 usecs
>>
>> [  164.390361] calling  00:09+ @ 2457, parent: pnp0
>> [  164.496458] call 00:09+ returned 0 after 103500 usecs
>>
>> [  164.496494] calling  00:05+ @ 2457, parent: pnp0
>> [  164.496511] call 00:05+ returned 0 after 14 usecs
>>
>> dmesg output after the change:
>>
>> [  545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1
>> [  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0)
>>
>> [  545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0
>> [  545.982554] system 00:0a: End  : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0)
>>
>> [  545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0
>> [  546.087017] tpm_tis 00:09: End  : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0)
>>
>> [  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
>> [  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)
>>
>
> I was about to apply your patch, but then I noticed something that might cause
> problems to happen.
>
> Namely, there are tools that use these messages to create suspend/resume time
> charts and they will stop working after the proposed changes.
>
> Please keep the existing formatting the way it is and only append the additional
> information at the end of each line.
>
> Thanks,
> Rafael
>

Hi Rafael,

Yes changing the format would cause problems for scripts that rely on 
the exact format. Would you like to pick the v2 version of the patch 
that appends the additional information at the end, instead of changing 
the format? Here is the link. If you would like me to resend it, I can 
do that.

https://lkml.org/lkml/2013/6/14/448

-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Saturday, June 22, 2013 12:58:28 AM Shuah Khan wrote:
> On 06/21/2013 06:15 PM, Rafael J. Wysocki wrote:
> > On Monday, June 17, 2013 01:36:35 PM Shuah Khan wrote:
> >> Change __device_suspend() path to include driver name and the ops that
> >> get run for a device. This additional information helps associate the
> >> driver and the type of pm_ops the device uses in the suspend path very
> >> quickly, which will aid in debugging problems in suspend and resume paths.
> >> Changed both start and end debug messages to include pm_ops information
> >> and use dev_info() instead of pr_info(). Changed the end message to include
> >> parent device information and have the same format as the start message.
> >>
> >> dmesg output before the change:
> >>
> >> [  164.390032] calling  1-1+ @ 69, parent: usb1
> >> [  164.390035] call 1-1+ returned 0 after 0 usecs
> >>
> >> [  164.390352] calling  00:0a+ @ 2457, parent: pnp0
> >> [  164.390357] call 00:0a+ returned 0 after 3 usecs
> >>
> >> [  164.390361] calling  00:09+ @ 2457, parent: pnp0
> >> [  164.496458] call 00:09+ returned 0 after 103500 usecs
> >>
> >> [  164.496494] calling  00:05+ @ 2457, parent: pnp0
> >> [  164.496511] call 00:05+ returned 0 after 14 usecs
> >>
> >> dmesg output after the change:
> >>
> >> [  545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1
> >> [  545.987650] usb 1-1: End  : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0)
> >>
> >> [  545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0
> >> [  545.982554] system 00:0a: End  : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0)
> >>
> >> [  545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0
> >> [  546.087017] tpm_tis 00:09: End  : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0)
> >>
> >> [  546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0
> >> [  546.087084] rtc_cmos 00:05: End  : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0)
> >>
> >
> > I was about to apply your patch, but then I noticed something that might cause
> > problems to happen.
> >
> > Namely, there are tools that use these messages to create suspend/resume time
> > charts and they will stop working after the proposed changes.
> >
> > Please keep the existing formatting the way it is and only append the additional
> > information at the end of each line.
> >
> > Thanks,
> > Rafael
> >
> 
> Hi Rafael,

Hi,

> Yes changing the format would cause problems for scripts that rely on 
> the exact format. Would you like to pick the v2 version of the patch 
> that appends the additional information at the end, instead of changing 
> the format? Here is the link. If you would like me to resend it, I can 
> do that.
> 
> https://lkml.org/lkml/2013/6/14/448

Well, this one replaces pr_info() with dev_info() and the format changes
as a result.  Please keep the existing format as is literally and append any
new information to the end of the line.

Thanks,
Rafael


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

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Joe Perches]

On Sun, 2013-06-23 at 13:36 +0200, Rafael J. Wysocki wrote:
> Please keep the existing format as is literally and append any
> new information to the end of the line.

Hi Shuah.

Perhaps the better long-term approach would be to add
a new tracepoint too.

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Sunday, June 23, 2013 04:34:17 AM Joe Perches wrote:
> On Sun, 2013-06-23 at 13:36 +0200, Rafael J. Wysocki wrote:
> > Please keep the existing format as is literally and append any
> > new information to the end of the line.
> 
> Hi Shuah.
> 
> Perhaps the better long-term approach would be to add
> a new tracepoint too.

In fact, I would even prefer it if new tracepoints were added so that we
could deprecate the dmesg messages at one point in the future.

Thanks,
Rafael


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

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Shuah Khan]

On 06/23/2013 03:49 PM, Rafael J. Wysocki wrote:
> On Sunday, June 23, 2013 04:34:17 AM Joe Perches wrote:
>> On Sun, 2013-06-23 at 13:36 +0200, Rafael J. Wysocki wrote:
>>> Please keep the existing format as is literally and append any
>>> new information to the end of the line.
>>
>> Hi Shuah.
>>
>> Perhaps the better long-term approach would be to add
>> a new tracepoint too.
>
> In fact, I would even prefer it if new tracepoints were added so that we
> could deprecate the dmesg messages at one point in the future.
>
> Thanks,
> Rafael
>
>

Rafael/Joe,

I can work on adding a tracepoint. Do you want to take the v2 patch in 
the meantime?

-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Shuah Khan]

On 06/24/2013 10:25 AM, Shuah Khan wrote:
> On 06/23/2013 03:49 PM, Rafael J. Wysocki wrote:
>> On Sunday, June 23, 2013 04:34:17 AM Joe Perches wrote:
>>> On Sun, 2013-06-23 at 13:36 +0200, Rafael J. Wysocki wrote:
>>>> Please keep the existing format as is literally and append any
>>>> new information to the end of the line.
>>>
>>> Hi Shuah.
>>>
>>> Perhaps the better long-term approach would be to add
>>> a new tracepoint too.
>>
>> In fact, I would even prefer it if new tracepoints were added so that we
>> could deprecate the dmesg messages at one point in the future.
>>
>> Thanks,
>> Rafael
>>
>>
>
> Rafael/Joe,
>
> I can work on adding a tracepoint. Do you want to take the v2 patch in
> the meantime?
>

Rafael,

ok. Caught up with the entire thread. v2 patch uses dev_info() and hence 
same concern about format change applies to that one as well.

Do you want to take the v1 patch that didn't change the format and just 
added the additional information at the end?

https://lkml.org/lkml/2013/6/14/330

-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Monday, June 24, 2013 04:37:28 PM Shuah Khan wrote:
> On 06/24/2013 10:25 AM, Shuah Khan wrote:
> > On 06/23/2013 03:49 PM, Rafael J. Wysocki wrote:
> >> On Sunday, June 23, 2013 04:34:17 AM Joe Perches wrote:
> >>> On Sun, 2013-06-23 at 13:36 +0200, Rafael J. Wysocki wrote:
> >>>> Please keep the existing format as is literally and append any
> >>>> new information to the end of the line.
> >>>
> >>> Hi Shuah.
> >>>
> >>> Perhaps the better long-term approach would be to add
> >>> a new tracepoint too.
> >>
> >> In fact, I would even prefer it if new tracepoints were added so that we
> >> could deprecate the dmesg messages at one point in the future.
> >>
> >> Thanks,
> >> Rafael
> >>
> >>
> >
> > Rafael/Joe,
> >
> > I can work on adding a tracepoint. Do you want to take the v2 patch in
> > the meantime?
> >
> 
> Rafael,
> 
> ok. Caught up with the entire thread. v2 patch uses dev_info() and hence 
> same concern about format change applies to that one as well.
> 
> Do you want to take the v1 patch that didn't change the format and just 
> added the additional information at the end?

Well, if you're going to work on the tracepoints, I'll rather not take this
at all.

Thanks,
Rafael


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

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Shuah Khan]

On 06/24/2013 01:35 PM, Rafael J. Wysocki wrote:
> On Monday, June 24, 2013 04:37:28 PM Shuah Khan wrote:
>> On 06/24/2013 10:25 AM, Shuah Khan wrote:
>>> On 06/23/2013 03:49 PM, Rafael J. Wysocki wrote:
>>>> On Sunday, June 23, 2013 04:34:17 AM Joe Perches wrote:
>>>>> On Sun, 2013-06-23 at 13:36 +0200, Rafael J. Wysocki wrote:
>>>>>> Please keep the existing format as is literally and append any
>>>>>> new information to the end of the line.
>>>>>
>>>>> Hi Shuah.
>>>>>
>>>>> Perhaps the better long-term approach would be to add
>>>>> a new tracepoint too.
>>>>
>>>> In fact, I would even prefer it if new tracepoints were added so that we
>>>> could deprecate the dmesg messages at one point in the future.
>>>>
>>>> Thanks,
>>>> Rafael
>>>>
>>>>
>>>
>>> Rafael/Joe,
>>>
>>> I can work on adding a tracepoint. Do you want to take the v2 patch in
>>> the meantime?
>>>
>>
>> Rafael,
>>
>> ok. Caught up with the entire thread. v2 patch uses dev_info() and hence
>> same concern about format change applies to that one as well.
>>
>> Do you want to take the v1 patch that didn't change the format and just
>> added the additional information at the end?
>
> Well, if you're going to work on the tracepoints, I'll rather not take this
> at all.
>
> Thanks,
> Rafael
>
>

Makes sense. Yes I am going to start work on tracepoints then.

-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Joe Perches]

On Sat, 2013-06-22 at 02:24 +0200, Rafael J. Wysocki wrote:
> Namely, there are tools that use these messages to create suspend/resume time
> charts and they will stop working after the proposed changes.

dmesg output isn't guaranteed to be stable.

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Friday, June 21, 2013 07:27:22 PM Joe Perches wrote:
> On Sat, 2013-06-22 at 02:24 +0200, Rafael J. Wysocki wrote:
> > Namely, there are tools that use these messages to create suspend/resume time
> > charts and they will stop working after the proposed changes.
> 
> dmesg output isn't guaranteed to be stable.

So?

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Joe Perches]

On Sat, 2013-06-22 at 21:52 +0200, Rafael J. Wysocki wrote:
> On Friday, June 21, 2013 07:27:22 PM Joe Perches wrote:
> > On Sat, 2013-06-22 at 02:24 +0200, Rafael J. Wysocki wrote:
> > > Namely, there are tools that use these messages to create suspend/resume time
> > > charts and they will stop working after the proposed changes.
> > 
> > dmesg output isn't guaranteed to be stable.
> 
> So?

So even if new information was only appended to
the existing line, the script could break.

If any script needs something stable it should
depend on information available through other
sources like trace or proc or sysfs.

Tools that use dmesg should adapt to whatever gets
thrown at it and handle the output from whatever
kernel versions the script supports.

For instance, what happens to the script when
console_level is set to 1?

Requiring that no one can change a dmesg to
add or improve the content for readability
or intelligibility I think unreasonable.

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Pavel Machek]

On Sat 2013-06-22 18:05:50, Joe Perches wrote:
> On Sat, 2013-06-22 at 21:52 +0200, Rafael J. Wysocki wrote:
> > On Friday, June 21, 2013 07:27:22 PM Joe Perches wrote:
> > > On Sat, 2013-06-22 at 02:24 +0200, Rafael J. Wysocki wrote:
> > > > Namely, there are tools that use these messages to create suspend/resume time
> > > > charts and they will stop working after the proposed changes.
> > > 
> > > dmesg output isn't guaranteed to be stable.
> > 
> > So?
> 
> So even if new information was only appended to
> the existing line, the script could break.
> 
> If any script needs something stable it should
> depend on information available through other
> sources like trace or proc or sysfs.

Yeah, people try to add it to debugfs, and the results were not nice.

dmesg output is not stable, but we should not break it unneccessarily;
appending at the end should be fine.
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> On Sat, 2013-06-22 at 21:52 +0200, Rafael J. Wysocki wrote:
> > On Friday, June 21, 2013 07:27:22 PM Joe Perches wrote:
> > > On Sat, 2013-06-22 at 02:24 +0200, Rafael J. Wysocki wrote:
> > > > Namely, there are tools that use these messages to create suspend/resume time
> > > > charts and they will stop working after the proposed changes.
> > > 
> > > dmesg output isn't guaranteed to be stable.
> > 
> > So?
> 
> So even if new information was only appended to
> the existing line, the script could break.

In this particular case, if it is written sanely, it won't.

> If any script needs something stable it should
> depend on information available through other
> sources like trace or proc or sysfs.

That is clearly impossible in this particular case, though.

> Tools that use dmesg should adapt to whatever gets
> thrown at it and handle the output from whatever
> kernel versions the script supports.
> 
> For instance, what happens to the script when
> console_level is set to 1?

You know, these particular messages are not printed without initcall_debug in
the command line and the people who use them for diagnostics usually generate
them on purpose and *then* feed the log to the script (or tool).

> Requiring that no one can change a dmesg to
> add or improve the content for readability
> or intelligibility I think unreasonable.

In general, you'd be right, but this is not a general case.

Thanks,
Rafael


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

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Joe Perches]

On Sun, 2013-06-23 at 12:07 +0200, Rafael J. Wysocki wrote:
> On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> > If any script needs something stable it should
> > depend on information available through other
> > sources like trace or proc or sysfs.
> 
> That is clearly impossible in this particular case, though.

Why couldn't this printk be converted into an equivalent tracepoint?

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Sunday, June 23, 2013 03:03:31 AM Joe Perches wrote:
> On Sun, 2013-06-23 at 12:07 +0200, Rafael J. Wysocki wrote:
> > On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> > > If any script needs something stable it should
> > > depend on information available through other
> > > sources like trace or proc or sysfs.
> > 
> > That is clearly impossible in this particular case, though.
> 
> Why couldn't this printk be converted into an equivalent tracepoint?

Well, why wouldn't you try to do that?

Rafael

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Joe Perches]

On Sun, 2013-06-23 at 12:22 +0200, Rafael J. Wysocki wrote:
> On Sunday, June 23, 2013 03:03:31 AM Joe Perches wrote:
> > On Sun, 2013-06-23 at 12:07 +0200, Rafael J. Wysocki wrote:
> > > On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> > > > If any script needs something stable it should
> > > > depend on information available through other
> > > > sources like trace or proc or sysfs.
> > > 
> > > That is clearly impossible in this particular case, though.
> > 
> > Why couldn't this printk be converted into an equivalent tracepoint?
> 
> Well, why wouldn't you try to do that?

Why should I?

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Sunday, June 23, 2013 03:16:30 AM Joe Perches wrote:
> On Sun, 2013-06-23 at 12:22 +0200, Rafael J. Wysocki wrote:
> > On Sunday, June 23, 2013 03:03:31 AM Joe Perches wrote:
> > > On Sun, 2013-06-23 at 12:07 +0200, Rafael J. Wysocki wrote:
> > > > On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> > > > > If any script needs something stable it should
> > > > > depend on information available through other
> > > > > sources like trace or proc or sysfs.
> > > > 
> > > > That is clearly impossible in this particular case, though.
> > > 
> > > Why couldn't this printk be converted into an equivalent tracepoint?
> > 
> > Well, why wouldn't you try to do that?
> 
> Why should I?

Because you're arguing that it should be done.

If you think that it's better to use tracepoints here, please implement those
tracepoints and show everyone that they are really better than what we have.

Till then, we'll use what's already there.

Thanks,
Rafael

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Joe Perches]

On Sun, 2013-06-23 at 12:35 +0200, Rafael J. Wysocki wrote:
> On Sunday, June 23, 2013 03:16:30 AM Joe Perches wrote:
> > On Sun, 2013-06-23 at 12:22 +0200, Rafael J. Wysocki wrote:
> > > On Sunday, June 23, 2013 03:03:31 AM Joe Perches wrote:
> > > > On Sun, 2013-06-23 at 12:07 +0200, Rafael J. Wysocki wrote:
> > > > > On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> > > > > > If any script needs something stable it should
> > > > > > depend on information available through other
> > > > > > sources like trace or proc or sysfs.
> > > > > 
> > > > > That is clearly impossible in this particular case, though.
> > > > 
> > > > Why couldn't this printk be converted into an equivalent tracepoint?
> > > 
> > > Well, why wouldn't you try to do that?
> > 
> > Why should I?
>
> Because you're arguing that it should be done.
>
> If you think that it's better to use tracepoints here, please implement those
> tracepoints and show everyone that they are really better than what we have.

Nope, you're arguing that dmesg output, known to be non-stable,
should not have this particular message changed.

You stated "<it's> clearly impossible".  I do dispute that.

If you need something stable, you shouldn't use dmesg,
That's a simple statement, not anything else.

Right now, I don't care if this particular message changes.
I'm not doing any PM testing or timing at the moment.

> Till then, we'll use what's already there.

Fine by me.  It's up to Shuah Khan to get a patch accepted.

cheers, Joe

Re: [PATCHv v3] power: Include additional information in pm_print_times

[Rafael J. Wysocki]

On Sunday, June 23, 2013 03:41:20 AM Joe Perches wrote:
> On Sun, 2013-06-23 at 12:35 +0200, Rafael J. Wysocki wrote:
> > On Sunday, June 23, 2013 03:16:30 AM Joe Perches wrote:
> > > On Sun, 2013-06-23 at 12:22 +0200, Rafael J. Wysocki wrote:
> > > > On Sunday, June 23, 2013 03:03:31 AM Joe Perches wrote:
> > > > > On Sun, 2013-06-23 at 12:07 +0200, Rafael J. Wysocki wrote:
> > > > > > On Saturday, June 22, 2013 06:05:50 PM Joe Perches wrote:
> > > > > > > If any script needs something stable it should
> > > > > > > depend on information available through other
> > > > > > > sources like trace or proc or sysfs.
> > > > > > 
> > > > > > That is clearly impossible in this particular case, though.
> > > > > 
> > > > > Why couldn't this printk be converted into an equivalent tracepoint?
> > > > 
> > > > Well, why wouldn't you try to do that?
> > > 
> > > Why should I?
> >
> > Because you're arguing that it should be done.
> >
> > If you think that it's better to use tracepoints here, please implement those
> > tracepoints and show everyone that they are really better than what we have.
> 
> Nope, you're arguing that dmesg output, known to be non-stable,
> should not have this particular message changed.
> 
> You stated "<it's> clearly impossible".  I do dispute that.

And what I meant by that was "there are no tracepoints, sysfs attributes etc.
those tools can use to get the information they need".  Which is a fact of
life.

> If you need something stable, you shouldn't use dmesg,
> That's a simple statement, not anything else.
> 
> Right now, I don't care if this particular message changes.
> I'm not doing any PM testing or timing at the moment.
> 
> > Till then, we'll use what's already there.
> 
> Fine by me.  It's up to Shuah Khan to get a patch accepted.

Well, precisely.

Thanks,
Rafael


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