Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections

From: Waiman Long
Date: Thu Nov 22 2018 - 14:59:00 EST

Next message: Sasha Levin: "[PATCH AUTOSEL 4.19 29/36] kdb: Use strscpy with destination buffer size"
Previous message: Sasha Levin: "[PATCH AUTOSEL 3.18 7/7] tmpfs: make lseek(SEEK_DATA/SEK_HOLE) return ENXIO with a negative offset"
In reply to: Petr Mladek: "Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections"
Next in thread: Sergey Senozhatsky: "Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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(&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.
> 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: 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
+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.

Cheers,
Longman

Next message: Sasha Levin: "[PATCH AUTOSEL 4.19 29/36] kdb: Use strscpy with destination buffer size"
Previous message: Sasha Levin: "[PATCH AUTOSEL 3.18 7/7] tmpfs: make lseek(SEEK_DATA/SEK_HOLE) return ENXIO with a negative offset"
In reply to: Petr Mladek: "Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections"
Next in thread: Sergey Senozhatsky: "Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]