Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Mon, Nov 19, 2018 at 01:55:16PM -0500, Waiman Long wrote: > 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. That's not why you did this patch though; you want to make these locks terminal locks and that means no printk() inside, as that uses locks again. Please write relevant changelogs. ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Mon 2018-11-26 13:57:09, Sergey Senozhatsky wrote: > On (11/23/18 12:48), Petr Mladek wrote: > [..] > > > 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 bust_spinlocks() is followed by die() in several situations. The rests seems to be Oops situations where we an invalid address is being accessed. There is a nontrivial chance that the system would die anyway. Now, if I look into Documentation/core-api/debug-objects.rst, the API is used to detect: - Activation of uninitialized objects - Initialization of active objects - Usage of freed/destroyed objects Of course, all the above situations might lead to the system crash. But even in the worst case, use-after-free, there is a non-trivial chance that the data still would be valid and the system would survive. There might be many other warnings of the same severity. > 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. Where is the border line, please? Do we want to have the kernel sources full of bust_spinlocks() callers? > 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]. But oops_in_progress does not affect only serial (UART) consoles. We want safe lockless consoles. We do not want to run a most-of-the-time-safe code too often. BTW: I have heard that someone from the RT people is working on a big printk() rewrite. One part is a lockless buffer. Another part should be a different handling of safe (lockless) and more complicated consoles. It was presented on some recent conference (I forgot which one). I do not know any details. But the first version should be sent in a near future. Best Regards, Petr ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On (11/23/18 12:48), Petr Mladek wrote: [..] > > 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]. -ss ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Fri 2018-11-23 11:40:48, Sergey Senozhatsky wrote: > On (11/22/18 11:16), Peter Zijlstra wrote: > > > 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. The best solution would be lockless console drivers. Sigh. > Another idea then: > > --- > > diff --git a/lib/debugobjects.c b/lib/debugobjects.c > index 70935ed91125..3928c2b2f77c 100644 > --- a/lib/debugobjects.c > +++ b/lib/debugobjects.c > @@ -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. Is the re-entrance safe? Some risk might be acceptable in Oops/panic situations. It is much less acceptable for random warnings. Best Regards, Petr ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Thu 2018-11-22 15:29:35, Waiman Long wrote: > On 11/22/2018 11:02 AM, Petr Mladek wrote: > > 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. Then please mention this as the real reason in the commit message. The reason that printk might take too long in IRQ context does not explain why we need the patch. printk() is called in IRQ context in many other locations. I do not see why this place should be special. The delay is the price for the chance to see the problem. > 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. The hang is a mystery. My guess is that there is a race somewhere. The patch might have reduced the race window but it probably did not fix the race itself. Best Regards, Petr ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Thu 2018-11-22 14:57:02, Waiman Long wrote: > On 11/21/2018 09:04 PM, Sergey Senozhatsky wrote: > > On (11/21/18 11:49), Waiman Long wrote: > > [..] > >>> case ODEBUG_STATE_ACTIVE: > >>> - debug_print_object(obj, "init"); > >>> state = obj->state; > >>> raw_spin_unlock_irqrestore(>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(>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. > > 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 > > 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: :880104187960 EFLAGS: 00010086 > [ 6.891000] RAX: 0050 RBX: 9764c570 RCX: > > [ 6.891000] RDX: RSI: RDI: > 880104178ca8 > [ 6.891000] RBP: 110020830f34 R08: 8807ce68a1d0 R09: > fbfff2923554 > [ 6.891000] R10: fbfff2923554 R11: 9491aaa3 R12: > 880104178000 > [ 6.891000] R13: 96c809b8 R14: a370 R15: > 8807ce68a1c0 > [ 6.891000] FS: () GS:8807d420() > knlGS: > [ 6.891000] CS: 0010 DS: ES: CR0: 80050033 > [ 6.891000] CR2: CR3: 00028de16001 CR4: > 007606e0 > [ 6.891000] DR0: DR1: DR2: > > [ 6.891000] DR3: DR6: fffe0ff0 DR7: > 0400 > [ 6.891000] PKRU: > [ 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] ?
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On (11/22/18 11:16), Peter Zijlstra wrote: > > 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: --- diff --git a/lib/debugobjects.c b/lib/debugobjects.c index 70935ed91125..3928c2b2f77c 100644 --- a/lib/debugobjects.c +++ b/lib/debugobjects.c @@ -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. IOW, this turns serial consoles into early_consoles, for a while ;) -ss ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On (11/22/18 14:57), Waiman Long wrote: > > [..] > >> 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. > > Actually, I don't think that was the cause of the hang. Oh, I didn't suggest that this was the case. Just talked about more problems with printk in debug objects. Serial consoles call mod_time, mod_timer calls debug objects, debug objects call printk and end up in serial console again. Serial consoles are not re-entrant at this point. > 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 > +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. Hmm, me neither. -ss ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On 11/22/2018 11:02 AM, Petr Mladek wrote:
> On Thu 2018-11-22 11:04:22, Sergey Senozhatsky wrote:
>> On (11/21/18 11:49), Waiman Long wrote:
>> [..]
case ODEBUG_STATE_ACTIVE:
- debug_print_object(obj, "init");
state = obj->state;
raw_spin_unlock_irqrestore(>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(>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.
> Please, was the system hang reproducible? I wonder if it was a
> deadlock described by Sergey below.
Yes, it is 100% reproducible on the testing system that I used.
> 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").
The problem might have been caused by the fact that IRQ was also
disabled in the lock critical section.
>> 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?
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.
Cheers,
Longman
___
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On 11/21/2018 09:04 PM, Sergey Senozhatsky wrote: > On (11/21/18 11:49), Waiman Long wrote: > [..] >>> case ODEBUG_STATE_ACTIVE: >>> - debug_print_object(obj, "init"); >>> state = obj->state; >>> raw_spin_unlock_irqrestore(>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(>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. > 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 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: :880104187960 EFLAGS: 00010086 [ 6.891000] RAX: 0050 RBX: 9764c570 RCX: [ 6.891000] RDX: RSI: RDI: 880104178ca8 [ 6.891000] RBP: 110020830f34 R08: 8807ce68a1d0 R09: fbfff2923554 [ 6.891000] R10: fbfff2923554 R11: 9491aaa3 R12: 880104178000 [ 6.891000] R13: 96c809b8 R14: a370 R15: 8807ce68a1c0 [ 6.891000] FS: () GS:8807d420() knlGS: [ 6.891000] CS: 0010 DS: ES: CR0: 80050033 [ 6.891000] CR2: CR3: 00028de16001 CR4: 007606e0 [ 6.891000] DR0: DR1: DR2: [ 6.891000] DR3: DR6: fffe0ff0 DR7: 0400 [ 6.891000] PKRU: [ 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 [
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Thu 2018-11-22 11:04:22, Sergey Senozhatsky wrote:
> On (11/21/18 11:49), Waiman Long wrote:
> [..]
> > > case ODEBUG_STATE_ACTIVE:
> > > - debug_print_object(obj, "init");
> > > state = obj->state;
> > > raw_spin_unlock_irqrestore(>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(>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.
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").
> 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?
Printk is problematic. It might delay any atomic context
where it is used. I would like to better understand the
problem here before we start spread printk-related hacks.
Best Regards,
Petr
___
iommu mailing list
iommu@lists.linux-foundation.org
https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On Thu, Nov 22, 2018 at 11:04:22AM +0900, Sergey Senozhatsky wrote: > 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. No, printk_deferred() is a disease, it needs to be eradicated, not spread around. ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On (11/21/18 11:49), Waiman Long wrote: [..] > > case ODEBUG_STATE_ACTIVE: > > - debug_print_object(obj, "init"); > > state = obj->state; > > raw_spin_unlock_irqrestore(>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(>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. 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 ___ iommu mailing list iommu@lists.linux-foundation.org https://lists.linuxfoundation.org/mailman/listinfo/iommu
Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
On 11/19/2018 01:55 PM, Waiman Long wrote:
> 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
> ---
> lib/debugobjects.c | 61
> +-
> 1 file changed, 42 insertions(+), 19 deletions(-)
>
> diff --git a/lib/debugobjects.c b/lib/debugobjects.c
> index 403dd95..4216d3d 100644
> --- a/lib/debugobjects.c
> +++ b/lib/debugobjects.c
> @@ -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(>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(>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(>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(>lock, flags);
> + if (debug_printobj)
> + debug_print_object(obj, "activate");
> return ret;
> }
>
> raw_spin_unlock_irqrestore(>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(>lock, flags);
> + if (!obj) {
> struct debug_obj o = { .object = addr,
>
[PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections
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
---
lib/debugobjects.c | 61 +-
1 file changed, 42 insertions(+), 19 deletions(-)
diff --git a/lib/debugobjects.c b/lib/debugobjects.c
index 403dd95..4216d3d 100644
--- a/lib/debugobjects.c
+++ b/lib/debugobjects.c
@@ -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(>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(>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(>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(>lock, flags);
+ if (debug_printobj)
+ debug_print_object(obj, "activate");
return ret;
}
raw_spin_unlock_irqrestore(>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(>lock, flags);
+ if (!obj) {
struct debug_obj o = { .object = addr,
.state = ODEBUG_STATE_NOTAVAILABLE,
.descr = descr };
debug_print_object(,
