Dramatic lockdep slowdown in 4.14

Hi,

I had noticed that the BeagleBone Black boot time appeared to have increased significantly with 4.14 and yesterday I finally had time to investigate it.

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

I quick bisect pointed to lockdep and specifically the following commit:

28a903f63ec0 ("locking/lockdep: Handle non(or multi)-acquisition
of a crosslock")

which I've verified is the commit which doubled the boot time (compared to 28a903f63ec0^) (added by lockdep crossrelease series [1]).

I also verified that simply disabling CONFIG_PROVE_LOCKING on 4.14-rc4 brought boot time down to about 14 seconds.

Now since it's lockdep I guess this can't really be considered a regression if these changes did improve lockdep correctness, but still, this dramatic slow down essentially forces me to disable PROVE_LOCKING by default on this system.

Is this lockdep slowdown expected and desirable?

Quoted 26 lines · Johan Hovold

Hi,

I had noticed that the BeagleBone Black boot time appeared to have increased significantly with 4.14 and yesterday I finally had time to investigate it.

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

I quick bisect pointed to lockdep and specifically the following commit:

28a903f63ec0 ("locking/lockdep: Handle non(or multi)-acquisition
of a crosslock")

which I've verified is the commit which doubled the boot time (compared to 28a903f63ec0^) (added by lockdep crossrelease series [1]).

I also verified that simply disabling CONFIG_PROVE_LOCKING on 4.14-rc4 brought boot time down to about 14 seconds.

Now since it's lockdep I guess this can't really be considered a regression if these changes did improve lockdep correctness, but still, this dramatic slow down essentially forces me to disable PROVE_LOCKING by default on this system.

Quoted 1 line

Is this lockdep slowdown expected and desirable?

Expected yes, desirable not so much. Its the save_stack_trace() in add_xhlock() (IIRC).

I've not yet had time to figure out what to do about that.

Hi,

I had noticed that the BeagleBone Black boot time appeared to have increased significantly with 4.14 and yesterday I finally had time to investigate it.

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

I quick bisect pointed to lockdep and specifically the following commit:

28a903f63ec0 ("locking/lockdep: Handle non(or multi)-acquisition
of a crosslock")

which I've verified is the commit which doubled the boot time (compared to 28a903f63ec0^) (added by lockdep crossrelease series [1]).

I also verified that simply disabling CONFIG_PROVE_LOCKING on 4.14-rc4 brought boot time down to about 14 seconds.

Now since it's lockdep I guess this can't really be considered a regression if these changes did improve lockdep correctness, but still, this dramatic slow down essentially forces me to disable PROVE_LOCKING by default on this system.

Is this lockdep slowdown expected and desirable?

Quoted 21 lines · Johan Hovold

Hi,

I had noticed that the BeagleBone Black boot time appeared to have increased significantly with 4.14 and yesterday I finally had time to investigate it.

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

I quick bisect pointed to lockdep and specifically the following commit:

28a903f63ec0 ("locking/lockdep: Handle non(or multi)-acquisition
of a crosslock")

which I've verified is the commit which doubled the boot time (compared to 28a903f63ec0^) (added by lockdep crossrelease series [1]).

I also verified that simply disabling CONFIG_PROVE_LOCKING on 4.14-rc4 brought boot time down to about 14 seconds.

Quoted 6 lines

Now since it's lockdep I guess this can't really be considered a regression if these changes did improve lockdep correctness, but still, this dramatic slow down essentially forces me to disable PROVE_LOCKING by default on this system.

Is this lockdep slowdown expected and desirable?

It's not desirable at all.

Does the patch below fix the regression for you - or does the introduction and handling of ->nr_acquire hurt as well?

Commit-ID:  b483cf3bc249d7af706390efa63d6671e80d1c09
Gitweb:     https://git.kernel.org/tip/b483cf3bc249d7af706390efa63d6671e80d1c09
Author:     Ingo Molnar <[email protected]>
AuthorDate: Sat, 14 Oct 2017 09:26:59 +0200
Committer:  Ingo Molnar <[email protected]>
CommitDate: Sat, 14 Oct 2017 12:50:26 +0200

locking/lockdep: Disable cross-release features for now

Johan Hovold reported a big lockdep slowdown on his system, caused by lockdep:

Quoted 11 lines

I had noticed that the BeagleBone Black boot time appeared to have increased significantly with 4.14 and yesterday I finally had time to investigate it.

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

I quick bisect pointed to lockdep and specifically the following commit:

28a903f63ec0 ("locking/lockdep: Handle non(or multi)-acquisition of a crosslock")

Because the final v4.14 release is close, disable the cross-release lockdep features for now.

Bisected-by Johan Hovold <[email protected]>

Debugged-by Johan Hovold <[email protected]>

Reported-by Johan Hovold <[email protected]>

Cc Arnd Bergmann <[email protected]>

Cc Byungchul Park <[email protected]>

Cc Linus Torvalds <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Thomas Gleixner <[email protected]>

Cc Tony Lindgren <[email protected]>

Cc [email protected]

Cc [email protected]

Cc [email protected]

Cc [email protected]

Link http://lkml.kernel.org/r/[email protected] open here

Signed-off-by Ingo Molnar <[email protected]>

---
 lib/Kconfig.debug | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

lib/Kconfig.debug +0 -0

index 2689b7c..e270584 100644

From d796b36bbed5783a22879d745e4d332bb02697a5 Mon Sep 17 00:00:00 2001

Quoted 50 lines · tip-bot for Ingo Molnar

Commit-ID:  b483cf3bc249d7af706390efa63d6671e80d1c09
Gitweb:     https://git.kernel.org/tip/b483cf3bc249d7af706390efa63d6671e80d1c09
Author:     Ingo Molnar <[email protected]>
AuthorDate: Sat, 14 Oct 2017 09:26:59 +0200
Committer:  Ingo Molnar <[email protected]>
CommitDate: Sat, 14 Oct 2017 12:50:26 +0200

locking/lockdep: Disable cross-release features for now

Johan Hovold reported a big lockdep slowdown on his system, caused by lockdep:

Quoted 11 lines

I had noticed that the BeagleBone Black boot time appeared to have increased significantly with 4.14 and yesterday I finally had time to investigate it.

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

I quick bisect pointed to lockdep and specifically the following commit:

28a903f63ec0 ("locking/lockdep: Handle non(or multi)-acquisition of a crosslock")

Because the final v4.14 release is close, disable the cross-release lockdep features for now.

Bisected-by Johan Hovold <[email protected]>

Debugged-by Johan Hovold <[email protected]>

Reported-by Johan Hovold <[email protected]>

Cc Arnd Bergmann <[email protected]>

Cc Byungchul Park <[email protected]>

Cc Linus Torvalds <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Thomas Gleixner <[email protected]>

Cc Tony Lindgren <[email protected]>

Cc [email protected]

Cc [email protected]

Cc [email protected]

Cc [email protected]

Link http://lkml.kernel.org/r/[email protected] open here

Signed-off-by Ingo Molnar <[email protected]>

---
 lib/Kconfig.debug | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

lib/Kconfig.debug +0 -0

index 2689b7c..e270584 100644

lib/Kconfig.debug config PROVE_LOCKING · line 1096

Quoted 7 lines

lib/Kconfig.debug +2 -2

@@ -1092,8 +1092,8 @@ config PROVE_LOCKING
 	select DEBUG_MUTEXES
 	select DEBUG_RT_MUTEXES if RT_MUTEXES
 	select DEBUG_LOCK_ALLOC
-	select LOCKDEP_CROSSRELEASE
-	select LOCKDEP_COMPLETIONS
+	select LOCKDEP_CROSSRELEASE if BROKEN
+	select LOCKDEP_COMPLETIONS if BROKEN

I agree with disabling crossrelease as default, becasue of regression, as I originally did.

However, it's expected to spend more time once it's enabled. Is the following acceptable?

Quoted 16 lines · Byungchul Park

lib/Kconfig.debug config PROVE_LOCKING · line 1096

Quoted 12 lines

lib/Kconfig.debug +2 -2

index 2689b7c..e270584 100644
@@ -1092,8 +1092,8 @@ config PROVE_LOCKING
 	select DEBUG_MUTEXES
 	select DEBUG_RT_MUTEXES if RT_MUTEXES
 	select DEBUG_LOCK_ALLOC
-	select LOCKDEP_CROSSRELEASE
-	select LOCKDEP_COMPLETIONS
+	select LOCKDEP_CROSSRELEASE if BROKEN
+	select LOCKDEP_COMPLETIONS if BROKEN

I agree with disabling crossrelease as default, becasue of regression, as I originally did.

Quoted 2 lines

However, it's expected to spend more time once it's enabled. Is the following acceptable?

No, please fix performance.

Quoted 17 lines · Ingo Molnar

Quoted 16 lines · Byungchul Park

lib/Kconfig.debug config PROVE_LOCKING · line 1096

Quoted 12 lines

lib/Kconfig.debug +2 -2

index 2689b7c..e270584 100644
@@ -1092,8 +1092,8 @@ config PROVE_LOCKING
 	select DEBUG_MUTEXES
 	select DEBUG_RT_MUTEXES if RT_MUTEXES
 	select DEBUG_LOCK_ALLOC
-	select LOCKDEP_CROSSRELEASE
-	select LOCKDEP_COMPLETIONS
+	select LOCKDEP_CROSSRELEASE if BROKEN
+	select LOCKDEP_COMPLETIONS if BROKEN

I agree with disabling crossrelease as default, becasue of regression, as I originally did.

Quoted 4 lines

Quoted 2 lines

However, it's expected to spend more time once it's enabled. Is the following acceptable?

No, please fix performance.

You know very well that with the cross release stuff we have to take the performance hit of stack unwinding because we have no idea whether there will show up a new lock relation later or not. And there is not much you can do in that respect.

OTOH, the cross release feature unearthed real deadlocks already so it is a valuable debug feature and having an explicit config switch which defaults to N is well worth it.

Quoted 8 lines · Thomas Gleixner

Quoted 1 line · Ingo Molnar

No, please fix performance.

You know very well that with the cross release stuff we have to take the performance hit of stack unwinding because we have no idea whether there will show up a new lock relation later or not. And there is not much you can do in that respect.

Quoted 3 lines

OTOH, the cross release feature unearthed real deadlocks already so it is a valuable debug feature and having an explicit config switch which defaults to N is well worth it.

I disagree, because even if that's correct, the choices are not binary. The performance regression was a slowdown of around 7x: lockdep boot overhead on that particula system went from +3 seconds to +21 seconds...

Quoted 3 lines

Quoted 3 lines

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

As a response to the performance regression I haven't seen _any_ attempt to measure, profile and generally quantify the performance impact, which would at least make it more believable that the overhead cannot be reduced. That really makes me worry about the code on a higher level than just whether it can be enabled by default or not.

Caring about the performance of debug features very much matters, _especially_ when they are expensive.

Quoted 9 lines · Ingo Molnar

Quoted 8 lines · Thomas Gleixner

Quoted 1 line · Ingo Molnar

No, please fix performance.

You know very well that with the cross release stuff we have to take the performance hit of stack unwinding because we have no idea whether there will show up a new lock relation later or not. And there is not much you can do in that respect.

Quoted 7 lines

Quoted 3 lines

OTOH, the cross release feature unearthed real deadlocks already so it is a valuable debug feature and having an explicit config switch which defaults to N is well worth it.

I disagree, because even if that's correct, the choices are not binary. The performance regression was a slowdown of around 7x: lockdep boot overhead on that particula system went from +3 seconds to +21 seconds...

Hmm, I might have missed something, but what I've seen in this thread is:

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

So that's 2x not 7x. [...]

Quoted 9 lines · Ingo Molnar

Quoted 8 lines · Thomas Gleixner

Quoted 1 line · Ingo Molnar

No, please fix performance.

You know very well that with the cross release stuff we have to take the performance hit of stack unwinding because we have no idea whether there will show up a new lock relation later or not. And there is not much you can do in that respect.

Quoted 7 lines

Quoted 3 lines

OTOH, the cross release feature unearthed real deadlocks already so it is a valuable debug feature and having an explicit config switch which defaults to N is well worth it.

I disagree, because even if that's correct, the choices are not binary. The performance regression was a slowdown of around 7x: lockdep boot overhead on that particula system went from +3 seconds to +21 seconds...

Hmm, I might have missed something, but what I've seen in this thread is:

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Boot time (from "Linux version" to login prompt) had in fact doubled since 4.13 where it took 17 seconds (with my current config) compared to the 35 seconds I now see with 4.14-rc4.

So that's 2x not 7x. On one of my main test machines it's about ~1.4 so I did not even really notice until this thread came up. Probably I have no expectations on boot time and performance when lockdep is on :)

Quoted 5 lines

As a response to the performance regression I haven't seen _any_ attempt to measure, profile and generally quantify the performance impact, which would at least make it more believable that the overhead cannot be reduced. That really makes me worry about the code on a higher level than just whether it can be enabled by default or not.

I did some quick perf top analysis, not in detail though, and what really dominates with that feature is the unwinder, which needs to be unconditional due to the nature of the problem.

I have not spend a huge amount of time to think about ways to improve that, but I could not come up with anything smart so far.

The only thing I thought about was making the unwind short and only record one or two call levels (if at all) instead of following the full call

chain. That makes it less useful for a quick test, but once you hit a splat you can enable full depth recording for full analysis. In the full analysis case performance is the least of your worries.

Quoted 2 lines

Caring about the performance of debug features very much matters, _especially_ when they are expensive.

I'm not disagreeing. I'm just trying to understand why this is marked BROKEN where I think it should be marked TOO_EXPENSIVE.

Thanks,

tglx

Quoted 16 lines

lib/Kconfig.debug config PROVE_LOCKING · line 1096

Quoted 12 lines

lib/Kconfig.debug +2 -2

index 2689b7c..e270584 100644
@@ -1092,8 +1092,8 @@ config PROVE_LOCKING
 	select DEBUG_MUTEXES
 	select DEBUG_RT_MUTEXES if RT_MUTEXES
 	select DEBUG_LOCK_ALLOC
-	select LOCKDEP_CROSSRELEASE
-	select LOCKDEP_COMPLETIONS
+	select LOCKDEP_CROSSRELEASE if BROKEN
+	select LOCKDEP_COMPLETIONS if BROKEN

I agree with disabling crossrelease as default, becasue of regression, as I originally did.

Quoted 2 lines

However, it's expected to spend more time once it's enabled. Is the following acceptable?

No, please fix performance.