[PATCH] ACPI: Read TSC upon resume

[PATCH] ACPI: Read TSC upon resume

[Sameer Nanda]

Read the TSC upon resuming and print it out. This is useful
in helping figure out amount of time spent in the BIOS when
resuming from suspend.

Change-Id: I1d6a32bd62421becddecd152d561763e5f3e1101
Signed-off-by: Sameer Nanda <snanda@chromium.org>
---
 drivers/acpi/sleep.c |    4 ++++
 1 files changed, 4 insertions(+), 0 deletions(-)

diff --git a/drivers/acpi/sleep.c b/drivers/acpi/sleep.c
index c0fed2e..f0588fa 100644
--- a/drivers/acpi/sleep.c
+++ b/drivers/acpi/sleep.c
@@ -214,6 +214,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
 	acpi_status status = AE_OK;
 	unsigned long flags = 0;
 	u32 acpi_state = acpi_target_sleep_state;
+	u64 tsc;
 
 	ACPI_FLUSH_CPU_CACHE();
 
@@ -235,6 +236,9 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
 
 	case ACPI_STATE_S3:
 		do_suspend_lowlevel();
+		rdtscll(tsc);
+		printk(KERN_INFO "TSC at resume: %llu\n",
+				(unsigned long long)tsc);
 		break;
 	}
 
-- 
1.7.1

Re: [PATCH] ACPI: Read TSC upon resume

[Greg KH]

On Wed, Oct 06, 2010 at 04:15:19PM -0700, Sameer Nanda wrote:
> Read the TSC upon resuming and print it out. This is useful
> in helping figure out amount of time spent in the BIOS when
> resuming from suspend.
> 
> Change-Id: I1d6a32bd62421becddecd152d561763e5f3e1101

What is this tag for?  I don't think it matches anything the kernel
community wants, do you?

And are you always going to be printing this out?  Why do we want to
know this every time?


> Signed-off-by: Sameer Nanda <snanda@chromium.org>
> ---
>  drivers/acpi/sleep.c |    4 ++++
>  1 files changed, 4 insertions(+), 0 deletions(-)
> 
> diff --git a/drivers/acpi/sleep.c b/drivers/acpi/sleep.c
> index c0fed2e..f0588fa 100644
> --- a/drivers/acpi/sleep.c
> +++ b/drivers/acpi/sleep.c
> @@ -214,6 +214,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
>  	acpi_status status = AE_OK;
>  	unsigned long flags = 0;
>  	u32 acpi_state = acpi_target_sleep_state;
> +	u64 tsc;
>  
>  	ACPI_FLUSH_CPU_CACHE();
>  
> @@ -235,6 +236,9 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
>  
>  	case ACPI_STATE_S3:
>  		do_suspend_lowlevel();
> +		rdtscll(tsc);
> +		printk(KERN_INFO "TSC at resume: %llu\n",
> +				(unsigned long long)tsc);

How long does this take, will it slow down resume?

thanks,

greg k-h

Re: [PATCH] ACPI: Read TSC upon resume

[Greg KH]

On Thu, Oct 07, 2010 at 10:43:34AM -0700, Sameer Nanda wrote:
> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> > And are you always going to be printing this out?  Why do we want to
> > know this every time?
> >
> 
> Yes, every time.  This helps track variance in BIOS resume times within a
> single boot.

Is that really something that users can do something about?  I can
understand when you are trying to work with a BIOS company, but
otherwise, this seems quite pointless.

thanks,

greg k-h

Re: [PATCH] ACPI: Read TSC upon resume

[Sameer Nanda]

On Thu, Oct 7, 2010 at 10:46 AM, Greg KH <gregkh@suse.de> wrote:
> On Thu, Oct 07, 2010 at 10:43:34AM -0700, Sameer Nanda wrote:
>> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
>> > And are you always going to be printing this out?  Why do we want to
>> > know this every time?
>> >
>>
>> Yes, every time.  This helps track variance in BIOS resume times within a
>> single boot.
>
> Is that really something that users can do something about?

Aside from complaining to the BIOS vendors, no :)

> I can
> understand when you are trying to work with a BIOS company, but
> otherwise, this seems quite pointless.
>
> thanks,
>
> greg k-h
>



-- 
Sameer

Re: [PATCH] ACPI: Read TSC upon resume

[Greg KH]

On Thu, Oct 07, 2010 at 11:05:21AM -0700, Sameer Nanda wrote:
> On Thu, Oct 7, 2010 at 10:46 AM, Greg KH <gregkh@suse.de> wrote:
> > On Thu, Oct 07, 2010 at 10:43:34AM -0700, Sameer Nanda wrote:
> >> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> >> > And are you always going to be printing this out?  Why do we want to
> >> > know this every time?
> >> >
> >>
> >> Yes, every time.  This helps track variance in BIOS resume times within a
> >> single boot.
> >
> > Is that really something that users can do something about?
> 
> Aside from complaining to the BIOS vendors, no :)

Then I would not recommend adding this patch, as it is irrelevant for
99.9999% of all Linux users.

thanks,

greg k-h

Re: [PATCH] ACPI: Read TSC upon resume

[Rafael J. Wysocki]

On Thursday, October 07, 2010, Greg KH wrote:
> On Thu, Oct 07, 2010 at 11:05:21AM -0700, Sameer Nanda wrote:
> > On Thu, Oct 7, 2010 at 10:46 AM, Greg KH <gregkh@suse.de> wrote:
> > > On Thu, Oct 07, 2010 at 10:43:34AM -0700, Sameer Nanda wrote:
> > >> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> > >> > And are you always going to be printing this out?  Why do we want to
> > >> > know this every time?
> > >> >
> > >>
> > >> Yes, every time.  This helps track variance in BIOS resume times within a
> > >> single boot.
> > >
> > > Is that really something that users can do something about?
> > 
> > Aside from complaining to the BIOS vendors, no :)
> 
> Then I would not recommend adding this patch, as it is irrelevant for
> 99.9999% of all Linux users.

It may be somewhat useful, but the rdtscll() call seems to be x86-specific, in
which case it shouldn't be used at this place.

Thanks,
Rafael

RE: [PATCH] ACPI: Read TSC upon resume

[Koornstra, Reinoud]

> -----Original Message-----
> From: linux-acpi-owner@vger.kernel.org [mailto:linux-acpi-
> owner@vger.kernel.org] On Behalf Of Rafael J. Wysocki
> Sent: Thursday, October 07, 2010 2:44 PM
> To: Greg KH
> Cc: Sameer Nanda; lenb@kernel.org; stefan.bader@canonical.com;
> brad.figg@canonical.com; apw@canonical.com; linux-acpi@vger.kernel.org;
> linux-kernel@vger.kernel.org
> Subject: Re: [PATCH] ACPI: Read TSC upon resume
> 
> On Thursday, October 07, 2010, Greg KH wrote:
> > On Thu, Oct 07, 2010 at 11:05:21AM -0700, Sameer Nanda wrote:
> > > On Thu, Oct 7, 2010 at 10:46 AM, Greg KH <gregkh@suse.de> wrote:
> > > > On Thu, Oct 07, 2010 at 10:43:34AM -0700, Sameer Nanda wrote:
> > > >> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> > > >> > And are you always going to be printing this out?  Why do we
> want to
> > > >> > know this every time?
> > > >> >
> > > >>
> > > >> Yes, every time.  This helps track variance in BIOS resume times
> within a
> > > >> single boot.
> > > >
> > > > Is that really something that users can do something about?
> > >
> > > Aside from complaining to the BIOS vendors, no :)
> >
> > Then I would not recommend adding this patch, as it is irrelevant for
> > 99.9999% of all Linux users.
> 
> It may be somewhat useful, but the rdtscll() call seems to be x86-
> specific, in
> which case it shouldn't be used at this place.

Also, in the case of an intel core 2 duo cpu, the tsc is not stable, hence upon resume the cpu is spinning up and the first tsc's will be slower.
During idle-time the tsc will not be incremented. The tsc is only stably incremented upon 100% cpu usage. It also doesn't increment faster in turbo mode in case of some core 2 duo and certainly the Nehalem cpu's. Calculating in time in terms of tsc might not be so reliable.

> 
> Thanks,
> Rafael
> --
> To unsubscribe from this list: send the line "unsubscribe linux-acpi"
> in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH] ACPI: Read TSC upon resume

[Chen Gong]

于 10/16/2010 11:03 AM, Koornstra, Reinoud 写道:
>> -----Original Message-----
>> From: linux-acpi-owner@vger.kernel.org [mailto:linux-acpi-
>> owner@vger.kernel.org] On Behalf Of Rafael J. Wysocki
>> Sent: Thursday, October 07, 2010 2:44 PM
>> To: Greg KH
>> Cc: Sameer Nanda; lenb@kernel.org; stefan.bader@canonical.com;
>> brad.figg@canonical.com; apw@canonical.com; linux-acpi@vger.kernel.org;
>> linux-kernel@vger.kernel.org
>> Subject: Re: [PATCH] ACPI: Read TSC upon resume
>>
>> On Thursday, October 07, 2010, Greg KH wrote:
>>> On Thu, Oct 07, 2010 at 11:05:21AM -0700, Sameer Nanda wrote:
>>>> On Thu, Oct 7, 2010 at 10:46 AM, Greg KH<gregkh@suse.de>  wrote:
>>>>> On Thu, Oct 07, 2010 at 10:43:34AM -0700, Sameer Nanda wrote:
>>>>>> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH<gregkh@suse.de>  wrote:
>>>>>>> And are you always going to be printing this out?  Why do we
>> want to
>>>>>>> know this every time?
>>>>>>>
>>>>>>
>>>>>> Yes, every time.  This helps track variance in BIOS resume times
>> within a
>>>>>> single boot.
>>>>>
>>>>> Is that really something that users can do something about?
>>>>
>>>> Aside from complaining to the BIOS vendors, no :)
>>>
>>> Then I would not recommend adding this patch, as it is irrelevant for
>>> 99.9999% of all Linux users.
>>
>> It may be somewhat useful, but the rdtscll() call seems to be x86-
>> specific, in
>> which case it shouldn't be used at this place.
>
> Also, in the case of an intel core 2 duo cpu, the tsc is not stable, hence upon resume the cpu is spinning up and the first tsc's will be slower.
> During idle-time the tsc will not be incremented. The tsc is only stably incremented upon 100% cpu usage. It also doesn't increment faster in turbo mode in case of some core 2 duo and certainly the Nehalem cpu's. Calculating in time in terms of tsc might not be so reliable.
>
If I'm wrong, please feel free to fix me.

I have 2 questions to your answer:

1.  CPU has a flag named constant_tsc to keep TSC always working in a 
constant way, so it is irrelvant to the CPU freq. whether in turbo mode 
or any P-state CPU currently belongs to, TSC should be not affected. 
IIRC, this flag should exist long before, at least before Core 2 duo. If 
so, TSC shoule be stable in this kind of environment.

2. though during idle-time TSC will not be incremented, here I want to
remind it is right before Westmere (TSC not always running), and you 
mentioned "upon resume the cpu is spinning up and the first tsc's will 
be slower", I don't know if this commit cd7240c0b can fix it up.

Re: [PATCH] ACPI: Read TSC upon resume

[Sameer Nanda]

(resending as plain text, sorry if you got dupe messages)

On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> On Wed, Oct 06, 2010 at 04:15:19PM -0700, Sameer Nanda wrote:
>> Read the TSC upon resuming and print it out. This is useful
>> in helping figure out amount of time spent in the BIOS when
>> resuming from suspend.
>>
>> Change-Id: I1d6a32bd62421becddecd152d561763e5f3e1101
>
> What is this tag for?  I don't think it matches anything the kernel
> community wants, do you?

Yeah, its not needed.  Let me resubmit the patch without this tag.

>
> And are you always going to be printing this out?  Why do we want to
> know this every time?

Yes, every time.  This helps track variance in BIOS resume times
within a single boot.

>
>> Signed-off-by: Sameer Nanda <snanda@chromium.org>
>> ---
>>  drivers/acpi/sleep.c |    4 ++++
>>  1 files changed, 4 insertions(+), 0 deletions(-)
>>
>> diff --git a/drivers/acpi/sleep.c b/drivers/acpi/sleep.c
>> index c0fed2e..f0588fa 100644
>> --- a/drivers/acpi/sleep.c
>> +++ b/drivers/acpi/sleep.c
>> @@ -214,6 +214,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
>>       acpi_status status = AE_OK;
>>       unsigned long flags = 0;
>>       u32 acpi_state = acpi_target_sleep_state;
>> +     u64 tsc;
>>
>>       ACPI_FLUSH_CPU_CACHE();
>>
>> @@ -235,6 +236,9 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
>>
>>       case ACPI_STATE_S3:
>>               do_suspend_lowlevel();
>> +             rdtscll(tsc);
>> +             printk(KERN_INFO "TSC at resume: %llu\n",
>> +                             (unsigned long long)tsc);
>
> How long does this take, will it slow down resume?

The impact is ~10us (as measured on an Intel Atom N455 @ 1.66Ghz).
Given that resume time is currently of the order of 1sec, its in the
noise range.

Thanks for the feedback!

>
> thanks,
>
> greg k-h
>



-- 
Sameer

Re: [PATCH] ACPI: Read TSC upon resume

[Rafael J. Wysocki]

On Thursday, October 07, 2010, Sameer Nanda wrote:
> (resending as plain text, sorry if you got dupe messages)
> 
> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> > On Wed, Oct 06, 2010 at 04:15:19PM -0700, Sameer Nanda wrote:
> >> Read the TSC upon resuming and print it out. This is useful
> >> in helping figure out amount of time spent in the BIOS when
> >> resuming from suspend.
> >>
> >> Change-Id: I1d6a32bd62421becddecd152d561763e5f3e1101
> >
> > What is this tag for?  I don't think it matches anything the kernel
> > community wants, do you?
> 
> Yeah, its not needed.  Let me resubmit the patch without this tag.
> 
> >
> > And are you always going to be printing this out?  Why do we want to
> > know this every time?
> 
> Yes, every time.  This helps track variance in BIOS resume times
> within a single boot.
> 
> >
> >> Signed-off-by: Sameer Nanda <snanda@chromium.org>
> >> ---
> >>  drivers/acpi/sleep.c |    4 ++++
> >>  1 files changed, 4 insertions(+), 0 deletions(-)
> >>
> >> diff --git a/drivers/acpi/sleep.c b/drivers/acpi/sleep.c
> >> index c0fed2e..f0588fa 100644
> >> --- a/drivers/acpi/sleep.c
> >> +++ b/drivers/acpi/sleep.c
> >> @@ -214,6 +214,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
> >>       acpi_status status = AE_OK;
> >>       unsigned long flags = 0;
> >>       u32 acpi_state = acpi_target_sleep_state;
> >> +     u64 tsc;
> >>
> >>       ACPI_FLUSH_CPU_CACHE();
> >>
> >> @@ -235,6 +236,9 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
> >>
> >>       case ACPI_STATE_S3:
> >>               do_suspend_lowlevel();
> >> +             rdtscll(tsc);
> >> +             printk(KERN_INFO "TSC at resume: %llu\n",
> >> +                             (unsigned long long)tsc);
> >
> > How long does this take, will it slow down resume?
> 
> The impact is ~10us (as measured on an Intel Atom N455 @ 1.66Ghz).
> Given that resume time is currently of the order of 1sec, its in the
> noise range.

Do I think correctly that it assumes the TSC will be updated in the sleep state?

Rafael

Re: [PATCH] ACPI: Read TSC upon resume

[Sameer Nanda]

On Thu, Oct 7, 2010 at 12:59 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> On Thursday, October 07, 2010, Sameer Nanda wrote:
>> (resending as plain text, sorry if you got dupe messages)
>>
>> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
>> > On Wed, Oct 06, 2010 at 04:15:19PM -0700, Sameer Nanda wrote:
>> >> Read the TSC upon resuming and print it out. This is useful
>> >> in helping figure out amount of time spent in the BIOS when
>> >> resuming from suspend.
>> >>
>> >> Change-Id: I1d6a32bd62421becddecd152d561763e5f3e1101
>> >
>> > What is this tag for?  I don't think it matches anything the kernel
>> > community wants, do you?
>>
>> Yeah, its not needed.  Let me resubmit the patch without this tag.
>>
>> >
>> > And are you always going to be printing this out?  Why do we want to
>> > know this every time?
>>
>> Yes, every time.  This helps track variance in BIOS resume times
>> within a single boot.
>>
>> >
>> >> Signed-off-by: Sameer Nanda <snanda@chromium.org>
>> >> ---
>> >>  drivers/acpi/sleep.c |    4 ++++
>> >>  1 files changed, 4 insertions(+), 0 deletions(-)
>> >>
>> >> diff --git a/drivers/acpi/sleep.c b/drivers/acpi/sleep.c
>> >> index c0fed2e..f0588fa 100644
>> >> --- a/drivers/acpi/sleep.c
>> >> +++ b/drivers/acpi/sleep.c
>> >> @@ -214,6 +214,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
>> >>       acpi_status status = AE_OK;
>> >>       unsigned long flags = 0;
>> >>       u32 acpi_state = acpi_target_sleep_state;
>> >> +     u64 tsc;
>> >>
>> >>       ACPI_FLUSH_CPU_CACHE();
>> >>
>> >> @@ -235,6 +236,9 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
>> >>
>> >>       case ACPI_STATE_S3:
>> >>               do_suspend_lowlevel();
>> >> +             rdtscll(tsc);
>> >> +             printk(KERN_INFO "TSC at resume: %llu\n",
>> >> +                             (unsigned long long)tsc);
>> >
>> > How long does this take, will it slow down resume?
>>
>> The impact is ~10us (as measured on an Intel Atom N455 @ 1.66Ghz).
>> Given that resume time is currently of the order of 1sec, its in the
>> noise range.
>
> Do I think correctly that it assumes the TSC will be updated in the sleep state?

No, it actually banks on TSC not being updated while the system is in S3 state.
Theory here being that upon resuming from S3, the CPU gets reset and so TSC
starts counting up from 0.  Therefore, reading the TSC value in the kernel upon
resuming gives the number of cycles spent in the BIOS in resume path.

>
> Rafael
>



-- 
Sameer

Re: [PATCH] ACPI: Read TSC upon resume

[Rafael J. Wysocki]

On Thursday, October 07, 2010, Sameer Nanda wrote:
> On Thu, Oct 7, 2010 at 12:59 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> > On Thursday, October 07, 2010, Sameer Nanda wrote:
> >> (resending as plain text, sorry if you got dupe messages)
> >>
> >> On Wed, Oct 6, 2010 at 7:19 PM, Greg KH <gregkh@suse.de> wrote:
> >> > On Wed, Oct 06, 2010 at 04:15:19PM -0700, Sameer Nanda wrote:
> >> >> Read the TSC upon resuming and print it out. This is useful
> >> >> in helping figure out amount of time spent in the BIOS when
> >> >> resuming from suspend.
> >> >>
> >> >> Change-Id: I1d6a32bd62421becddecd152d561763e5f3e1101
> >> >
> >> > What is this tag for?  I don't think it matches anything the kernel
> >> > community wants, do you?
> >>
> >> Yeah, its not needed.  Let me resubmit the patch without this tag.
> >>
> >> >
> >> > And are you always going to be printing this out?  Why do we want to
> >> > know this every time?
> >>
> >> Yes, every time.  This helps track variance in BIOS resume times
> >> within a single boot.
> >>
> >> >
> >> >> Signed-off-by: Sameer Nanda <snanda@chromium.org>
> >> >> ---
> >> >>  drivers/acpi/sleep.c |    4 ++++
> >> >>  1 files changed, 4 insertions(+), 0 deletions(-)
> >> >>
> >> >> diff --git a/drivers/acpi/sleep.c b/drivers/acpi/sleep.c
> >> >> index c0fed2e..f0588fa 100644
> >> >> --- a/drivers/acpi/sleep.c
> >> >> +++ b/drivers/acpi/sleep.c
> >> >> @@ -214,6 +214,7 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
> >> >>       acpi_status status = AE_OK;
> >> >>       unsigned long flags = 0;
> >> >>       u32 acpi_state = acpi_target_sleep_state;
> >> >> +     u64 tsc;
> >> >>
> >> >>       ACPI_FLUSH_CPU_CACHE();
> >> >>
> >> >> @@ -235,6 +236,9 @@ static int acpi_suspend_enter(suspend_state_t pm_state)
> >> >>
> >> >>       case ACPI_STATE_S3:
> >> >>               do_suspend_lowlevel();
> >> >> +             rdtscll(tsc);
> >> >> +             printk(KERN_INFO "TSC at resume: %llu\n",
> >> >> +                             (unsigned long long)tsc);
> >> >
> >> > How long does this take, will it slow down resume?
> >>
> >> The impact is ~10us (as measured on an Intel Atom N455 @ 1.66Ghz).
> >> Given that resume time is currently of the order of 1sec, its in the
> >> noise range.
> >
> > Do I think correctly that it assumes the TSC will be updated in the sleep state?
> 
> No, it actually banks on TSC not being updated while the system is in S3 state.
> Theory here being that upon resuming from S3, the CPU gets reset and so TSC
> starts counting up from 0.  Therefore, reading the TSC value in the kernel upon
> resuming gives the number of cycles spent in the BIOS in resume path.

Ah that.  OK, that's more clear now.

Thanks,
Rafael