Re: [PATCH] PM: trace events for suspend/resume

["Srivatsa S. Bhat" <srivatsa.bhat@linux.vnet.ibm.com>]

On 05/23/2014 05:20 AM, Todd E Brandt wrote:
> On Fri, May 23, 2014 at 03:46:54AM +0530, Srivatsa S. Bhat wrote:
>> On 05/22/2014 05:31 AM, Rafael J. Wysocki wrote:
>>> On Monday, May 19, 2014 04:02:26 PM Todd E Brandt wrote:
>>>> Adds trace events that give finer resolution into suspend/resume. These
>>>> events are graphed in the timelines generated by the analyze_suspend.py
>>>> script. They represent large areas of time consumed that are typical in
>>>> suspend and resume.
>>>>
>>>> The event is triggered by calling the function "trace_suspend_resume"
>>>> with two arguments: a string (the name of the event to be displayed
>>>> in the timeline), and a boolean (where true is used to denote the start
>>>> of the timeline event, and false to denote the end).
>>>>
>>>> Signed-off-by: Todd Brandt <todd.e.brandt@intel.com>
>>>> ---
>>>>  drivers/acpi/nvs.c           |  6 ++++++
>>>>  drivers/acpi/osl.c           |  3 +++
>>>>  drivers/base/syscore.c       |  5 +++++
>>>>  include/trace/events/power.h | 19 +++++++++++++++++++
>>>>  kernel/cpu.c                 |  9 +++++++++
>>>>  kernel/power/process.c       |  3 +++
>>>>  kernel/power/suspend.c       |  4 ++++
>>>>  7 files changed, 49 insertions(+)
>>>>
>>>> For more info see:
>>>> https://01.org/suspendresume/blogs/tebrandt/2014/custom-timeline-event-support-0
>>>>
>>>> I'm also interested to know if any tools depend on the machine_suspend
>>>> tracepoints, as this patch expands on the same info. I'd be willing to
>>>> merge the existing machine_suspend calls into this patch and rename
>>>> everything to suspend_resume provided it doesn't hurt any downstream tools.
>>>>
>>>> diff --git a/drivers/acpi/nvs.c b/drivers/acpi/nvs.c
>>>> index de4fe03..b52b686 100644
>>>> --- a/drivers/acpi/nvs.c
>>>> +++ b/drivers/acpi/nvs.c
>>>> @@ -12,6 +12,7 @@
>>>>  #include <linux/mm.h>
>>>>  #include <linux/slab.h>
>>>>  #include <linux/acpi.h>
>>>> +#include <trace/events/power.h>
>>>>  
>>>>  #include "internal.h"
>>>>  
>>>> @@ -171,6 +172,7 @@ int suspend_nvs_save(void)
>>>>  {
>>>>  	struct nvs_page *entry;
>>>>  
>>>> +	trace_suspend_resume("save_nvs_memory", true);
>>>>  	printk(KERN_INFO "PM: Saving platform NVS memory\n");
>>>>  
>>>>  	list_for_each_entry(entry, &nvs_list, node)
>>>> @@ -185,11 +187,13 @@ int suspend_nvs_save(void)
>>>>  			}
>>>>  			if (!entry->kaddr) {
>>>>  				suspend_nvs_free();
>>>> +				trace_suspend_resume("save_nvs_memory", false);
>>>>  				return -ENOMEM;
>>>>  			}
>>>>  			memcpy(entry->data, entry->kaddr, entry->size);
>>>>  		}
>>>>  
>>>> +	trace_suspend_resume("save_nvs_memory", false);
>>>>  	return 0;
>>>>  }
>>>>  
>>>> @@ -203,10 +207,12 @@ void suspend_nvs_restore(void)
>>>>  {
>>>>  	struct nvs_page *entry;
>>>>  
>>>> +	trace_suspend_resume("restore_nvs_memory", true);
>>>>  	printk(KERN_INFO "PM: Restoring platform NVS memory\n");
>>>>  
>>>>  	list_for_each_entry(entry, &nvs_list, node)
>>>>  		if (entry->data)
>>>>  			memcpy(entry->kaddr, entry->data, entry->size);
>>>> +	trace_suspend_resume("restore_nvs_memory", false);
>>>>  }
>>>>  #endif
>>>> diff --git a/drivers/acpi/osl.c b/drivers/acpi/osl.c
>>>> index 6776c59..b65a77a 100644
>>>> --- a/drivers/acpi/osl.c
>>>> +++ b/drivers/acpi/osl.c
>>>> @@ -44,6 +44,7 @@
>>>>  #include <linux/list.h>
>>>>  #include <linux/jiffies.h>
>>>>  #include <linux/semaphore.h>
>>>> +#include <trace/events/power.h>
>>>>  
>>>>  #include <asm/io.h>
>>>>  #include <asm/uaccess.h>
>>>> @@ -835,7 +836,9 @@ acpi_status acpi_os_remove_interrupt_handler(u32 irq, acpi_osd_handler handler)
>>>>  
>>>>  void acpi_os_sleep(u64 ms)
>>>>  {
>>>> +	trace_suspend_resume("acpi_os_sleep", true);
>>>>  	msleep(ms);
>>>> +	trace_suspend_resume("acpi_os_sleep", false);
>>>>  }
>>>
>>> This function doesn't have anything to do with system suspend/resume.
>>> It is for waiting. :-)
>>>
>>> The rest of the patch looks OK to me.
>>>
>>> Steven, what about the tracing angle?
>>>
>>
>> Hi Todd,
>>
>> This might be a silly question, but the suspend_enter() function invokes
>> ftrace_stop() before suspending the machine, and restarts ftrace after
>> resume. And your patch seems to instrument code further down (deeper)
>> in the suspend/resume path (such as disable_nonboot_cpus() for example).
>> Doesn't the ftrace stop/start pose any problem for this patch?
> 
> I put a patch in the kernel a few months back that allowed ftrace to
> function all the way through to disable/enable_nonboot_cpus. So the
> actual trace code includes everything up to the actual CPU suspend/resume.
> And also (as Steven mentioned), the tracepoint activity isn't controlled
> via ftrace_start/ftrace_stop, those are for tracer based logging.
> 

Cool, thanks!

Regards,
Srivatsa S. Bhat