linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs
@ 2016-12-20 10:21 Chen Yu
  2016-12-20 10:56 ` Lukas Wunner
  2017-01-16  2:56 ` Chen Yu
  0 siblings, 2 replies; 6+ messages in thread
From: Chen Yu @ 2016-12-20 10:21 UTC (permalink / raw)
  To: x86, linux-pm
  Cc: Chen Yu, Thomas Gleixner, Ingo Molnar, H. Peter Anvin, Len Brown,
	Rafael J. Wysocki, Suresh Siddha, Borislav Petkov, Lukas Wunner,
	Brandt, Todd E, Rui Zhang, linux-kernel

This is a debug patch to descibe/workaround the issue
we encountered recently.

Problem and the cause:
Currently we are suffering from *extremely* slow CPU online
speed during system resuming from S3. Say, the MacBookPro 2015
has 4 CPUs, and it took more than 1 second each for both CPU1
and CPU3 to be brought back to idle thread again. Further ftrace
result showed that, *each* instruction the CPU1 and CPU3 execute
will take much longer time than it will take during normal cpu
online via sysfs(without S3 involved). And more interesting
thing was found that after resumed back, every instruction CPU1 and
CPU3 execute is back to its normal speed(unixbench has the same score
before/after S3). So it smells like there is something wrong with
the cache/tlb settings only during resuming back from S3.
Finally we have found this might be related to BIOS who has
scribbled the mtrr/pat before it resumed back to the OS, and every
instruction seems to be run in an uncached behavior, fortunately
later after all the APs have been brought up again, mtrr_aps_init()
will be invoked to synchronize the mtrr on these APs to the value
once saved by CPU0 before suspended, thus everything is back
to normal after resumed.

Workaround:
So it turns out to be that if we can synchronize the APs with boot CPU
ASAP, rather than waiting till all CPUS online, it might reduce the
impact of the bogus BIOS who scribbled the mtrr/pat. So here is the
hack patch to let the users to synchronize mtrr on APs earlier.
With the following debug patch applied, the resume time for CPU1 and
CPU3 have dropped a lot.

(Notice, the following result were tested with ftrace function_graph enabled
during suspend/resume, by this tool:
https://01.org/suspendresume


Before patch applied:
[  619.810899] Enabling non-boot CPUs ...
[  619.825528] x86: Booting SMP configuration:
[  619.825537] smpboot: Booting Node 0 Processor 1 APIC 0x2
-------skip--------
[  621.723809] CPU1 is up
[  621.762843] smpboot: Booting Node 0 Processor 2 APIC 0x1
-------skip--------
[  621.766679] CPU2 is up
[  621.840228] smpboot: Booting Node 0 Processor 3 APIC 0x3
-------skip--------
[  626.690900] CPU3 is up

So it took CPU1 621.723809 - 619.825537 = 1898.272 ms, and
CPU3 626.690900 - 621.840228 = 4850.672 ms !


After patch applied:
[  106.931790] smpboot: Booting Node 0 Processor 1 APIC 0x2
-------skip--------
[  106.948360] CPU1 is up
[  106.963975] smpboot: Booting Node 0 Processor 2 APIC 0x1
-------skip--------
[  106.968087] CPU2 is up
[  106.986534] smpboot: Booting Node 0 Processor 3 APIC 0x3
-------skip--------
[  106.990702] CPU3 is up

It took CPU1 106.948360 - 106.931790 = 16.57 ms, and
CPU3 106.990702 - 106.986534 = 4.16 ms

Question:
So it turns out to be a BIOS issue, but Linux should also deal with
this bogus BIOS, right? I studied the commit we delay the synchronization
until all the APs are brought up, and according to:

Commit d0af9eed5aa9 ("x86, pat/mtrr: Rendezvous all the cpus
for MTRR/PAT init")

It seems that there would be problem if we do not sync APs at the same
time(some CPUs run with cache disabled will hang the system, because its
sibling is trying to adjust the mtrr which might disable its cache) on
some special platforms? But I have a question that, even in our current
solution which defers the synchronization, the scenario mentioned above
can not be avoided because at the time CPU3 is trying to restore mtrr,
its sibling CPU1 might also be doing some kworker or ticking tasks,
the CPU1 might also run with cache disabled?
I'm not sure if I understand the code correctly, and it would be
appreciated if people could give any comments/suggestions on how to deal
with this situation found on MacProBook, and if you need me to do any test
please feel free to let me know.

Thanks,
Yu

Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: Len Brown <len.brown@intel.com>
Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net>
Cc: Suresh Siddha <sbsiddha@gmail.com>
Cc: Borislav Petkov <bp@suse.de>
Cc: Lukas Wunner <lukas@wunner.de>
Cc: "Brandt, Todd E" <todd.e.brandt@intel.com>
Cc: Rui Zhang <rui.zhang@intel.com>
Cc: linux-kernel@vger.kernel.org
Signed-off-by: Chen Yu <yu.c.chen@intel.com>
---
 arch/x86/kernel/cpu/mtrr/main.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/arch/x86/kernel/cpu/mtrr/main.c b/arch/x86/kernel/cpu/mtrr/main.c
index 24e87e7..eddaa89 100644
--- a/arch/x86/kernel/cpu/mtrr/main.c
+++ b/arch/x86/kernel/cpu/mtrr/main.c
@@ -813,15 +813,28 @@ void mtrr_save_state(void)
 	put_online_cpus();
 }
 
+static bool __read_mostly no_aps_delay;
+
+static int __init no_aps_setup(char *str)
+{
+	no_aps_delay = true;
+	pr_info("hack: do not delay aps mtrr/pat initialization.\n");
+
+	return 0;
+}
+
 void set_mtrr_aps_delayed_init(void)
 {
 	if (!mtrr_enabled())
 		return;
 	if (!use_intel())
 		return;
+	if (no_aps_delay)
+		return;
 
 	mtrr_aps_delayed_init = true;
 }
+early_param("no_aps_delay", no_aps_setup);
 
 /*
  * Delayed MTRR initialization for all AP's
-- 
2.7.4

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs
  2016-12-20 10:21 [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs Chen Yu
@ 2016-12-20 10:56 ` Lukas Wunner
  2016-12-21  2:32   ` Chen Yu
  2016-12-21  6:51   ` Chen Yu
  2017-01-16  2:56 ` Chen Yu
  1 sibling, 2 replies; 6+ messages in thread
From: Lukas Wunner @ 2016-12-20 10:56 UTC (permalink / raw)
  To: Chen Yu
  Cc: x86, linux-pm, Thomas Gleixner, Ingo Molnar, H. Peter Anvin,
	Len Brown, Rafael J. Wysocki, Suresh Siddha, Borislav Petkov,
	Brandt, Todd E, Rui Zhang, linux-kernel

On Tue, Dec 20, 2016 at 06:21:28PM +0800, Chen Yu wrote:
> This is a debug patch to descibe/workaround the issue
> we encountered recently.
> 
> Problem and the cause:
> Currently we are suffering from *extremely* slow CPU online
> speed during system resuming from S3. Say, the MacBookPro 2015
> has 4 CPUs, and it took more than 1 second each for both CPU1
> and CPU3 to be brought back to idle thread again. Further ftrace
> result showed that, *each* instruction the CPU1 and CPU3 execute
> will take much longer time than it will take during normal cpu
> online via sysfs(without S3 involved). And more interesting
> thing was found that after resumed back, every instruction CPU1 and
> CPU3 execute is back to its normal speed(unixbench has the same score
> before/after S3). So it smells like there is something wrong with
> the cache/tlb settings only during resuming back from S3.
> Finally we have found this might be related to BIOS who has
> scribbled the mtrr/pat before it resumed back to the OS, and every
> instruction seems to be run in an uncached behavior, fortunately
> later after all the APs have been brought up again, mtrr_aps_init()
> will be invoked to synchronize the mtrr on these APs to the value
> once saved by CPU0 before suspended, thus everything is back
> to normal after resumed.

I'm seeing the same issue on a MacBookPro9,1 (Ivy Bridge, 2012,
BIOS MBP91.88Z.00D3.B0C.1509111653 09/11/2015).

I was already wondering what's going on, so thanks a lot for looking
into this.

For me this is a regression because with 4.7.0-rc7 resume was
sufficiently quick.  The issue only started to appear after
I rebased my working branch on 4.8.0-rc8.  I can confirm that
your patch fixes the issue, so FWIW:

Tested-by: Lukas Wunner <lukas@wunner.de>


This is with 4.7.0-rc7, resume was consistently at or below 1 sec:

[  107.080920] ACPI: Low-level resume complete
[  107.080965] ACPI : EC: EC started
[  107.080966] PM: Restoring platform NVS memory
[  107.081341] Enabling non-boot CPUs ...
[  107.101059] x86: Booting SMP configuration:
[  107.101060] smpboot: Booting Node 0 Processor 1 APIC 0x2
[  107.108619]  cache: parent cpu1 should not be sleeping
[  107.135789] CPU1 is up
[  107.199203] smpboot: Booting Node 0 Processor 2 APIC 0x4
[  107.209808]  cache: parent cpu2 should not be sleeping
[  107.240896] CPU2 is up
[  107.314086] smpboot: Booting Node 0 Processor 3 APIC 0x6
[  107.326220]  cache: parent cpu3 should not be sleeping
[  107.357507] CPU3 is up
[  107.449002] smpboot: Booting Node 0 Processor 4 APIC 0x1
[  107.451740]  cache: parent cpu4 should not be sleeping
[  107.452106] CPU4 is up
[  107.549902] smpboot: Booting Node 0 Processor 5 APIC 0x3
[  107.566487]  cache: parent cpu5 should not be sleeping
[  107.624016] CPU5 is up
[  107.787000] smpboot: Booting Node 0 Processor 6 APIC 0x5
[  107.804491]  cache: parent cpu6 should not be sleeping
[  107.869075] CPU6 is up
[  108.057328] smpboot: Booting Node 0 Processor 7 APIC 0x7
[  108.075840]  cache: parent cpu7 should not be sleeping
[  108.149616] CPU7 is up
[  108.155910] ACPI: Waking up from system sleep state S3


This is with 4.8.0-rc8 without your patch, around 4 sec:

[  608.277228] ACPI: Low-level resume complete
[  608.277273] ACPI : EC: EC started
[  608.277274] PM: Restoring platform NVS memory
[  608.277612] Enabling non-boot CPUs ...
[  608.301165] x86: Booting SMP configuration:
[  608.301165] smpboot: Booting Node 0 Processor 1 APIC 0x2
[  608.350399]  cache: parent cpu1 should not be sleeping
[  608.531440] CPU1 is up
[  608.761943] smpboot: Booting Node 0 Processor 2 APIC 0x4
[  608.806085]  cache: parent cpu2 should not be sleeping
[  608.972760] CPU2 is up
[  609.276436] smpboot: Booting Node 0 Processor 3 APIC 0x6
[  609.323774]  cache: parent cpu3 should not be sleeping
[  609.472503] CPU3 is up
[  609.824707] smpboot: Booting Node 0 Processor 4 APIC 0x1
[  609.828097]  cache: parent cpu4 should not be sleeping
[  609.828776] CPU4 is up
[  610.223620] smpboot: Booting Node 0 Processor 5 APIC 0x3
[  610.292411]  cache: parent cpu5 should not be sleeping
[  610.545823] CPU5 is up
[  610.981127] smpboot: Booting Node 0 Processor 6 APIC 0x5
[  611.049177]  cache: parent cpu6 should not be sleeping
[  611.334813] CPU6 is up
[  612.049163] smpboot: Booting Node 0 Processor 7 APIC 0x7
[  612.123333]  cache: parent cpu7 should not be sleeping
[  612.427630] CPU7 is up
[  612.436692] ACPI: Waking up from system sleep state S3


With your patch I'm back to 1 sec:

[   98.177541] ACPI: Low-level resume complete
[   98.177585] ACPI : EC: EC started
[   98.177585] PM: Restoring platform NVS memory
[   98.177951] Enabling non-boot CPUs ...
[   98.201608] x86: Booting SMP configuration:
[   98.201609] smpboot: Booting Node 0 Processor 1 APIC 0x2
[   98.210412]  cache: parent cpu1 should not be sleeping
[   98.238198] CPU1 is up
[   98.307550] smpboot: Booting Node 0 Processor 2 APIC 0x4
[   98.319788]  cache: parent cpu2 should not be sleeping
[   98.353269] CPU2 is up
[   98.428475] smpboot: Booting Node 0 Processor 3 APIC 0x6
[   98.439979]  cache: parent cpu3 should not be sleeping
[   98.478572] CPU3 is up
[   98.585208] smpboot: Booting Node 0 Processor 4 APIC 0x1
[   98.588040]  cache: parent cpu4 should not be sleeping
[   98.588412] CPU4 is up
[   98.702925] smpboot: Booting Node 0 Processor 5 APIC 0x3
[   98.719564]  cache: parent cpu5 should not be sleeping
[   98.786342] CPU5 is up
[   98.959777] smpboot: Booting Node 0 Processor 6 APIC 0x5
[   98.977120]  cache: parent cpu6 should not be sleeping
[   99.048355] CPU6 is up
[   99.241252] smpboot: Booting Node 0 Processor 7 APIC 0x7
[   99.261368]  cache: parent cpu7 should not be sleeping
[   99.339541] CPU7 is up
[   99.345700] ACPI: Waking up from system sleep state S3

Thanks,

Lukas

> 
> Workaround:
> So it turns out to be that if we can synchronize the APs with boot CPU
> ASAP, rather than waiting till all CPUS online, it might reduce the
> impact of the bogus BIOS who scribbled the mtrr/pat. So here is the
> hack patch to let the users to synchronize mtrr on APs earlier.
> With the following debug patch applied, the resume time for CPU1 and
> CPU3 have dropped a lot.
> 
> (Notice, the following result were tested with ftrace function_graph enabled
> during suspend/resume, by this tool:
> https://01.org/suspendresume
> 
> 
> Before patch applied:
> [  619.810899] Enabling non-boot CPUs ...
> [  619.825528] x86: Booting SMP configuration:
> [  619.825537] smpboot: Booting Node 0 Processor 1 APIC 0x2
> -------skip--------
> [  621.723809] CPU1 is up
> [  621.762843] smpboot: Booting Node 0 Processor 2 APIC 0x1
> -------skip--------
> [  621.766679] CPU2 is up
> [  621.840228] smpboot: Booting Node 0 Processor 3 APIC 0x3
> -------skip--------
> [  626.690900] CPU3 is up
> 
> So it took CPU1 621.723809 - 619.825537 = 1898.272 ms, and
> CPU3 626.690900 - 621.840228 = 4850.672 ms !
> 
> 
> After patch applied:
> [  106.931790] smpboot: Booting Node 0 Processor 1 APIC 0x2
> -------skip--------
> [  106.948360] CPU1 is up
> [  106.963975] smpboot: Booting Node 0 Processor 2 APIC 0x1
> -------skip--------
> [  106.968087] CPU2 is up
> [  106.986534] smpboot: Booting Node 0 Processor 3 APIC 0x3
> -------skip--------
> [  106.990702] CPU3 is up
> 
> It took CPU1 106.948360 - 106.931790 = 16.57 ms, and
> CPU3 106.990702 - 106.986534 = 4.16 ms
> 
> Question:
> So it turns out to be a BIOS issue, but Linux should also deal with
> this bogus BIOS, right? I studied the commit we delay the synchronization
> until all the APs are brought up, and according to:
> 
> Commit d0af9eed5aa9 ("x86, pat/mtrr: Rendezvous all the cpus
> for MTRR/PAT init")
> 
> It seems that there would be problem if we do not sync APs at the same
> time(some CPUs run with cache disabled will hang the system, because its
> sibling is trying to adjust the mtrr which might disable its cache) on
> some special platforms? But I have a question that, even in our current
> solution which defers the synchronization, the scenario mentioned above
> can not be avoided because at the time CPU3 is trying to restore mtrr,
> its sibling CPU1 might also be doing some kworker or ticking tasks,
> the CPU1 might also run with cache disabled?
> I'm not sure if I understand the code correctly, and it would be
> appreciated if people could give any comments/suggestions on how to deal
> with this situation found on MacProBook, and if you need me to do any test
> please feel free to let me know.
> 
> Thanks,
> Yu
> 
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: "H. Peter Anvin" <hpa@zytor.com>
> Cc: Len Brown <len.brown@intel.com>
> Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net>
> Cc: Suresh Siddha <sbsiddha@gmail.com>
> Cc: Borislav Petkov <bp@suse.de>
> Cc: Lukas Wunner <lukas@wunner.de>
> Cc: "Brandt, Todd E" <todd.e.brandt@intel.com>
> Cc: Rui Zhang <rui.zhang@intel.com>
> Cc: linux-kernel@vger.kernel.org
> Signed-off-by: Chen Yu <yu.c.chen@intel.com>
> ---
>  arch/x86/kernel/cpu/mtrr/main.c | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/arch/x86/kernel/cpu/mtrr/main.c b/arch/x86/kernel/cpu/mtrr/main.c
> index 24e87e7..eddaa89 100644
> --- a/arch/x86/kernel/cpu/mtrr/main.c
> +++ b/arch/x86/kernel/cpu/mtrr/main.c
> @@ -813,15 +813,28 @@ void mtrr_save_state(void)
>  	put_online_cpus();
>  }
>  
> +static bool __read_mostly no_aps_delay;
> +
> +static int __init no_aps_setup(char *str)
> +{
> +	no_aps_delay = true;
> +	pr_info("hack: do not delay aps mtrr/pat initialization.\n");
> +
> +	return 0;
> +}
> +
>  void set_mtrr_aps_delayed_init(void)
>  {
>  	if (!mtrr_enabled())
>  		return;
>  	if (!use_intel())
>  		return;
> +	if (no_aps_delay)
> +		return;
>  
>  	mtrr_aps_delayed_init = true;
>  }
> +early_param("no_aps_delay", no_aps_setup);
>  
>  /*
>   * Delayed MTRR initialization for all AP's
> -- 
> 2.7.4
> 

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs
  2016-12-20 10:56 ` Lukas Wunner
@ 2016-12-21  2:32   ` Chen Yu
  2016-12-21  6:51   ` Chen Yu
  1 sibling, 0 replies; 6+ messages in thread
From: Chen Yu @ 2016-12-21  2:32 UTC (permalink / raw)
  To: Lukas Wunner
  Cc: x86, linux-pm, Thomas Gleixner, Ingo Molnar, H. Peter Anvin,
	Len Brown, Rafael J. Wysocki, Suresh Siddha, Borislav Petkov,
	Brandt, Todd E, Rui Zhang, linux-kernel

On Tue, Dec 20, 2016 at 11:56:51AM +0100, Lukas Wunner wrote:
Hi Lukas,
> On Tue, Dec 20, 2016 at 06:21:28PM +0800, Chen Yu wrote:
> > This is a debug patch to descibe/workaround the issue
> > we encountered recently.
> > 
> > Problem and the cause:
> > Currently we are suffering from *extremely* slow CPU online
> > speed during system resuming from S3. Say, the MacBookPro 2015
> > has 4 CPUs, and it took more than 1 second each for both CPU1
> > and CPU3 to be brought back to idle thread again. Further ftrace
> > result showed that, *each* instruction the CPU1 and CPU3 execute
> > will take much longer time than it will take during normal cpu
> > online via sysfs(without S3 involved). And more interesting
> > thing was found that after resumed back, every instruction CPU1 and
> > CPU3 execute is back to its normal speed(unixbench has the same score
> > before/after S3). So it smells like there is something wrong with
> > the cache/tlb settings only during resuming back from S3.
> > Finally we have found this might be related to BIOS who has
> > scribbled the mtrr/pat before it resumed back to the OS, and every
> > instruction seems to be run in an uncached behavior, fortunately
> > later after all the APs have been brought up again, mtrr_aps_init()
> > will be invoked to synchronize the mtrr on these APs to the value
> > once saved by CPU0 before suspended, thus everything is back
> > to normal after resumed.
> 
> I'm seeing the same issue on a MacBookPro9,1 (Ivy Bridge, 2012,
> BIOS MBP91.88Z.00D3.B0C.1509111653 09/11/2015).
> 
> I was already wondering what's going on, so thanks a lot for looking
> into this.
> 
> For me this is a regression because with 4.7.0-rc7 resume was
> sufficiently quick.  The issue only started to appear after
> I rebased my working branch on 4.8.0-rc8.  I can confirm that
> your patch fixes the issue, so FWIW:
> 
> Tested-by: Lukas Wunner <lukas@wunner.de>
> 
Thanks for confirming this, and you have also provided an important
information that, this does not appear in 4.7.0-rc7, so I'll rebase to
this versin to check if things are better. Could you also send me your
kernel config when using 4.7.0-rc7? 

> 
> This is with 4.7.0-rc7, resume was consistently at or below 1 sec:
> 
> [  107.080920] ACPI: Low-level resume complete
> [  107.080965] ACPI : EC: EC started
> [  107.080966] PM: Restoring platform NVS memory
> [  107.081341] Enabling non-boot CPUs ...
> [  107.101059] x86: Booting SMP configuration:
> [  107.101060] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [  107.108619]  cache: parent cpu1 should not be sleeping
> [  107.135789] CPU1 is up
> [  107.199203] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [  107.209808]  cache: parent cpu2 should not be sleeping
> [  107.240896] CPU2 is up
> [  107.314086] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [  107.326220]  cache: parent cpu3 should not be sleeping
> [  107.357507] CPU3 is up
> [  107.449002] smpboot: Booting Node 0 Processor 4 APIC 0x1
> [  107.451740]  cache: parent cpu4 should not be sleeping
> [  107.452106] CPU4 is up
> [  107.549902] smpboot: Booting Node 0 Processor 5 APIC 0x3
> [  107.566487]  cache: parent cpu5 should not be sleeping
> [  107.624016] CPU5 is up
> [  107.787000] smpboot: Booting Node 0 Processor 6 APIC 0x5
> [  107.804491]  cache: parent cpu6 should not be sleeping
> [  107.869075] CPU6 is up
> [  108.057328] smpboot: Booting Node 0 Processor 7 APIC 0x7
> [  108.075840]  cache: parent cpu7 should not be sleeping
> [  108.149616] CPU7 is up
> [  108.155910] ACPI: Waking up from system sleep state S3
> 
> 
> This is with 4.8.0-rc8 without your patch, around 4 sec:
> 
> [  608.277228] ACPI: Low-level resume complete
> [  608.277273] ACPI : EC: EC started
> [  608.277274] PM: Restoring platform NVS memory
> [  608.277612] Enabling non-boot CPUs ...
> [  608.301165] x86: Booting SMP configuration:
> [  608.301165] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [  608.350399]  cache: parent cpu1 should not be sleeping
> [  608.531440] CPU1 is up
> [  608.761943] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [  608.806085]  cache: parent cpu2 should not be sleeping
> [  608.972760] CPU2 is up
> [  609.276436] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [  609.323774]  cache: parent cpu3 should not be sleeping
> [  609.472503] CPU3 is up
> [  609.824707] smpboot: Booting Node 0 Processor 4 APIC 0x1
> [  609.828097]  cache: parent cpu4 should not be sleeping
> [  609.828776] CPU4 is up
> [  610.223620] smpboot: Booting Node 0 Processor 5 APIC 0x3
> [  610.292411]  cache: parent cpu5 should not be sleeping
> [  610.545823] CPU5 is up
> [  610.981127] smpboot: Booting Node 0 Processor 6 APIC 0x5
> [  611.049177]  cache: parent cpu6 should not be sleeping
> [  611.334813] CPU6 is up
> [  612.049163] smpboot: Booting Node 0 Processor 7 APIC 0x7
> [  612.123333]  cache: parent cpu7 should not be sleeping
> [  612.427630] CPU7 is up
> [  612.436692] ACPI: Waking up from system sleep state S3
> 
> 
> With your patch I'm back to 1 sec:
> 
> [   98.177541] ACPI: Low-level resume complete
> [   98.177585] ACPI : EC: EC started
> [   98.177585] PM: Restoring platform NVS memory
> [   98.177951] Enabling non-boot CPUs ...
> [   98.201608] x86: Booting SMP configuration:
> [   98.201609] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [   98.210412]  cache: parent cpu1 should not be sleeping
> [   98.238198] CPU1 is up
> [   98.307550] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [   98.319788]  cache: parent cpu2 should not be sleeping
> [   98.353269] CPU2 is up
> [   98.428475] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [   98.439979]  cache: parent cpu3 should not be sleeping
> [   98.478572] CPU3 is up
> [   98.585208] smpboot: Booting Node 0 Processor 4 APIC 0x1
> [   98.588040]  cache: parent cpu4 should not be sleeping
> [   98.588412] CPU4 is up
> [   98.702925] smpboot: Booting Node 0 Processor 5 APIC 0x3
> [   98.719564]  cache: parent cpu5 should not be sleeping
> [   98.786342] CPU5 is up
> [   98.959777] smpboot: Booting Node 0 Processor 6 APIC 0x5
> [   98.977120]  cache: parent cpu6 should not be sleeping
> [   99.048355] CPU6 is up
> [   99.241252] smpboot: Booting Node 0 Processor 7 APIC 0x7
> [   99.261368]  cache: parent cpu7 should not be sleeping
> [   99.339541] CPU7 is up
> [   99.345700] ACPI: Waking up from system sleep state S3
> 
> Thanks,
> 
> Lukas
>
Thanks,
Yu

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs
  2016-12-20 10:56 ` Lukas Wunner
  2016-12-21  2:32   ` Chen Yu
@ 2016-12-21  6:51   ` Chen Yu
  2016-12-21  9:54     ` Lukas Wunner
  1 sibling, 1 reply; 6+ messages in thread
From: Chen Yu @ 2016-12-21  6:51 UTC (permalink / raw)
  To: Lukas Wunner
  Cc: x86, linux-pm, Thomas Gleixner, Ingo Molnar, H. Peter Anvin,
	Len Brown, Rafael J. Wysocki, Suresh Siddha, Borislav Petkov,
	Brandt, Todd E, Rui Zhang, linux-kernel

On Tue, Dec 20, 2016 at 11:56:51AM +0100, Lukas Wunner wrote:
> On Tue, Dec 20, 2016 at 06:21:28PM +0800, Chen Yu wrote:
> > This is a debug patch to descibe/workaround the issue
> > we encountered recently.
> > 
> > Problem and the cause:
> > Currently we are suffering from *extremely* slow CPU online
> > speed during system resuming from S3. Say, the MacBookPro 2015
> > has 4 CPUs, and it took more than 1 second each for both CPU1
> > and CPU3 to be brought back to idle thread again. Further ftrace
> > result showed that, *each* instruction the CPU1 and CPU3 execute
> > will take much longer time than it will take during normal cpu
> > online via sysfs(without S3 involved). And more interesting
> > thing was found that after resumed back, every instruction CPU1 and
> > CPU3 execute is back to its normal speed(unixbench has the same score
> > before/after S3). So it smells like there is something wrong with
> > the cache/tlb settings only during resuming back from S3.
> > Finally we have found this might be related to BIOS who has
> > scribbled the mtrr/pat before it resumed back to the OS, and every
> > instruction seems to be run in an uncached behavior, fortunately
> > later after all the APs have been brought up again, mtrr_aps_init()
> > will be invoked to synchronize the mtrr on these APs to the value
> > once saved by CPU0 before suspended, thus everything is back
> > to normal after resumed.
> 
> I'm seeing the same issue on a MacBookPro9,1 (Ivy Bridge, 2012,
> BIOS MBP91.88Z.00D3.B0C.1509111653 09/11/2015).
> 
> I was already wondering what's going on, so thanks a lot for looking
> into this.
> 
> For me this is a regression because with 4.7.0-rc7 resume was
> sufficiently quick.  The issue only started to appear after
> I rebased my working branch on 4.8.0-rc8.  I can confirm that
> your patch fixes the issue, so FWIW:
> 
> Tested-by: Lukas Wunner <lukas@wunner.de>
>
I've tested on 4.7.0-rc7, and the problem is still there,
it tooks nearly 2 second to bring up these cpus, after the
patch applied on top of 4.7.0-rc7, the time has dropped to 30ms.
Maybe because the mtrr after restored are random, thus we see different
result. Let's wait if other experts would give any clue on this :)

Original 4.7.0-rc7
[ 1895.937202] Enabling non-boot CPUs ...
[ 1895.960590] x86: Booting SMP configuration:
[ 1895.960599] smpboot: Booting Node 0 Processor 1 APIC 0x2
[ 1896.042237]  cache: parent cpu1 should not be sleeping
[ 1896.278915] CPU1 is up
[ 1896.326531] hrtimer: interrupt took 21233972 ns
[ 1896.497384] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 2.551 msecs
[ 1896.499428] perf: interrupt took too long (15541 > 2500), lowering kernel.perf_event_max_sample_rate to 12750
[ 1898.533643] smpboot: Booting Node 0 Processor 2 APIC 0x1
[ 1898.539348]  cache: parent cpu2 should not be sleeping
[ 1898.583167] CPU2 is up
[ 1900.938878] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 1901.002698]  cache: parent cpu3 should not be sleeping
[ 1901.584319] perf: interrupt took too long (20241 > 19426), lowering kernel.perf_event_max_sample_rate to 9750
[ 1901.605220] CPU3 is up


After patch applied on 4.7.0-rc7:
[   93.580823] Enabling non-boot CPUs ...
[   93.613049] x86: Booting SMP configuration:
[   93.613057] smpboot: Booting Node 0 Processor 1 APIC 0x2
[   93.620355]  cache: parent cpu1 should not be sleeping
[   93.620773] CPU1 is up
[   93.642325] smpboot: Booting Node 0 Processor 2 APIC 0x1
[   93.646009]  cache: parent cpu2 should not be sleeping
[   93.646293] CPU2 is up
[   93.675439] smpboot: Booting Node 0 Processor 3 APIC 0x3
[   93.679256]  cache: parent cpu3 should not be sleeping
[   93.679573] CPU3 is up
[   93.679582] ACPI: Waking up from system sleep state S3

> 
> This is with 4.7.0-rc7, resume was consistently at or below 1 sec:
> 
> [  107.080920] ACPI: Low-level resume complete
> [  107.080965] ACPI : EC: EC started
> [  107.080966] PM: Restoring platform NVS memory
> [  107.081341] Enabling non-boot CPUs ...
> [  107.101059] x86: Booting SMP configuration:
> [  107.101060] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [  107.108619]  cache: parent cpu1 should not be sleeping
> [  107.135789] CPU1 is up
> [  107.199203] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [  107.209808]  cache: parent cpu2 should not be sleeping
> [  107.240896] CPU2 is up
> [  107.314086] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [  107.326220]  cache: parent cpu3 should not be sleeping
> [  107.357507] CPU3 is up
> [  107.449002] smpboot: Booting Node 0 Processor 4 APIC 0x1
> [  107.451740]  cache: parent cpu4 should not be sleeping
> [  107.452106] CPU4 is up
> [  107.549902] smpboot: Booting Node 0 Processor 5 APIC 0x3
> [  107.566487]  cache: parent cpu5 should not be sleeping
> [  107.624016] CPU5 is up
> [  107.787000] smpboot: Booting Node 0 Processor 6 APIC 0x5
> [  107.804491]  cache: parent cpu6 should not be sleeping
> [  107.869075] CPU6 is up
> [  108.057328] smpboot: Booting Node 0 Processor 7 APIC 0x7
> [  108.075840]  cache: parent cpu7 should not be sleeping
> [  108.149616] CPU7 is up
> [  108.155910] ACPI: Waking up from system sleep state S3
> 
> 
> This is with 4.8.0-rc8 without your patch, around 4 sec:
> 
> [  608.277228] ACPI: Low-level resume complete
> [  608.277273] ACPI : EC: EC started
> [  608.277274] PM: Restoring platform NVS memory
> [  608.277612] Enabling non-boot CPUs ...
> [  608.301165] x86: Booting SMP configuration:
> [  608.301165] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [  608.350399]  cache: parent cpu1 should not be sleeping
> [  608.531440] CPU1 is up
> [  608.761943] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [  608.806085]  cache: parent cpu2 should not be sleeping
> [  608.972760] CPU2 is up
> [  609.276436] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [  609.323774]  cache: parent cpu3 should not be sleeping
> [  609.472503] CPU3 is up
> [  609.824707] smpboot: Booting Node 0 Processor 4 APIC 0x1
> [  609.828097]  cache: parent cpu4 should not be sleeping
> [  609.828776] CPU4 is up
> [  610.223620] smpboot: Booting Node 0 Processor 5 APIC 0x3
> [  610.292411]  cache: parent cpu5 should not be sleeping
> [  610.545823] CPU5 is up
> [  610.981127] smpboot: Booting Node 0 Processor 6 APIC 0x5
> [  611.049177]  cache: parent cpu6 should not be sleeping
> [  611.334813] CPU6 is up
> [  612.049163] smpboot: Booting Node 0 Processor 7 APIC 0x7
> [  612.123333]  cache: parent cpu7 should not be sleeping
> [  612.427630] CPU7 is up
> [  612.436692] ACPI: Waking up from system sleep state S3
> 
> 
> With your patch I'm back to 1 sec:
> 
> [   98.177541] ACPI: Low-level resume complete
> [   98.177585] ACPI : EC: EC started
> [   98.177585] PM: Restoring platform NVS memory
> [   98.177951] Enabling non-boot CPUs ...
> [   98.201608] x86: Booting SMP configuration:
> [   98.201609] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [   98.210412]  cache: parent cpu1 should not be sleeping
> [   98.238198] CPU1 is up
> [   98.307550] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [   98.319788]  cache: parent cpu2 should not be sleeping
> [   98.353269] CPU2 is up
> [   98.428475] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [   98.439979]  cache: parent cpu3 should not be sleeping
> [   98.478572] CPU3 is up
> [   98.585208] smpboot: Booting Node 0 Processor 4 APIC 0x1
> [   98.588040]  cache: parent cpu4 should not be sleeping
> [   98.588412] CPU4 is up
> [   98.702925] smpboot: Booting Node 0 Processor 5 APIC 0x3
> [   98.719564]  cache: parent cpu5 should not be sleeping
> [   98.786342] CPU5 is up
> [   98.959777] smpboot: Booting Node 0 Processor 6 APIC 0x5
> [   98.977120]  cache: parent cpu6 should not be sleeping
> [   99.048355] CPU6 is up
> [   99.241252] smpboot: Booting Node 0 Processor 7 APIC 0x7
> [   99.261368]  cache: parent cpu7 should not be sleeping
> [   99.339541] CPU7 is up
> [   99.345700] ACPI: Waking up from system sleep state S3
> 
> Thanks,
> 
> Lukas
> 

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs
  2016-12-21  6:51   ` Chen Yu
@ 2016-12-21  9:54     ` Lukas Wunner
  0 siblings, 0 replies; 6+ messages in thread
From: Lukas Wunner @ 2016-12-21  9:54 UTC (permalink / raw)
  To: Chen Yu
  Cc: x86, linux-pm, Thomas Gleixner, Ingo Molnar, H. Peter Anvin,
	Len Brown, Rafael J. Wysocki, Suresh Siddha, Borislav Petkov,
	Brandt, Todd E, Rui Zhang, linux-kernel

On Wed, Dec 21, 2016 at 02:51:02PM +0800, Chen Yu wrote:
> On Tue, Dec 20, 2016 at 11:56:51AM +0100, Lukas Wunner wrote:
> > On Tue, Dec 20, 2016 at 06:21:28PM +0800, Chen Yu wrote:
> > > This is a debug patch to descibe/workaround the issue
> > > we encountered recently.
> > > 
> > > Problem and the cause:
> > > Currently we are suffering from *extremely* slow CPU online
> > > speed during system resuming from S3. Say, the MacBookPro 2015
> > > has 4 CPUs, and it took more than 1 second each for both CPU1
> > > and CPU3 to be brought back to idle thread again. Further ftrace
> > > result showed that, *each* instruction the CPU1 and CPU3 execute
> > > will take much longer time than it will take during normal cpu
> > > online via sysfs(without S3 involved). And more interesting
> > > thing was found that after resumed back, every instruction CPU1 and
> > > CPU3 execute is back to its normal speed(unixbench has the same score
> > > before/after S3). So it smells like there is something wrong with
> > > the cache/tlb settings only during resuming back from S3.
> > > Finally we have found this might be related to BIOS who has
> > > scribbled the mtrr/pat before it resumed back to the OS, and every
> > > instruction seems to be run in an uncached behavior, fortunately
> > > later after all the APs have been brought up again, mtrr_aps_init()
> > > will be invoked to synchronize the mtrr on these APs to the value
> > > once saved by CPU0 before suspended, thus everything is back
> > > to normal after resumed.
> > 
> > I'm seeing the same issue on a MacBookPro9,1 (Ivy Bridge, 2012,
> > BIOS MBP91.88Z.00D3.B0C.1509111653 09/11/2015).
> > 
> > I was already wondering what's going on, so thanks a lot for looking
> > into this.
> > 
> > For me this is a regression because with 4.7.0-rc7 resume was
> > sufficiently quick.  The issue only started to appear after
> > I rebased my working branch on 4.8.0-rc8.  I can confirm that
> > your patch fixes the issue, so FWIW:
> > 
> > Tested-by: Lukas Wunner <lukas@wunner.de>
>
> I've tested on 4.7.0-rc7, and the problem is still there,
> it tooks nearly 2 second to bring up these cpus, after the
> patch applied on top of 4.7.0-rc7, the time has dropped to 30ms.
> Maybe because the mtrr after restored are random, thus we see different
> result. Let's wait if other experts would give any clue on this :)

Feeding /var/log/kern.log into this quick perl hack results in the numbers
included below.  The 4 sec resume began with 4.8-rc8 for me, but it's
not 100% reproducible, sometimes it just takes 1 sec even with 4.8-rc8,
likely as you say because of random content in the relevant registers:

perl -n -e '
if (/Linux version ([^ ]+)/) {
	$ver = "$1";
} elsif (/\[ *([0-9.]+)\] ACPI: Low-level/) {
	$start = $1;
} elsif (/\[ *([0-9.]+)\] ACPI: Waking up/) {
	$end = $1;
	print $ver . "\t" . ($end - $start) . "\n";
}'

Thanks,

Lukas

-- snip --

4.5.0-rc5-amd64	0.791821999999996
4.5.0-rc5-amd64	0.784248000000048
4.5.0-rc5-amd64	0.755302000000029
4.5.0-rc5-amd64	0.872710000000041
4.5.0-rc5-amd64	0.811196999999993
4.5.0-rc5-amd64	0.619765999999998
4.5.0-rc5-amd64	0.847110000000001
4.5.0-rc5-amd64	0.583031000000005
4.5.0-rc5-amd64	0.619109999999999
4.5.0-rc5-amd64	0.833584999999999
4.5.0-rc5-amd64	0.899036000000024
4.5.0-rc5-amd64	0.912164000000004
4.5.0-rc5-amd64	0.886482999999998
4.5.0-rc5-amd64	0.724455999999996
4.5.0-rc5-amd64	0.900266000000002
4.5.0-rc5-amd64	0.848599000000007
4.5.0-rc5-amd64	0.805461000000008
4.5.0-rc5-amd64	0.711756999999992
4.5.0-rc5-amd64	0.546851000000004
4.5.0-rc5-amd64	0.779108000000008
4.5.0-rc5-amd64	0.904349999999795
4.5.0-rc5-amd64	0.8104629999998
4.5.0-rc5-amd64	0.810886000000004
4.5.0-rc5-amd64	0.806125999999999
4.5.0-rc5-amd64	0.83456000000001
4.5.0-rc5-amd64	0.809259999999995
4.5.0-rc5-amd64	0.657921000000002
4.5.0-rc5-amd64	0.710526999999956
4.5.0-rc5-amd64	0.827078000000029
4.5.0-rc5-amd64	0.82047
4.5.0-rc5-amd64	0.545153999999911
4.5.0-rc5-amd64	0.617734000000041
4.5.0-rc5-amd64	0.884256000000001
4.5.0-rc5-amd64	0.629543999999981
4.5.0-rc5-amd64	0.902484999999999
4.5.0-rc5-amd64	0.80895799999999
4.5.0-rc5-amd64	0.651888999999983
4.5.0-rc5-amd64	0.681414999999902
4.5.0-rc5-amd64	0.908006
4.5.0-rc5-amd64	0.810744
4.5.0-rc5-amd64	0.673935
4.5.0-rc5-amd64	0.921460999999994
4.5.0-rc5-amd64	0.875963999999996
4.5.0-rc5-amd64	0.904393999999996
4.5.0-rc5-amd64	0.771819999999998
4.5.0-rc5-amd64	0.829245999999998
4.5.0-rc5-amd64	0.884001000000126
4.5.0-rc5-amd64	0.925242999999995
4.5.0-rc5-amd64	0.807276999999999
4.5.0-rc5-amd64	0.77618600000001
4.5.0-rc5-amd64	0.891590000000008
4.5.0-rc5-amd64	0.832144999999997
4.5.0-rc5-amd64	0.664855000000017
4.5.0-rc5-amd64	0.743611000000016
4.5.0-rc5-amd64	0.572099999999978
4.5.0-rc5-amd64	0.968667000000039
4.5.0-rc5-amd64	0.835151999999994
4.5.0-rc5-amd64	0.835349000000008
4.5.0-rc5-amd64	0.698092000000003
4.5.0-rc5-amd64	0.743515000000002
4.5.0-rc5-amd64	0.916257999999999
4.5.0-rc5-amd64	0.801462000000001
4.5.0-rc5-amd64	0.847062999999999
4.5.0-rc5-amd64	0.837590999999989
4.5.0-rc5-amd64	0.878129999999999
4.5.0-rc5-amd64	0.911189000000007
4.5.0-rc5-amd64	0.841833000000008
4.5.0-rc5-amd64	0.69529
4.5.0-rc5-amd64	0.568078
4.5.0-rc5-amd64	0.813648999999998
4.5.0-rc5-amd64	0.801636999999999
4.5.0-rc5-amd64	0.790887999999995
4.5.0-rc5-amd64	0.828260999999998
4.5.0-rc5-amd64	0.950163000000003
4.5.0-rc5-amd64	0.916289999999996
4.5.0-rc5-amd64	0.644873000000004
4.5.0-rc5-amd64	0.61748499999976
4.5.0-rc5-amd64	0.846859000000009
4.5.0-rc5-amd64	0.902849000000003
4.5.0-rc5-amd64	0.903951000000006
4.5.0-rc5-amd64	0.929685000000006
4.5.0-rc5-amd64	0.595804000000044
4.5.0-rc5-amd64	0.807150999999976
4.5.0-rc5-amd64	0.918833000000006
4.5.0-rc5-amd64	0.621095000000004
4.5.0-rc5-amd64	0.797015000000002
4.5.0-rc5-amd64	0.798920000000066
4.5.0-rc5-amd64	0.844256999999971
4.5.0-rc5-amd64	0.545507999999927
4.5.0-rc5-amd64	0.558537999999999
4.5.0-rc5-amd64	0.523992000000135
4.5.0-rc5-amd64	0.862690000000001
4.5.0-rc5-amd64	0.854602
4.5.0-rc5-amd64	0.535631999999964
4.5.0-rc5-amd64	0.758905000000027
4.5.0-rc5-amd64	0.763448999999923
4.5.0-rc5-amd64	0.857717000000001
4.5.0-rc5-amd64	0.934520999999989
4.5.0-rc5-amd64	0.883544000000001
4.5.0-rc5-amd64	0.786261000000081
4.5.0-rc5-amd64	0.620818999999983
4.5.0-rc5-amd64	0.69337500000006
4.5.0-rc5-amd64	0.847121000000016
4.5.0-rc5-amd64	0.811431000000084
4.5.0-rc5-amd64	0.958880999999991
4.5.0-rc5-amd64	0.771730999999932
4.5.0-rc5-amd64	0.916927999999999
4.5.0-rc5-amd64	0.640732
4.5.0-rc5-amd64	0.770714999999996
4.5.0-rc5-amd64	0.822458999999981
4.5.0-rc5-amd64	0.922315999999995
4.5.0-rc5-amd64	0.849181999999985
4.5.0-rc5-amd64	0.898053999999945
4.5.0-rc5-amd64	0.889291000000014
4.5.0-rc5-amd64	0.816744999999969
4.5.0-rc5-amd64	0.603718000000001
4.5.0-rc5-amd64	0.809477000000001
4.5.0-rc5-amd64	0.647982999999996
4.5.0-rc5-amd64	0.569856999999999
4.5.0-rc5-amd64	0.836538000000004
4.5.0-rc5-amd64	0.503213000000017
4.5.0-rc5-amd64	0.921850999999997
4.5.0-rc5-amd64	0.819006000000002
4.5.0-rc5-amd64	0.690811000000053
4.5.0-rc5-amd64	0.844243000000006
4.5.0-rc5-amd64	0.908578999999918
4.5.0-rc5-amd64	0.617271000000073
4.5.0-rc5-amd64	0.916234000000031
4.5.0-rc5-amd64	0.808912999999961
4.5.0-rc5-amd64	0.774151999999958
4.5.0-rc5-amd64	0.905732000000057
4.5.0-rc5-amd64	0.806829999999991
4.5.0-rc5-amd64	0.847582999999986
4.5.0-rc5-amd64	0.898519999999962
4.5.0-rc5-amd64	0.888661000000013
4.5.0-rc5-amd64	1.05587100000002
4.5.0-rc5-amd64	0.831493000000023
4.5.0-rc5-amd64	0.783102999999983
4.5.0-rc5-amd64	0.859454000001278
4.5.0-rc5-amd64	0.903360000000248
4.5.0-rc5-amd64	0.590835999999399
4.5.0-rc5-amd64	0.810430999998061
4.5.0-rc5-amd64	0.868598000000929
4.6.0-rc6-amd64	0.858732000000032
4.6.0-rc6-amd64	0.768321000000014
4.6.0-rc6-amd64	0.999735999999984
4.6.0-rc6-amd64	0.935766000000058
4.6.0-rc6-amd64	1.074747
4.6.0-rc6-amd64	0.871172000000001
4.6.0-rc6-amd64	0.735118
4.6.0-rc6-amd64	0.688977000000023
4.6.0-rc6-amd64	0.98784999999998
4.6.0-rc6-amd64	0.902268000000007
4.6.0-rc6-amd64	0.687322000000002
4.6.0-rc6-amd64	0.966214999999977
4.6.0-rc6-amd64	0.945695999999998
4.6.0-rc6-amd64	0.984290999999985
4.6.0-rc6-amd64	1.00772600000002
4.6.0-rc6-amd64	0.832724999999982
4.6.0-rc6-amd64	1.007998
4.6.0-rc6-amd64	0.928820999999999
4.6.0-rc6-amd64	0.724267999999995
4.6.0-rc6-amd64	0.779960000000003
4.6.0-rc6-amd64	0.928005999999996
4.6.0-rc6-amd64	0.785260999999998
4.6.0-rc6-amd64	0.938457999999997
4.6.0-rc6-amd64	0.718059000000011
4.6.0-rc6-amd64	0.934480999999998
4.6.0-rc6-amd64	0.895643999999997
4.6.0-rc6-amd64	0.776068000000002
4.6.0-rc6-amd64	0.948469999999986
4.6.0-rc6-amd64	0.712186999999972
4.6.0-rc6-amd64	0.749055999999996
4.6.0-rc6-amd64	1.024166
4.6.0-rc6-amd64	0.742650000000026
4.6.0-rc6-amd64	1.108676
4.6.0-rc6-amd64	1.17285699999996
4.6.0-rc6-amd64	0.78110300000003
4.6.0-rc6-amd64	0.811090000000036
4.6.0-rc6-amd64	0.997298999999998
4.6.0-rc6-amd64	0.788564000000065
4.6.0-rc6-amd64	0.864753999999948
4.6.0-rc6-amd64	0.539875999999936
4.6.0-rc6-amd64	0.859683000000018
4.6.0-rc6-amd64	0.84412199999997
4.6.0-rc6-amd64	0.911157000000003
4.6.0-rc6-amd64	1.08518399999991
4.6.0-rc6-amd64	0.975603999999976
4.6.0-rc6-amd64	1.01276200000001
4.6.0-rc6-amd64	0.957143000000002
4.6.0-rc6-amd64	0.838584999999995
4.6.0-rc6-amd64	1.027795
4.6.0-rc6-amd64	0.837847999999994
4.6.0-rc6-amd64	1.00810899999988
4.6.0-rc6-amd64	1.03576699999999
4.6.0-rc6-amd64	0.825954000000024
4.6.0-rc6-amd64	0.915140000000008
4.6.0-rc6-amd64	0.875745999999999
4.6.0-rc6-amd64	1.068602
4.6.0-rc6-amd64	0.880808999999999
4.6.0-rc6-amd64	0.848484999999997
4.6.0-rc6-amd64	0.98555300000001
4.6.0-rc6-amd64	1.098177
4.6.0-rc6-amd64	0.969982999999999
4.6.0-rc6-amd64	1.06376
4.6.0-rc6-amd64	1.03072
4.6.0-rc6-amd64	0.957211999999998
4.6.0-rc6-amd64	0.725653000000001
4.6.0-rc6-amd64	0.739570000000001
4.6.0-rc6-amd64	0.861633000000005
4.6.0-rc6-amd64	0.877488
4.6.0-rc6-amd64	0.962841999999995
4.7.0-rc7-amd64	0.854735000000005
4.7.0-rc7-amd64	0.827500000000001
4.7.0-rc7-amd64	1.057783
4.7.0-rc7-amd64	0.884496999999982
4.7.0-rc7-amd64	0.523160000000018
4.7.0-rc7-amd64	1.05743199999995
4.7.0-rc7-amd64	1.04921400000001
4.7.0-rc7-amd64	1.080662
4.7.0-rc7-amd64	1.043806
4.7.0-rc7-amd64	1.01401000000001
4.7.0-rc7-amd64	0.513013999999998
4.7.0-rc7-amd64	1.042517
4.7.0-rc7-amd64	0.389202999999981
4.7.0-rc7-amd64	0.401685999999927
4.7.0-rc7-amd64	0.67577899999992
4.7.0-rc7-amd64	1.08775700000001
4.7.0-rc7-amd64	1.079895
4.7.0-rc7-amd64	0.929226999999997
4.7.0-rc7-amd64	1.048232
4.7.0-rc7-amd64	1.04880600000001
4.7.0-rc7-amd64	1.02780900000005
4.7.0-rc7-amd64	1.07356300000001
4.7.0-rc7-amd64	0.748491999999999
4.7.0-rc7-amd64	1.06909499999999
4.7.0-rc7-amd64	0.53069
4.7.0-rc7-amd64	0.645086000000049
4.7.0-rc7-amd64	0.772515999999996
4.7.0-rc7-amd64	1.0279589999999
4.7.0-rc7-amd64	1.07909899999993
4.7.0-rc7-amd64	0.989211999999995
4.7.0-rc7-amd64	0.655788000000001
4.7.0-rc7-amd64	0.680987999999957
4.7.0-rc7-amd64	0.530302000000006
4.7.0-rc7-amd64	1.06296600000002
4.7.0-rc7-amd64	1.06546299999991
4.7.0-rc7-amd64	1.09333399999991
4.7.0-rc7-amd64	1.016413
4.7.0-rc7-amd64	0.892668000000015
4.7.0-rc7-amd64	0.411213000000032
4.7.0-rc7-amd64	0.744064000000002
4.7.0-rc7-amd64	0.924797000000012
4.7.0-rc7-amd64	0.953418000000056
4.7.0-rc7-amd64	1.10205900000005
4.7.0-rc7-amd64	0.933835999999999
4.7.0-rc7-amd64	0.937736000000001
4.7.0-rc7-amd64	1.09499199999999
4.7.0-rc7-amd64	0.961829999999999
4.7.0-rc7-amd64	0.515383
4.7.0-rc7-amd64	0.524988000000008
4.7.0-rc7-amd64	1.090538
4.7.0-rc7-amd64	0.527456000000001
4.7.0-rc7-amd64	1.088252
4.7.0-rc7-amd64	0.970280000000002
4.7.0-rc7-amd64	1.50766499999997
4.7.0-rc7-amd64	0.666339999999991
4.7.0-rc7-amd64	1.090823
4.7.0-rc7-amd64	0.53107
4.7.0-rc7-amd64	1.07499
4.7.0-rc7-amd64	0.390456
4.7.0-rc7-amd64	0.991683999999992
4.7.0-rc7-amd64	1.10761199999999
4.7.0-rc7-amd64	0.691510999999998
4.7.0-rc7-amd64	0.543309999999991
4.7.0-rc7-amd64	1.033035
4.7.0-rc7-amd64	0.550754999999995
4.7.0-rc7-amd64	0.931038999999998
4.7.0-rc7-amd64	0.419938999999999
4.7.0-rc7-amd64	0.957441000000017
4.7.0-rc7-amd64	0.953374999999994
4.7.0-rc7-amd64	1.02400699999998
4.7.0-rc7-amd64	0.551457999999997
4.7.0-rc7-amd64	1.09606400000001
4.7.0-rc7-amd64	1.112664
4.7.0-rc7-amd64	0.545329000000038
4.8.0-rc8-amd64	4.15946399999996
4.8.0-rc8-amd64	1.95669999999996
4.8.0-rc8-amd64	4.32400200000006
4.8.0-rc8-amd64	2.02430000000004
4.8.0-rc8-amd64	1.90040800000008
4.8.0-rc8-amd64	4.37152000000003
4.8.0-rc8-amd64	4.383017
4.8.0-rc8-amd64	4.199254
4.8.0-rc8-amd64	4.44121400000017
4.8.0-rc8-amd64	4.14728700000001
4.8.0-rc8-amd64	4.33939000000009
4.8.0-rc8-amd64	4.203777
4.8.0-rc8-amd64	0.587456000000003
4.8.0-rc8-amd64	4.39352499999998
4.8.0-rc8-amd64	1.969683
4.8.0-rc8-amd64	4.31196299999999
4.8.0-rc8-amd64	4.23275299999997
4.8.0-rc8-amd64	1.95122600000001
4.8.0-rc8-amd64	4.515658
4.8.0-rc8-amd64	3.855763
4.8.0-rc8-amd64	4.33339400000114
4.8.0-rc8-amd64	4.10148699999991
4.8.0-rc8-amd64	1.11672299999998
4.8.0-rc8-amd64	1.10457399999996
4.8.0-rc8-amd64	2.56593599999997
4.8.0-rc8-amd64	1.99261300000035
4.8.0-rc8-amd64	1.96518300000025
4.8.0-rc8-amd64	4.36082399999941
4.8.0-rc8-amd64	4.36475400000018
4.8.0-rc8-amd64	1.94891699999971
4.8.0-rc8-amd64	4.06829799999923

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs
  2016-12-20 10:21 [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs Chen Yu
  2016-12-20 10:56 ` Lukas Wunner
@ 2017-01-16  2:56 ` Chen Yu
  1 sibling, 0 replies; 6+ messages in thread
From: Chen Yu @ 2017-01-16  2:56 UTC (permalink / raw)
  To: Suresh Siddha, Suresh Siddha, Thomas Gleixner, Ingo Molnar,
	H. Peter Anvin, Len Brown, Rafael J. Wysocki, Borislav Petkov,
	Lukas Wunner, Brandt, Todd E, Rui Zhang
  Cc: x86, linux-pm, linux-kernel

Hi experts,
do you have any clue on this? thanks.

On Tue, Dec 20, 2016 at 06:21:28PM +0800, Chen Yu wrote:
> This is a debug patch to descibe/workaround the issue
> we encountered recently.
> 
> Problem and the cause:
> Currently we are suffering from *extremely* slow CPU online
> speed during system resuming from S3. Say, the MacBookPro 2015
> has 4 CPUs, and it took more than 1 second each for both CPU1
> and CPU3 to be brought back to idle thread again. Further ftrace
> result showed that, *each* instruction the CPU1 and CPU3 execute
> will take much longer time than it will take during normal cpu
> online via sysfs(without S3 involved). And more interesting
> thing was found that after resumed back, every instruction CPU1 and
> CPU3 execute is back to its normal speed(unixbench has the same score
> before/after S3). So it smells like there is something wrong with
> the cache/tlb settings only during resuming back from S3.
> Finally we have found this might be related to BIOS who has
> scribbled the mtrr/pat before it resumed back to the OS, and every
> instruction seems to be run in an uncached behavior, fortunately
> later after all the APs have been brought up again, mtrr_aps_init()
> will be invoked to synchronize the mtrr on these APs to the value
> once saved by CPU0 before suspended, thus everything is back
> to normal after resumed.
> 
> Workaround:
> So it turns out to be that if we can synchronize the APs with boot CPU
> ASAP, rather than waiting till all CPUS online, it might reduce the
> impact of the bogus BIOS who scribbled the mtrr/pat. So here is the
> hack patch to let the users to synchronize mtrr on APs earlier.
> With the following debug patch applied, the resume time for CPU1 and
> CPU3 have dropped a lot.
> 
> (Notice, the following result were tested with ftrace function_graph enabled
> during suspend/resume, by this tool:
> https://01.org/suspendresume
> 
> 
> Before patch applied:
> [  619.810899] Enabling non-boot CPUs ...
> [  619.825528] x86: Booting SMP configuration:
> [  619.825537] smpboot: Booting Node 0 Processor 1 APIC 0x2
> -------skip--------
> [  621.723809] CPU1 is up
> [  621.762843] smpboot: Booting Node 0 Processor 2 APIC 0x1
> -------skip--------
> [  621.766679] CPU2 is up
> [  621.840228] smpboot: Booting Node 0 Processor 3 APIC 0x3
> -------skip--------
> [  626.690900] CPU3 is up
> 
> So it took CPU1 621.723809 - 619.825537 = 1898.272 ms, and
> CPU3 626.690900 - 621.840228 = 4850.672 ms !
> 
> 
> After patch applied:
> [  106.931790] smpboot: Booting Node 0 Processor 1 APIC 0x2
> -------skip--------
> [  106.948360] CPU1 is up
> [  106.963975] smpboot: Booting Node 0 Processor 2 APIC 0x1
> -------skip--------
> [  106.968087] CPU2 is up
> [  106.986534] smpboot: Booting Node 0 Processor 3 APIC 0x3
> -------skip--------
> [  106.990702] CPU3 is up
> 
> It took CPU1 106.948360 - 106.931790 = 16.57 ms, and
> CPU3 106.990702 - 106.986534 = 4.16 ms
> 
> Question:
> So it turns out to be a BIOS issue, but Linux should also deal with
> this bogus BIOS, right? I studied the commit we delay the synchronization
> until all the APs are brought up, and according to:
> 
> Commit d0af9eed5aa9 ("x86, pat/mtrr: Rendezvous all the cpus
> for MTRR/PAT init")
> 
> It seems that there would be problem if we do not sync APs at the same
> time(some CPUs run with cache disabled will hang the system, because its
> sibling is trying to adjust the mtrr which might disable its cache) on
> some special platforms? But I have a question that, even in our current
> solution which defers the synchronization, the scenario mentioned above
> can not be avoided because at the time CPU3 is trying to restore mtrr,
> its sibling CPU1 might also be doing some kworker or ticking tasks,
> the CPU1 might also run with cache disabled?
> I'm not sure if I understand the code correctly, and it would be
> appreciated if people could give any comments/suggestions on how to deal
> with this situation found on MacProBook, and if you need me to do any test
> please feel free to let me know.
> 
> Thanks,
> Yu
> 
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: "H. Peter Anvin" <hpa@zytor.com>
> Cc: Len Brown <len.brown@intel.com>
> Cc: "Rafael J. Wysocki" <rjw@rjwysocki.net>
> Cc: Suresh Siddha <sbsiddha@gmail.com>
> Cc: Borislav Petkov <bp@suse.de>
> Cc: Lukas Wunner <lukas@wunner.de>
> Cc: "Brandt, Todd E" <todd.e.brandt@intel.com>
> Cc: Rui Zhang <rui.zhang@intel.com>
> Cc: linux-kernel@vger.kernel.org
> Signed-off-by: Chen Yu <yu.c.chen@intel.com>
> ---
>  arch/x86/kernel/cpu/mtrr/main.c | 13 +++++++++++++
>  1 file changed, 13 insertions(+)
> 
> diff --git a/arch/x86/kernel/cpu/mtrr/main.c b/arch/x86/kernel/cpu/mtrr/main.c
> index 24e87e7..eddaa89 100644
> --- a/arch/x86/kernel/cpu/mtrr/main.c
> +++ b/arch/x86/kernel/cpu/mtrr/main.c
> @@ -813,15 +813,28 @@ void mtrr_save_state(void)
>  	put_online_cpus();
>  }
>  
> +static bool __read_mostly no_aps_delay;
> +
> +static int __init no_aps_setup(char *str)
> +{
> +	no_aps_delay = true;
> +	pr_info("hack: do not delay aps mtrr/pat initialization.\n");
> +
> +	return 0;
> +}
> +
>  void set_mtrr_aps_delayed_init(void)
>  {
>  	if (!mtrr_enabled())
>  		return;
>  	if (!use_intel())
>  		return;
> +	if (no_aps_delay)
> +		return;
>  
>  	mtrr_aps_delayed_init = true;
>  }
> +early_param("no_aps_delay", no_aps_setup);
>  
>  /*
>   * Delayed MTRR initialization for all AP's
> -- 
> 2.7.4
> 

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2017-01-16  2:57 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-12-20 10:21 [PATCH DEBUG] x86, pat/mtrr: MTRR/PAT init earlier for each APs Chen Yu
2016-12-20 10:56 ` Lukas Wunner
2016-12-21  2:32   ` Chen Yu
2016-12-21  6:51   ` Chen Yu
2016-12-21  9:54     ` Lukas Wunner
2017-01-16  2:56 ` Chen Yu

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).