[PATCH 0/4] Dovetail fixes (v5.13)

[PATCH 0/4] Dovetail fixes (v5.13)

[Philippe Gerum]

From: Philippe Gerum <rpm@xenomai.org>

The usual pain with synchronizing the virtual and real interrupt
states. These issues have been detected while porting to v5.14, some
are reported by CONFIG_DEBUG_LOCKDEP=y.

Philippe Gerum (4):
  x86/ioapic: irq_pipeline: unbreak irqflags tracing
  init: early sync the inband stall with the hardware state
  x86/fault: dovetail: unbreak irqflags tracing
  genirq: irq_pipeline: fix inverted check in debug assertion

 arch/x86/kernel/apic/io_apic.c |  4 ++--
 arch/x86/mm/fault.c            | 12 ++++++------
 init/main.c                    |  1 +
 kernel/irq/pipeline.c          | 10 +++++-----
 4 files changed, 14 insertions(+), 13 deletions(-)

-- 
2.31.1

[PATCH 1/4] x86/ioapic: irq_pipeline: unbreak irqflags tracing

[Philippe Gerum]

From: Philippe Gerum <rpm@xenomai.org>

local_irq_save/restore() pairs should be replaced by
local_irq_save_full() calls when pipelining, not
hard_local_irq_save/restore(), so that lockdep does not complain about
inconsistent irq state (the hard_* form does not invoke the trace_irq*
API).

This fixes this kind of splat at boot:

[    0.124134] Switched APIC routing to physical flat.
[    0.125066] ------------[ cut here ]------------
[    0.125353] DEBUG_LOCKS_WARN_ON(lockdep_hardirqs_enabled())
[    0.125369] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:5521 check_flags+0x102/0x1b0
[    0.126203] Modules linked in:
[    0.126395] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.14.0-rc1+ #31
[    0.126779] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-4.fc34 04/01/2014
[    0.127302] RIP: 0010:check_flags+0x102/0x1b0
[    0.127565] Code: ff ff e8 a1 ff aa ff 85 c0 74 21 44 8b 0d 5e b0 bd 00 45 85 c9 75 15 48 c7 c6 78 73 2d 82 48 c7 c7 88 dd 2b 82 e8 b9 75 fb ff <0f> 0b 48 c7 c7 08 89 2d 82 e8 81 e6 fb ff eb 9e 85 c0 0f 85 42 ff
[    0.128670] RSP: 0000:ffffffff82403cb0 EFLAGS: 00010082
[    0.128983] RAX: 000000000000002f RBX: 0000000000000000 RCX: 0000000000000000
[    0.129409] RDX: 0000000000000003 RSI: 00000000ffffffea RDI: 00000000ffffffff
[    0.129888] RBP: 0000000000000001 R08: ffffffff825573c8 R09: 00000000ffffdfff
[    0.130318] R10: ffffffff824773e0 R11: ffffffff824773e0 R12: ffffffff82461bd8
[    0.130741] R13: 0000000000000046 R14: 0000000000000000 R15: 0000000000000000
[    0.131166] FS:  0000000000000000(0000) GS:ffff888233e00000(0000) knlGS:0000000000000000
[    0.131649] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    0.131993] CR2: ffff88823ffff000 CR3: 0000000002424000 CR4: 00000000000406b0
[    0.132420] Call Trace:
[    0.132572]  lock_acquire.part.0+0x52/0x1f0
[    0.132832]  ? _raw_spin_unlock_irqrestore+0x55/0x70
[    0.133134]  ? rcu_read_lock_sched_held+0xa/0x70
[    0.133419]  ? lock_acquire+0xa0/0x140
[    0.133647]  ? mask_8259A_irq+0x14/0x60
[    0.133883]  _raw_spin_lock_irqsave+0x43/0x90
[    0.134146]  ? mask_8259A_irq+0x14/0x60
[    0.134383]  mask_8259A_irq+0x14/0x60
[    0.134606]  mp_irqdomain_alloc+0x1a7/0x260
[    0.134862]  __irq_domain_alloc_irqs+0x154/0x410
[    0.135144]  alloc_isa_irq_from_domain.constprop.0+0xa0/0xe0
[    0.135486]  mp_map_pin_to_irq+0x1a9/0x310
[    0.135735]  setup_IO_APIC+0x121/0x1d0
[    0.135971]  apic_intr_mode_init+0xff/0x105
[    0.136224]  x86_late_time_init+0x20/0x30
[    0.136469]  start_kernel+0x45f/0x4f8
[    0.136692]  secondary_startup_64_no_verify+0xb0/0xbb

Signed-off-by: Philippe Gerum <rpm@xenomai.org>
---
 arch/x86/kernel/apic/io_apic.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/arch/x86/kernel/apic/io_apic.c b/arch/x86/kernel/apic/io_apic.c
index febaa0f0dcd43ed..59bc9d1824e1f00 100644
--- a/arch/x86/kernel/apic/io_apic.c
+++ b/arch/x86/kernel/apic/io_apic.c
@@ -3078,10 +3078,10 @@ int mp_irqdomain_alloc(struct irq_domain *domain, unsigned int virq,
 	mp_preconfigure_entry(data);
 	mp_register_handler(virq, data->is_level);
 
-	flags = hard_local_irq_save();
+	local_irq_save_full(flags);
 	if (virq < nr_legacy_irqs())
 		legacy_pic->mask(virq);
-	hard_local_irq_restore(flags);
+	local_irq_restore_full(flags);
 
 	apic_printk(APIC_VERBOSE, KERN_DEBUG
 		    "IOAPIC[%d]: Preconfigured routing entry (%d-%d -> IRQ %d Level:%i ActiveLow:%i)\n",
-- 
2.31.1

[PATCH 2/4] init: early sync the inband stall with the hardware state

[Philippe Gerum]

From: Philippe Gerum <rpm@xenomai.org>

Hard irqs are off when start_kernel() is called from the head code, we
must set the stall accordingly. Failing to do so causes lockdep to
complain, such as:

[    0.000000] DEBUG_LOCKS_WARN_ON(!lockdep_hardirqs_enabled())
[    0.000000] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:5525 check_flags+0x193/0x1c0
[    0.000000] Modules linked in:
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted 5.14.0-rc1+ #43
[    0.000000] IRQ stage: Linux
[    0.000000] RIP: 0010:check_flags+0x193/0x1c0
[    0.000000] Code: ff ff e8 60 17 ab ff 85 c0 74 21 44 8b 05 3d bb bd 00 45 85 c0 75 15 48 c7 c6 f7 7f 2d 82 48 c7 c7 38 ea 2b 82 e8 91 7c fb ff <0f> 0b 48 c7 c7 b0 95 2d 82 e8 92 ed fb ff e9 5c ff ff ff 65 48 8b
[    0.000000] RSP: 0000:ffffffff82403db8 EFLAGS: 00010096 ORIG_RAX: 0000000000000000
[    0.000000] RAX: 0000000000000030 RBX: ffffffff8255c6e0 RCX: 0000000000000000
[    0.000000] RDX: 0000000000000002 RSI: ffffffff811c74e4 RDI: 00000000ffffffff
[    0.000000] RBP: ffffffff8242da00 R08: 0000000000000001 R09: 0000000000000000
[    0.000000] R10: ffffffffffffffff R11: 284e4f5f4e524157 R12: ffffffff8242e340
[    0.000000] R13: ffffffff80000200 R14: 0000000000000000 R15: 0000000000000000
[    0.000000] FS:  0000000000000000(0000) GS:ffffffff82afb000(0000) knlGS:0000000000000000
[    0.000000] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    0.000000] CR2: ffff888000013d10 CR3: 0000000002d4c000 CR4: 00000000000000a0
[    0.000000] Call Trace:
[    0.000000]  ? lock_is_held_type+0x6b/0x140
[    0.000000]  ? ___might_sleep+0x26/0x160
[    0.000000]  ? __mutex_lock+0x48/0x8e0
[    0.000000]  ? cgroup_init_subsys+0x26/0x181
[    0.000000]  ? lockdep_init_map_type+0x51/0x260
[    0.000000]  ? lockdep_init_map_type+0x51/0x260
[    0.000000]  ? cgroup_init_subsys+0x26/0x181
[    0.000000]  ? cgroup_init_subsys+0x26/0x181
[    0.000000]  ? cgroup_init_early+0xdd/0xf3
[    0.000000]  ? start_kernel+0x28/0x4ef
[    0.000000]  ? secondary_startup_64_no_verify+0xb0/0xbb
[    0.000000] irq event stamp: 0
[    0.000000] hardirqs last  enabled at (0): [<0000000000000000>] 0x0
[    0.000000] hardirqs last disabled at (0): [<0000000000000000>] 0x0
[    0.000000] softirqs last  enabled at (0): [<0000000000000000>] 0x0
[    0.000000] softirqs last disabled at (0): [<0000000000000000>] 0x0
[    0.000000] random: get_random_bytes called from __warn+0xb9/0x120 with crng_init=0
[    0.000000] ---[ end trace 0000000000000000 ]---
[    0.000000] possible reason: unannotated irqs-on.

Signed-off-by: Philippe Gerum <rpm@xenomai.org>
---
 init/main.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/init/main.c b/init/main.c
index dcc0a764626aba8..259b938d7cd2973 100644
--- a/init/main.c
+++ b/init/main.c
@@ -878,6 +878,7 @@ asmlinkage __visible void __init __no_sanitize_address start_kernel(void)
 	char *command_line;
 	char *after_dashes;
 
+	stall_inband_nocheck();
 	set_task_stack_end_magic(&init_task);
 	smp_setup_processor_id();
 	debug_objects_early_init();
-- 
2.31.1

[PATCH 3/4] x86/fault: dovetail: unbreak irqflags tracing

[Philippe Gerum]

From: Philippe Gerum <rpm@xenomai.org>

Conditional irq enabling/disabling helpers must inform the irq tracer
about the change, so that lockdep does not complain about inconsistent
irq state. Fixing up the stall bit using the common
local_irq_enable/disable() helpers ensures this.

CAUTION: we make sure to always have hard irqs on before calling
local_irq_enable(), so that we won't trigger the corresponding
pipeline debug assertion.

Failing to do so may cause such warning:

[    5.489344] DEBUG_LOCKS_WARN_ON(!lockdep_hardirqs_enabled())
[    5.489345] WARNING: CPU: 1 PID: 1 at kernel/locking/lockdep.c:5525 check_flags+0x193/0x1c0
[    5.489345] Modules linked in:
[    5.489346] CPU: 1 PID: 1 Comm: init Not tainted 5.14.0-rc1+ #48
[    5.489346] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-4.fc34 04/01/2014
[    5.489347] IRQ stage: Linux
[    5.489347] RIP: 0010:check_flags+0x193/0x1c0
[    5.489348] Code: ff ff e8 c0 16 ab ff 85 c0 74 21 44 8b 05 6d bb bd 00 45 85 c0 75 15 48 c7 c6 47 80 2d 82 48 c7 c7 60 ea 2b 82 e8 41 7c fb ff <0f> 0b 48 c7 c7 00 96 2d 82 e8 42 ed fb ff e9 5c ff ff ff 65 48 8b
[    5.489349] RSP: 0018:ffffc90000013b98 EFLAGS: 00010092
[    5.489349] RAX: 0000000000000030 RBX: ffffffff8255c720 RCX: 0000000000000023
[    5.489350] RDX: 0000000000000023 RSI: ffffffff822bea76 RDI: ffff8882343e9a70
[    5.489350] RBP: ffff888100278000 R08: ffff8882343eba60 R09: ffff8883343e9aba
[    5.489351] R10: ffffffffffffffff R11: 284e4f5f4e524157 R12: ffff888100278940
[    5.489351] R13: 0000000000000200 R14: 0000000000000000 R15: 0000000000000000
[    5.489352] FS:  0000000000000000(0000) GS:ffff888234200000(0000) knlGS:0000000000000000
[    5.489352] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    5.489353] CR2: 000000000050edeb CR3: 000000010004c000 CR4: 00000000000406e0
[    5.489353] Call Trace:
[    5.489353]  lock_is_held_type+0x6b/0x140
[    5.489354]  rcu_read_lock_sched_held+0x57/0x80
[    5.489354]  lock_acquire+0x11c/0x2c0
[    5.489355]  ? add_chain_cache+0x212/0x4a0
[    5.489355]  down_read_trylock+0x73/0xf0
[    5.489355]  ? do_user_addr_fault+0x156/0x720
[    5.489356]  do_user_addr_fault+0x156/0x720
[    5.489356]  exc_page_fault+0x78/0x100
[    5.489356]  asm_exc_page_fault+0x1e/0x30
[    5.489357] RIP: 0010:__clear_user+0x40/0x70
[    5.489357] Code: 00 00 00 e8 52 2a d2 ff 0f 1f 00 48 89 d8 48 c1 eb 03 48 89 ef 83 e0 07 48 89 d9 48 85 c9 74 19 66 2e 0f 1f 84 00 00 00 00 00 <48> c7 07 00 00 00 00 48 83 c7 08 ff c9 75 f1 48 89 c1 85 c9 74 0a
[    5.489358] RSP: 0018:ffffc90000013da8 EFLAGS: 00010206
[    5.489359] RAX: 0000000000000005 RBX: 0000000000000042 RCX: 0000000000000042
[    5.489359] RDX: ffff888100278000 RSI: ffffffff822d2f72 RDI: 000000000050edeb
[    5.489360] RBP: 000000000050edeb R08: 0000000000000000 R09: 00000000ffffffff
[    5.489360] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[    5.489361] R13: ffff888102628200 R14: ffff88810262eaa0 R15: ffff8881008b1940
[    5.489361]  ? __clear_user+0x1e/0x70
[    5.489361]  load_elf_binary+0xc0c/0xd80
[    5.489362]  search_binary_handler+0xc7/0x230
[    5.489362]  exec_binprm+0xa8/0x2f0
[    5.489362]  bprm_execve.part.0+0x1c0/0x2e0
[    5.489363]  ? rest_init+0x250/0x250
[    5.489363]  kernel_execve+0x12e/0x1b0
[    5.489363]  try_to_run_init_process+0x10/0x34
[    5.489364]  kernel_init+0xc7/0x110
[    5.489364]  ret_from_fork+0x22/0x30
[    5.489364] irq event stamp: 13468052
[    5.489365] hardirqs last  enabled at (13468051): [<ffffffff812efe0e>] free_unref_page_list+0x44e/0x590
[    5.489365] hardirqs last disabled at (13468052): [<ffffffff81aa98fa>] exc_page_fault+0x3a/0x100
[    5.489366] softirqs last  enabled at (13467850): [<ffffffff81a17fa3>] xs_tcp_send_request+0x143/0x210
[    5.489367] softirqs last disabled at (13467848): [<ffffffff81855479>] release_sock+0x19/0xa0
[    5.489367] ---[ end trace d0075380c74bdffc ]---
[    5.489368] possible reason: unannotated irqs-on.
[    5.489368] irq event stamp: 13468052
[    5.489368] hardirqs last  enabled at (13468051): [<ffffffff812efe0e>] free_unref_page_list+0x44e/0x590
[    5.489369] hardirqs last disabled at (13468052): [<ffffffff81aa98fa>] exc_page_fault+0x3a/0x100
[    5.489370] softirqs last  enabled at (13467850): [<ffffffff81a17fa3>] xs_tcp_send_request+0x143/0x210
[    5.489370] softirqs last disabled at (13467848): [<ffffffff81855479>] release_sock+0x19/0xa0

Signed-off-by: Philippe Gerum <rpm@xenomai.org>
---
 arch/x86/mm/fault.c | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/arch/x86/mm/fault.c b/arch/x86/mm/fault.c
index f37098aa4e58655..0f042e72a11e449 100644
--- a/arch/x86/mm/fault.c
+++ b/arch/x86/mm/fault.c
@@ -803,19 +803,19 @@ static bool is_vsyscall_vaddr(unsigned long vaddr)
 
 static inline void cond_reenable_irqs_user(void)
 {
-	if (running_inband())
-		unstall_inband_nocheck();
-
 	hard_local_irq_enable();
+
+	if (running_inband())
+		local_irq_enable();
 }
 
 static inline void cond_reenable_irqs_kernel(irqentry_state_t state,
 					struct pt_regs *regs)
 {
 	if (regs->flags & X86_EFLAGS_IF) {
-		if (state.stage_info == IRQENTRY_INBAND_UNSTALLED)
-			unstall_inband_nocheck();
 		hard_local_irq_enable();
+		if (state.stage_info == IRQENTRY_INBAND_UNSTALLED)
+			local_irq_enable();
 	}
 }
 
@@ -824,7 +824,7 @@ static inline void cond_disable_irqs(void)
 	hard_local_irq_disable();
 
 	if (running_inband())
-		stall_inband_nocheck();
+		local_irq_disable();
 }
 
 #else  /* !CONFIG_IRQ_PIPELINE */
-- 
2.31.1

[PATCH 4/4] genirq: irq_pipeline: fix inverted check in debug assertion

[Philippe Gerum]

From: Philippe Gerum <rpm@xenomai.org>

Signed-off-by: Philippe Gerum <rpm@xenomai.org>
---
 kernel/irq/pipeline.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/kernel/irq/pipeline.c b/kernel/irq/pipeline.c
index 090fcc8bbb6a449..585bd3b6fae5ef4 100644
--- a/kernel/irq/pipeline.c
+++ b/kernel/irq/pipeline.c
@@ -1076,15 +1076,15 @@ int generic_pipeline_irq(unsigned int irq, struct pt_regs *regs)
 			pr_err("IRQ pipeline: interrupts enabled on entry (IRQ%u)\n",
 			       irq);
 		}
+
 		/*
 		 * Running with the oob stage stalled implies hardirqs
 		 * off.  For this reason, if the oob stage is stalled
-		 * on pipeline entry but we still receive an interrupt
-		 * from the hardware, something is badly broken in our
-		 * interrupt state. Try fixing up, but without great
-		 * hopes.
+		 * when we receive an interrupt from the hardware,
+		 * something is badly broken in our interrupt
+		 * state. Try fixing up, but without great hopes.
 		 */
-		if (on_pipeline_entry() && test_oob_stall()) {
+		if (!on_pipeline_entry() && test_oob_stall()) {
 			pr_err("IRQ pipeline: out-of-band stage stalled on IRQ entry\n");
 			unstall_oob();
 		}
-- 
2.31.1

Re: [PATCH 0/4] Dovetail fixes (v5.13)

[Florian Bezdeka]

Hi Philippe,

On 31.07.21 11:49, Philippe Gerum via Xenomai wrote:
> From: Philippe Gerum <rpm@xenomai.org>
> 
> The usual pain with synchronizing the virtual and real interrupt
> states. These issues have been detected while porting to v5.14, some
> are reported by CONFIG_DEBUG_LOCKDEP=y.
> 

One of our test boards (Intel XEON D) has an issue with the TSC being
marked unstable because the clocksource watchdog is coming too late.
Could one of these fixes explain that? Something like missed / dropped
interrupts / interrupts not being delivered to Linux?

> Philippe Gerum (4):
>   x86/ioapic: irq_pipeline: unbreak irqflags tracing
>   init: early sync the inband stall with the hardware state
>   x86/fault: dovetail: unbreak irqflags tracing
>   genirq: irq_pipeline: fix inverted check in debug assertion
> 
>  arch/x86/kernel/apic/io_apic.c |  4 ++--
>  arch/x86/mm/fault.c            | 12 ++++++------
>  init/main.c                    |  1 +
>  kernel/irq/pipeline.c          | 10 +++++-----
>  4 files changed, 14 insertions(+), 13 deletions(-)
> 


-- 
Siemens AG, T RDA IOT
Corporate Competence Center Embedded Linux

Re: [PATCH 0/4] Dovetail fixes (v5.13)

[Philippe Gerum]

Hi Florian,

Florian Bezdeka via Xenomai <xenomai@xenomai.org> writes:

> Hi Philippe,
>
> On 31.07.21 11:49, Philippe Gerum via Xenomai wrote:
>> From: Philippe Gerum <rpm@xenomai.org>
>> 
>> The usual pain with synchronizing the virtual and real interrupt
>> states. These issues have been detected while porting to v5.14, some
>> are reported by CONFIG_DEBUG_LOCKDEP=y.
>> 
>
> One of our test boards (Intel XEON D) has an issue with the TSC being
> marked unstable because the clocksource watchdog is coming too late.
> Could one of these fixes explain that? Something like missed / dropped
> interrupts / interrupts not being delivered to Linux?
>

I don't think so, these fixes are not supposed to address this kind of
issue. They are merely aimed at keeping the interrupt state reported by
the IRQ flags tracer in sync with lockdep expectations. This series is
not complete yet, more is to come to fully address this matter and more.

Booting with CONFIG_DEBUG_LOCKDEP enabled, CONFIG_EVL/CONFIG_XENOMAI
disabled (i.e. only keeping the IRQ pipeline on) should reveal the
remaining problems. This also revealed a deeper and nastier issue than
de-synced IRQ flag tracing, particularly on ARM/arm64 where we do depend
on RCU read sides when traversing the interrupt pipeline, an unmet
dependency which is currently papered over as a result of having a
high-priority interrupt stage enabled in the kernel
(e.g. EVL/Xenomai). A fix is under test here.

-- 
Philippe.