locking/lockdep: Add a new class of terminal locks

A terminal lock is a lock where further locking or unlocking on another lock is not allowed. IOW, no forward dependency is permitted.

With such a restriction in place, we don't really need to do a full validation of the lock chain involving a terminal lock. Instead, we just check if there is any further locking or unlocking on another lock when a terminal lock is being held.

Only spinlocks which are acquired by the _irq or _irqsave variants or in IRQ disabled context should be classified as terminal locks.

By adding this new lock type, we can save entries in lock_chains[], chain_hlocks[], list_entries[] and stack_trace[]. By marking suitable locks as terminal, we reduce the chance of overflowing those tables allowing them to focus on locks that can have both forward and backward dependencies.

Four bits are stolen from the pin_count of the held_lock structure to hold a new 4-bit flags field. The pin_count field is essentially a summation of 16-bit random cookie values. Removing 4 bits still allow the pin_count to accumulate up to almost 4096 of those cookie values.

Signed-off-by Waiman Long <[email protected]>

---
 include/linux/lockdep.h            | 29 ++++++++++++++++++++---
 kernel/locking/lockdep.c           | 47 ++++++++++++++++++++++++++++++++------
 kernel/locking/lockdep_internals.h |  5 ++++
 kernel/locking/lockdep_proc.c      | 11 +++++++--
 4 files changed, 80 insertions(+), 12 deletions(-)

include/linux/lockdep.h +1 -0

index 8fe5b4f..a146bca 100644
@@ -144,9 +144,20 @@ struct lock_class_stats {
 
 /*
  * Lockdep class type flags
+ *

The db->lock is a raw spinlock and so the lock hold time is supposed to be short. This will not be the case when printk() is being involved in some of the critical sections. In order to avoid the long hold time, in case some messages need to be printed, the debug_object_is_on_stack() and debug_print_object() calls are now moved out of those critical sections.

Signed-off-by Waiman Long <[email protected]>

---
 lib/debugobjects.c | 61 +++++++++++++++++++++++++++++++++++++-----------------
 1 file changed, 42 insertions(+), 19 deletions(-)

lib/debugobjects.c +41 -18

index 403dd95..4216d3d 100644
@@ -376,6 +376,8 @@ static void debug_object_is_on_stack(void *addr, int onstack)
 	struct debug_bucket *db;
 	struct debug_obj *obj;
 	unsigned long flags;
+	bool debug_printobj = false;
+	bool debug_chkstack = false;
 
 	fill_pool();
 

@@ -392,7 +394,7 @@ static void debug_object_is_on_stack(void *addr, int onstack)
 			debug_objects_oom();
 			return;
 		}
-		debug_object_is_on_stack(addr, onstack);
+		debug_chkstack = true;
 	}
 
 	switch (obj->state) {

@@ -403,20 +405,25 @@ static void debug_object_is_on_stack(void *addr, int onstack)
 		break;
 
 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "init");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "init");
 		debug_object_fixup(descr->fixup_init, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "init");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}
 
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_chkstack)
+		debug_object_is_on_stack(addr, onstack);
+	if (debug_printobj)
+		debug_print_object(obj, "init");
+
 }
 
 /**

@@ -474,6 +481,8 @@ int debug_object_activate(void *addr, struct debug_obj_descr *descr)
 
 	obj = lookup_object(addr, db);
 	if (obj) {
+		bool debug_printobj = false;
+
 		switch (obj->state) {
 		case ODEBUG_STATE_INIT:
 		case ODEBUG_STATE_INACTIVE:

@@ -482,14 +491,14 @@ int debug_object_activate(void *addr, struct debug_obj_descr *descr)
 			break;
 
 		case ODEBUG_STATE_ACTIVE:
-			debug_print_object(obj, "activate");
 			state = obj->state;
 			raw_spin_unlock_irqrestore(&db->lock, flags);
+			debug_print_object(obj, "activate");
 			ret = debug_object_fixup(descr->fixup_activate, addr, state);
 			return ret ? 0 : -EINVAL;
 
 		case ODEBUG_STATE_DESTROYED:
-			debug_print_object(obj, "activate");
+			debug_printobj = true;
 			ret = -EINVAL;
 			break;
 		default:

@@ -497,10 +506,13 @@ int debug_object_activate(void *addr, struct debug_obj_descr *descr)
 			break;
 		}
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		if (debug_printobj)
+			debug_print_object(obj, "activate");
 		return ret;
 	}
 
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+
 	/*
 	 * We are here when a static object is activated. We
 	 * let the type specific code confirm whether this is

@@ -532,6 +544,7 @@ void debug_object_deactivate(void *addr, struct debug_obj_descr *descr)
 	struct debug_bucket *db;
 	struct debug_obj *obj;
 	unsigned long flags;
+	bool debug_printobj = false;
 
 	if (!debug_objects_enabled)
 		return;

@@ -549,24 +562,27 @@ void debug_object_deactivate(void *addr, struct debug_obj_descr *descr)
 			if (!obj->astate)
 				obj->state = ODEBUG_STATE_INACTIVE;
 			else
-				debug_print_object(obj, "deactivate");
+				debug_printobj = true;
 			break;
 
 		case ODEBUG_STATE_DESTROYED:
-			debug_print_object(obj, "deactivate");
+			debug_printobj = true;
 			break;
 		default:
 			break;
 		}
-	} else {
+	}
+
+	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (!obj) {
 		struct debug_obj o = { .object = addr,
 				       .state = ODEBUG_STATE_NOTAVAILABLE,
 				       .descr = descr };
 
 		debug_print_object(&o, "deactivate");
+	} else if (debug_printobj) {
+		debug_print_object(obj, "deactivate");
 	}
-
-	raw_spin_unlock_irqrestore(&db->lock, flags);
 }
 EXPORT_SYMBOL_GPL(debug_object_deactivate);
 

@@ -581,6 +597,7 @@ void debug_object_destroy(void *addr, struct debug_obj_descr *descr)
 	struct debug_bucket *db;
 	struct debug_obj *obj;
 	unsigned long flags;
+	bool debug_printobj = false;
 
 	if (!debug_objects_enabled)
 		return;

@@ -600,20 +617,22 @@ void debug_object_destroy(void *addr, struct debug_obj_descr *descr)
 		obj->state = ODEBUG_STATE_DESTROYED;
 		break;
 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "destroy");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "destroy");
 		debug_object_fixup(descr->fixup_destroy, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "destroy");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}
 out_unlock:
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_printobj)
+		debug_print_object(obj, "destroy");
 }
 EXPORT_SYMBOL_GPL(debug_object_destroy);
 

@@ -642,9 +661,9 @@ void debug_object_free(void *addr, struct debug_obj_descr *descr)
 
 	switch (obj->state) {
 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "free");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "free");
 		debug_object_fixup(descr->fixup_free, addr, state);
 		return;
 	default:

@@ -717,6 +736,7 @@ void debug_object_assert_init(void *addr, struct debug_obj_descr *descr)
 	struct debug_bucket *db;
 	struct debug_obj *obj;
 	unsigned long flags;
+	bool debug_printobj = false;
 
 	if (!debug_objects_enabled)
 		return;

@@ -732,22 +752,25 @@ void debug_object_assert_init(void *addr, struct debug_obj_descr *descr)
 			if (obj->astate == expect)
 				obj->astate = next;
 			else
-				debug_print_object(obj, "active_state");
+				debug_printobj = true;
 			break;
 
 		default:
-			debug_print_object(obj, "active_state");
+			debug_printobj = true;
 			break;
 		}
-	} else {
+	}
+
+	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (!obj) {
 		struct debug_obj o = { .object = addr,
 				       .state = ODEBUG_STATE_NOTAVAILABLE,
 				       .descr = descr };
 
 		debug_print_object(&o, "active_state");
+	} else if (debug_printobj) {
+		debug_print_object(obj, "active_state");
 	}
-
-	raw_spin_unlock_irqrestore(&db->lock, flags);
 }
 EXPORT_SYMBOL_GPL(debug_object_active_state);
 

@@ -783,10 +806,10 @@ static void __debug_check_no_obj_freed(const void *address, unsigned long size)
 

Quoted 22 lines

lib/debugobjects.c +6 -2

 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "init");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "init");
 		debug_object_fixup(descr->fixup_init, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "init");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}
 
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_chkstack)
+		debug_object_is_on_stack(addr, onstack);
+	if (debug_printobj)
+		debug_print_object(obj, "init");

As a side note, one of the test systems that I used generated a debugobjects splat in the bootup process and the system hanged afterward. Applying this patch alone fix the hanging problem and the system booted up successfully. So it is not really a good idea to call printk() while holding a raw spinlock.

Some serial consoles call mod_timer(). So what we could have with the debug objects enabled was

	mod_timer()
	 lock_timer_base()
	  debug_activate()
	   printk()
	    call_console_drivers()
	     foo_console()
	      mod_timer()
	       lock_timer_base()       << deadlock

That's one possible scenario. The other one can involve console's IRQ handler, uart port spinlock, mod_timer, debug objects, printk, and an eventual deadlock on the uart port spinlock. This one can be mitigated with printk_safe. But mod_timer() deadlock will require a different fix.

So maybe we need to switch debug objects print-outs to _always_ printk_deferred(). Debug objects can be used in code which cannot do direct printk() - timekeeping is just one example.

Quoted 3 lines

So maybe we need to switch debug objects print-outs to _always_ printk_deferred(). Debug objects can be used in code which cannot do direct printk() - timekeeping is just one example.

No, printk_deferred() is a disease, it needs to be eradicated, not spread around.

Quoted 6 lines · Peter Zijlstra

Quoted 3 lines

So maybe we need to switch debug objects print-outs to _always_ printk_deferred(). Debug objects can be used in code which cannot do direct printk() - timekeeping is just one example.

No, printk_deferred() is a disease, it needs to be eradicated, not spread around.

deadlock-free printk() is deferred, but OK.

Another idea then:

---

lib/debugobjects.c +3 -1

index 70935ed91125..3928c2b2f77c 100644
@@ -323,10 +323,13 @@ static void debug_print_object(struct debug_obj *obj, char *msg)
 		void *hint = descr->debug_hint ?
 			descr->debug_hint(obj->object) : NULL;
 		limit++;
+
+		bust_spinlocks(1);
 		WARN(1, KERN_ERR "ODEBUG: %s %s (active state %u) "
 				 "object type: %s hint: %pS\n",
 			msg, obj_states[obj->state], obj->astate,
 			descr->name, hint);
+		bust_spinlocks(0);
 	}
 	debug_objects_warnings++;
 }
 
---

This should make serial consoles re-entrant.
So printk->console_driver_write() hopefully will not deadlock.

Quoted 2 lines

This should make serial consoles re-entrant.
So printk->console_driver_write() hopefully will not deadlock.

Is the re-entrance safe? Some risk might be acceptable in Oops/panic situations. It is much less acceptable for random warnings.

On (11/23/18 12:48), Petr Mladek wrote:
[..]

Quoted 5 lines

Quoted 2 lines

This should make serial consoles re-entrant.
So printk->console_driver_write() hopefully will not deadlock.

Is the re-entrance safe? Some risk might be acceptable in Oops/panic situations. It is much less acceptable for random warnings.

Good question.

But what's the alternative? A deadlock in a serial console driver; such that even panic() is not guaranteed to make through it (at least of now). debug objects are used from the code which cannot re-entrant console drivers.

bust_spinlock is called from various paths, not only panic. git grep bust_spinlocks | wc -l
62

So we already switch to re-entrant consoles (and accept the risks) in mm/fault.c, kernel/traps.c and so on. Which, I guess, makes us a little more confident, faults/traps happen often enough.

It seems, that, more or less, serial consoles are ready to handle it. UART consoles in ->write() callbacks just do a bunch of writel() [for every char + \r\n].

On (11/21/18 11:49), Waiman Long wrote:
[..]

Quoted 16 lines

Quoted 16 lines

lib/debugobjects.c +2 -2

 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "init");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "init");
 		debug_object_fixup(descr->fixup_init, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "init");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}

Quoted 6 lines

Quoted 6 lines

lib/debugobjects.c +4 -0

 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_chkstack)
+		debug_object_is_on_stack(addr, onstack);
+	if (debug_printobj)
+		debug_print_object(obj, "init");

[..]

Quoted 6 lines

As a side note, one of the test systems that I used generated a debugobjects splat in the bootup process and the system hanged afterward. Applying this patch alone fix the hanging problem and the system booted up successfully. So it is not really a good idea to call printk() while holding a raw spinlock.

Some serial consoles call mod_timer(). So what we could have with the debug objects enabled was

	mod_timer()
	 lock_timer_base()
	  debug_activate()
	   printk()
	    call_console_drivers()
	     foo_console()
	      mod_timer()
	       lock_timer_base()       << deadlock

Quoted 25 lines · Sergey Senozhatsky

On (11/21/18 11:49), Waiman Long wrote:
[..]

Quoted 22 lines

Quoted 22 lines

lib/debugobjects.c +6 -2

 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "init");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "init");
 		debug_object_fixup(descr->fixup_init, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "init");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}
 
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_chkstack)
+		debug_object_is_on_stack(addr, onstack);
+	if (debug_printobj)
+		debug_print_object(obj, "init");

[..]

Quoted 5 lines

Quoted 5 lines

As a side note, one of the test systems that I used generated a debugobjects splat in the bootup process and the system hanged afterward. Applying this patch alone fix the hanging problem and the system booted up successfully. So it is not really a good idea to call printk() while holding a raw spinlock.

Please, was the system hang reproducible? I wonder if it was a deadlock described by Sergey below.

The commit message is right. printk() might take too long and cause softlockup or livelock. But it does not explain why the system could competely hang.

Also note that prinkt() should not longer block a single process indefinitely thanks to the commit dbdda842fe96f8932 ("printk:
Add console owner and waiter logic to load balance console writes").

Quoted 11 lines

Some serial consoles call mod_timer(). So what we could have with the debug objects enabled was

	mod_timer()
	 lock_timer_base()
	  debug_activate()
	   printk()
	    call_console_drivers()
	     foo_console()
	      mod_timer()
	       lock_timer_base()       << deadlock

Anyway, I wonder what was the primary motivation for this patch. Was it the system hang? Or was it lockdep report about nesting two terminal locks: db->lock, pool_lock with logbuf_lock?

Quoted 3 lines · Petr Mladek

Anyway, I wonder what was the primary motivation for this patch. Was it the system hang? Or was it lockdep report about nesting two terminal locks: db->lock, pool_lock with logbuf_lock?

The primary motivation was to make sure that printk() won't be called while holding either db->lock or pool_lock in the debugobjects code. In the determination of which locks can be made terminal, I focused on local spinlocks that won't cause boundary to an unrelated subsystem as it will greatly complicate the analysis.

I didn't realize that it fixed a hang problem that I was seeing until I did bisection to find out that it was caused by the patch that cause the debugobjects splat in the first place a few days ago. I was comparing the performance status of the pre and post patched kernel. The pre-patch kernel failed to boot in the one of my test systems, but the post-patched kernel could. I narrowed it down to this patch as the fix for the hang problem.

On (11/21/18 11:49), Waiman Long wrote:
[..]

Quoted 22 lines

Quoted 22 lines

lib/debugobjects.c +6 -2

 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "init");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "init");
 		debug_object_fixup(descr->fixup_init, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "init");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}
 
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_chkstack)
+		debug_object_is_on_stack(addr, onstack);
+	if (debug_printobj)
+		debug_print_object(obj, "init");

[..]

Quoted 5 lines

As a side note, one of the test systems that I used generated a debugobjects splat in the bootup process and the system hanged afterward. Applying this patch alone fix the hanging problem and the system booted up successfully. So it is not really a good idea to call printk() while holding a raw spinlock.

Right, I like this patch.
And I think that we, maybe, can go even further.

Some serial consoles call mod_timer(). So what we could have with the debug objects enabled was

	mod_timer()
	 lock_timer_base()
	  debug_activate()
	   printk()
	    call_console_drivers()
	     foo_console()
	      mod_timer()
	       lock_timer_base()       << deadlock

That's one possible scenario. The other one can involve console's IRQ handler, uart port spinlock, mod_timer, debug objects, printk, and an eventual deadlock on the uart port spinlock. This one can be mitigated with printk_safe. But mod_timer() deadlock will require a different fix.

So maybe we need to switch debug objects print-outs to _always_ printk_deferred(). Debug objects can be used in code which cannot do direct printk() - timekeeping is just one example.

	-ss

Quoted 27 lines

[..]

Quoted 5 lines

As a side note, one of the test systems that I used generated a debugobjects splat in the bootup process and the system hanged afterward. Applying this patch alone fix the hanging problem and the system booted up successfully. So it is not really a good idea to call printk() while holding a raw spinlock.

Right, I like this patch.
And I think that we, maybe, can go even further.

Some serial consoles call mod_timer(). So what we could have with the debug objects enabled was

	mod_timer()
	 lock_timer_base()
	  debug_activate()
	   printk()
	    call_console_drivers()
	     foo_console()
	      mod_timer()
	       lock_timer_base()       << deadlock

That's one possible scenario. The other one can involve console's IRQ handler, uart port spinlock, mod_timer, debug objects, printk, and an eventual deadlock on the uart port spinlock. This one can be mitigated with printk_safe. But mod_timer() deadlock will require a different fix.

Quoted 3 lines

So maybe we need to switch debug objects print-outs to _always_ printk_deferred(). Debug objects can be used in code which cannot do direct printk() - timekeeping is just one example.

Actually, I don't think that was the cause of the hang.

The debugobjects splat was caused by debug_object_is_on_stack(), below was the output:

[    6.890048] ODEBUG: object (____ptrval____) is NOT on stack (____ptrval____), but annotated.
[    6.891000] WARNING: CPU: 28 PID: 1 at lib/debugobjects.c:369 __debug_object_init.cold.11+0x51/0x2d6

   11.270654] systemd[1]: systemd 239 running in system mode. (+PAM

(quoted diff) +3 -0

+AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN
+PCRE2 default-hierarchy=legacy)

[   11.311307] systemd[1]: Detected architecture x86-64. [   11.316420] systemd[1]: Running in initial RAM disk.

Welcome to

The system is not responsive at this point.

I am not totally sure what caused this.

Quoted 51 lines · Sergey Senozhatsky

On (11/21/18 11:49), Waiman Long wrote:
[..]

Quoted 22 lines

Quoted 22 lines

lib/debugobjects.c +6 -2

 	case ODEBUG_STATE_ACTIVE:
-		debug_print_object(obj, "init");
 		state = obj->state;
 		raw_spin_unlock_irqrestore(&db->lock, flags);
+		debug_print_object(obj, "init");
 		debug_object_fixup(descr->fixup_init, addr, state);
 		return;
 
 	case ODEBUG_STATE_DESTROYED:
-		debug_print_object(obj, "init");
+		debug_printobj = true;
 		break;
 	default:
 		break;
 	}
 
 	raw_spin_unlock_irqrestore(&db->lock, flags);
+	if (debug_chkstack)
+		debug_object_is_on_stack(addr, onstack);
+	if (debug_printobj)
+		debug_print_object(obj, "init");

[..]

Quoted 5 lines

As a side note, one of the test systems that I used generated a debugobjects splat in the bootup process and the system hanged afterward. Applying this patch alone fix the hanging problem and the system booted up successfully. So it is not really a good idea to call printk() while holding a raw spinlock.

Right, I like this patch.
And I think that we, maybe, can go even further.

Some serial consoles call mod_timer(). So what we could have with the debug objects enabled was

	mod_timer()
	 lock_timer_base()
	  debug_activate()
	   printk()
	    call_console_drivers()
	     foo_console()
	      mod_timer()
	       lock_timer_base()       << deadlock

That's one possible scenario. The other one can involve console's IRQ handler, uart port spinlock, mod_timer, debug objects, printk, and an eventual deadlock on the uart port spinlock. This one can be mitigated with printk_safe. But mod_timer() deadlock will require a different fix.

Quoted 5 lines

So maybe we need to switch debug objects print-outs to _always_ printk_deferred(). Debug objects can be used in code which cannot do direct printk() - timekeeping is just one example.

	-ss

Actually, I don't think that was the cause of the hang. The debugobjects splat was caused by debug_object_is_on_stack(), below was the output:

[    6.890048] ODEBUG: object (____ptrval____) is NOT on stack (____ptrval____), but annotated.
[    6.891000] WARNING: CPU: 28 PID: 1 at lib/debugobjects.c:369 __debug_object_init.cold.11+0x51/0x2d6
[    6.891000] Modules linked in:
[    6.891000] CPU: 28 PID: 1 Comm: swapper/0 Not tainted 4.18.0-41.el8.bz1651764_cgroup_debug.x86_64+debug #1
[    6.891000] Hardware name: HPE ProLiant DL120 Gen10/ProLiant DL120 Gen10, BIOS U36 11/14/2017
[    6.891000] RIP: 0010:__debug_object_init.cold.11+0x51/0x2d6 [    6.891000] Code: ea 03 80 3c 02 00 0f 85 85 02 00 00 49 8b 54 24 18 48 89 de 4c 89 44 24 10 48 c7 c7 00 ce 22 94 e8 73 18 62 ff 4c 8b 44 24 10 <0f> 0b e9 60 db ff ff 41 83 c4 01 b8 ff ff 37 00 44 89 25 ce 46 f9 [    6.891000] RSP: 0000:ffff880104187960 EFLAGS: 00010086
[    6.891000] RAX: 0000000000000050 RBX: ffffffff9764c570 RCX:
0000000000000000
[    6.891000] RDX: 0000000000000000 RSI: 0000000000000000 RDI:
ffff880104178ca8
[    6.891000] RBP: 1ffff10020830f34 R08: ffff8807ce68a1d0 R09:
fffffbfff2923554
[    6.891000] R10: fffffbfff2923554 R11: ffffffff9491aaa3 R12:
ffff880104178000
[    6.891000] R13: ffffffff96c809b8 R14: 000000000000a370 R15:
ffff8807ce68a1c0
[    6.891000] FS:  0000000000000000(0000) GS:ffff8807d4200000(0000) knlGS:0000000000000000
[    6.891000] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [    6.891000] CR2: 0000000000000000 CR3: 000000028de16001 CR4:
00000000007606e0
[    6.891000] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[    6.891000] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[    6.891000] PKRU: 00000000
[    6.891000] Call Trace:
[    6.891000]  ? debug_object_fixup+0x30/0x30
[    6.891000]  ? _raw_spin_unlock_irqrestore+0x4b/0x60
[    6.891000]  ? __lockdep_init_map+0x12f/0x510
[    6.891000]  ? __lockdep_init_map+0x12f/0x510
[    6.891000]  virt_efi_get_next_variable+0xa2/0x160
[    6.891000]  efivar_init+0x1c4/0x6d7
[    6.891000]  ? efivar_ssdt_setup+0x3b/0x3b
[    6.891000]  ? efivar_entry_iter+0x120/0x120
[    6.891000]  ? find_held_lock+0x3a/0x1c0
[    6.891000]  ? lock_downgrade+0x5e0/0x5e0
[    6.891000]  ? kmsg_dump_rewind_nolock+0xd9/0xd9
[    6.891000]  ? _raw_spin_unlock_irqrestore+0x4b/0x60
[    6.891000]  ? trace_hardirqs_on_caller+0x381/0x570
[    6.891000]  ? efivar_ssdt_iter+0x1f4/0x1f4
[    6.891000]  efisubsys_init+0x1be/0x4ae
[    6.891000]  ? kernfs_get.part.8+0x4c/0x60
[    6.891000]  ? efivar_ssdt_iter+0x1f4/0x1f4
[    6.891000]  ? __kernfs_create_file+0x235/0x2e0
[    6.891000]  ? efivar_ssdt_iter+0x1f4/0x1f4
[    6.891000]  do_one_initcall+0xe9/0x5fd
[    6.891000]  ? perf_trace_initcall_level+0x450/0x450
[    6.891000]  ? __wake_up_common+0x5a0/0x5a0
[    6.891000]  ? lock_downgrade+0x5e0/0x5e0
[    6.891000]  kernel_init_freeable+0x51a/0x5f2
[    6.891000]  ? start_kernel+0x7b8/0x7b8
[    6.891000]  ? finish_task_switch+0x19a/0x690
[    6.891000]  ? __switch_to_asm+0x40/0x70
[    6.891000]  ? __switch_to_asm+0x34/0x70
[    6.891000]  ? rest_init+0xe9/0xe9
[    6.891000]  kernel_init+0xc/0x110
[    6.891000]  ? rest_init+0xe9/0xe9
[    6.891000]  ret_from_fork+0x24/0x50
[    6.891000] irq event stamp: 1081352
[    6.891000] hardirqs last  enabled at (1081351): [<ffffffff93af7dab>] _raw_spin_unlock_irqrestore+0x4b/0x60
[    6.891000] hardirqs last disabled at (1081352): [<ffffffff93af85c2>] _raw_spin_lock_irqsave+0x22/0x81
[    6.891000] softirqs last  enabled at (1081334): [<ffffffff93e006f9>] __do_softirq+0x6f9/0xaa0
[    6.891000] softirqs last disabled at (1081325): [<ffffffff921b993f>] irq_exit+0x27f/0x2d0
[    6.891000] ---[ end trace 15e1083fc009a526 ]---

All the messages above were printed while holding a raw spinlock with IRQ disabled. Further down the bootup sequence, the system appeared to hang:

   11.270654] systemd[1]: systemd 239 running in system mode. (+PAM

(quoted diff) +3 -0

+AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN
+PCRE2 default-hierarchy=legacy)

[   11.311307] systemd[1]: Detected architecture x86-64. [   11.316420] systemd[1]: Running in initial RAM disk.

Welcome to

The system is not responsive at this point.

I am not totally sure what caused this. Maybe it was caused by disabling IRQ for too long leading to some kind of corruption. Anyway, moving debug_object_is_on_stack() outside of the IRQ disabled lock critical section seemed to fix the hang problem.

The db->lock is a raw spinlock and so the lock hold time is supposed to be short. This will not be the case when printk() is being involved in some of the critical sections. In order to avoid the long hold time, in case some messages need to be printed, the debug_object_is_on_stack() and debug_print_object() calls are now moved out of those critical sections.

There are use cases where we want to allow nesting of one terminal lock underneath another terminal-like lock. That new lock type is called nestable terminal lock which can optionally allow the acquisition of no more than one regular (non-nestable) terminal lock underneath it.

Quoted 4 lines · Waiman Long

There are use cases where we want to allow nesting of one terminal lock underneath another terminal-like lock. That new lock type is called nestable terminal lock which can optionally allow the acquisition of no more than one regular (non-nestable) terminal lock underneath it.

I think I asked for a more coherent changelog on this. The above is still self contradictory and doesn't explain why you'd ever want such a 'misfeature' :-)

By making the object hash locks nestable terminal locks, we can avoid a bunch of unnecessary lockdep validations as well as saving space in the lockdep tables.

Quoted 3 lines · Waiman Long

By making the object hash locks nestable terminal locks, we can avoid a bunch of unnecessary lockdep validations as well as saving space in the lockdep tables.

Please, explain which terminal lock might be nested.

Hmm, it would hide eventual nesting of other terminal locks. It might reduce lockdep reliability. I wonder if the space optimization is worth it.

Finally, it might be good to add a short explanation what (nested) terminal locks mean into each commit. It would help people to understand the effect without digging into the lockdep code, ...

Best Regards,
Petr

Quoted 5 lines · Petr Mladek

Quoted 3 lines · Waiman Long

By making the object hash locks nestable terminal locks, we can avoid a bunch of unnecessary lockdep validations as well as saving space in the lockdep tables.

Please, explain which terminal lock might be nested.

So the db_lock is made to be nestable that it can allow acquisition of pool_lock (a regular terminal lock) underneath it.

By making the object hash locks nestable terminal locks, we can avoid a bunch of unnecessary lockdep validations as well as saving space in the lockdep tables.