Re: IOMMU faults after S3

["Marek Marczykowski-Górecki" <marmarek@invisiblethingslab.com>]

[-- Attachment #1.1: Type: text/plain, Size: 7207 bytes --]

On Thu, Apr 02, 2026 at 12:48:14PM +0200, Jan Beulich wrote:
> On 02.04.2026 11:35, Marek Marczykowski-Górecki wrote:
> > On Thu, Apr 02, 2026 at 10:39:41AM +0200, Jan Beulich wrote:
> >> On 02.04.2026 10:08, Marek Marczykowski-Górecki wrote:
> >>> The xl dmesg output (from MTL this time):
> >>>
> >>>     (XEN) [  123.477511] Entering ACPI S3 state.
> >>>     (XEN) [18446743903.571842] _disable_pit_irq:2649: using_pit: 0, cpu_has_apic: 1
> >>>     (XEN) [18446743903.571856] _disable_pit_irq:2659: cpuidle_using_deep_cstate: 1, boot_cpu_has(X86_FEATURE_XEN_ARAT): 0
> > 
> >> Hmm, but what you didn't log is whether __hpet_setup_msi_irq() actually
> >> succeeded everywhere. (And if it did, also logging HPET_Tn_ROUTE() values
> >> might be a good idea, if only to double check.)
> > 
> > Updated output:
> > 
> >     (XEN) [18446743899.720395] _disable_pit_irq:2649: using_pit: 0, cpu_has_apic: 1
> >     (XEN) [18446743899.720409] _disable_pit_irq:2659: cpuidle_using_deep_cstate: 1, boot_cpu_has(X86_FEATURE_XEN_ARAT): 0
> >     (XEN) [18446743899.720420] _disable_pit_irq:2662: init: 0
> >     (XEN) [18446743899.720431] hpet_broadcast_resume:663: hpet_events: ffff83046bc1f080
> >     (XEN) [18446743899.720579] hpet_broadcast_resume:674: num_hpets_used: 8
> >     (XEN) [18446743899.720587] hpet_broadcast_resume:692: cfg: 0x1
> >     (XEN) [18446743899.720599] hpet_broadcast_resume:697: i:0, hpet_events[i].msi.irq: 122, hpet_events[i].flags: 0
> >     (XEN) [18446743899.720612] hpet_msi_write:283: iommu_intremap: 2 (iommu_intremap_off: 0), HPET_Tn_ROUTE(ch->idx): 0x110
> >     (XEN) [18446743899.720638] hpet_msi_write:287: iommu_update_ire_from_msi rc: 0
> 
> So it succeeds, and the low half of HPET_Tn_ROUTE also looks plausible. The high
> half is, however, the address that the low half value is written to. It's hard
> to imagine that it would be zero when the low half isn't, but it is about the
> last thing I can think of which could explain observed behavior. (Yet then, all
> of this is pretty meaningless; see below.)
> 
> > And the current debug diff attached.
> 
> Hmm, you log HPET_Tn_ROUTE _before_ our update. That's not very useful. You want
> to move that part of logging to the bottom of hpet_msi_write(), or maybe to
> where you also log the per-channel cfg value in hpet_broadcast_resume() (thus
> making the logging overall less verbose).

This test is with the updated patch (attached) + your extra
calculate_host_policy() call and "no-arat" on cmdline:

    (XEN) [18446743900.569705] _disable_pit_irq:2649: using_pit: 0, cpu_has_apic: 1
    (XEN) [18446743900.569720] _disable_pit_irq:2659: cpuidle_using_deep_cstate: 1, boot_cpu_has(X86_FEATURE_XEN_ARAT): 0
    (XEN) [18446743900.569730] _disable_pit_irq:2662: init: 0
    (XEN) [18446743900.569741] hpet_broadcast_resume:662: hpet_events: ffff83046bc1f080
    (XEN) [18446743900.569885] hpet_broadcast_resume:673: num_hpets_used: 8
    (XEN) [18446743900.569893] hpet_broadcast_resume:691: cfg: 0x1
    (XEN) [18446743900.569905] hpet_broadcast_resume:696: i:0, hpet_events[i].msi.irq: 122, hpet_events[i].flags: 0
    (XEN) [18446743900.569935] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.569946] hpet_broadcast_resume:700: i:0, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.569970] hpet_broadcast_resume:710: i:0, cfg: 0xc134, HPET_Tn_ROUTE(hpet_events[i].idx): 0x110
    (XEN) [18446743900.569980] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x110
    (XEN) [18446743900.569989] hpet_broadcast_resume:696: i:1, hpet_events[i].msi.irq: 123, hpet_events[i].flags: 0
    (XEN) [18446743900.570012] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570022] hpet_broadcast_resume:700: i:1, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570040] hpet_broadcast_resume:710: i:1, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x130
    (XEN) [18446743900.570050] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x130
    (XEN) [18446743900.570059] hpet_broadcast_resume:696: i:2, hpet_events[i].msi.irq: 124, hpet_events[i].flags: 0
    (XEN) [18446743900.570082] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570092] hpet_broadcast_resume:700: i:2, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570105] hpet_broadcast_resume:710: i:2, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x150
    (XEN) [18446743900.570114] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x150
    (XEN) [18446743900.570123] hpet_broadcast_resume:696: i:3, hpet_events[i].msi.irq: 125, hpet_events[i].flags: 0
    (XEN) [18446743900.570145] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570155] hpet_broadcast_resume:700: i:3, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570172] hpet_broadcast_resume:710: i:3, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x170
    (XEN) [18446743900.570181] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x170
    (XEN) [18446743900.570191] hpet_broadcast_resume:696: i:4, hpet_events[i].msi.irq: 126, hpet_events[i].flags: 0
    (XEN) [18446743900.570214] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570225] hpet_broadcast_resume:700: i:4, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570242] hpet_broadcast_resume:710: i:4, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x190
    (XEN) [18446743900.570251] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x190
    (XEN) [18446743900.570260] hpet_broadcast_resume:696: i:5, hpet_events[i].msi.irq: 127, hpet_events[i].flags: 0
    (XEN) [18446743900.570282] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570292] hpet_broadcast_resume:700: i:5, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570309] hpet_broadcast_resume:710: i:5, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x1b0
    (XEN) [18446743900.570318] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x1b0
    (XEN) [18446743900.570327] hpet_broadcast_resume:696: i:6, hpet_events[i].msi.irq: 128, hpet_events[i].flags: 0
    (XEN) [18446743900.570351] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570361] hpet_broadcast_resume:700: i:6, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570374] hpet_broadcast_resume:710: i:6, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x1d0
    (XEN) [18446743900.570383] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x1d0
    (XEN) [18446743900.570392] hpet_broadcast_resume:696: i:7, hpet_events[i].msi.irq: 129, hpet_events[i].flags: 0
    (XEN) [18446743900.570415] hpet_msi_write:286: iommu_update_ire_from_msi rc: 0
    (XEN) [18446743900.570425] hpet_broadcast_resume:700: i:7, __hpet_setup_msi_irq ret: 0
    (XEN) [18446743900.570442] hpet_broadcast_resume:710: i:7, cfg: 0xc104, HPET_Tn_ROUTE(hpet_events[i].idx): 0x1f0
    (XEN) [18446743900.570451] hpet_broadcast_resume:713: HPET_Tn_ROUTE(hpet_events[i].idx): 0x1f0


-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

[-- Attachment #1.2: 0001-DEBUG.patch --]
[-- Type: text/plain, Size: 5363 bytes --]

From 34e6a34cf0504233776337ace8ac69a92297984e Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Marek=20Marczykowski-G=C3=B3recki?=
 <marmarek@invisiblethingslab.com>
Date: Thu, 2 Apr 2026 11:09:32 +0200
Subject: [PATCH] DEBUG

---
 xen/arch/x86/cpu-policy.c |  1 +
 xen/arch/x86/cpu/intel.c  |  1 +
 xen/arch/x86/hpet.c       | 17 ++++++++++++++++-
 xen/arch/x86/time.c       |  3 +++
 xen/source                |  1 +
 5 files changed, 22 insertions(+), 1 deletion(-)
 create mode 120000 xen/source

diff --git a/xen/arch/x86/cpu-policy.c b/xen/arch/x86/cpu-policy.c
index 5273fe0ae435..9916afd5ed68 100644
--- a/xen/arch/x86/cpu-policy.c
+++ b/xen/arch/x86/cpu-policy.c
@@ -364,6 +364,7 @@ static void __init calculate_host_policy(void)
     struct cpu_policy *p = &host_cpu_policy;
     unsigned int max_extd_leaf;
 
+    printk("%s:%d\n", __func__, __LINE__);
     *p = raw_cpu_policy;
 
     p->basic.max_leaf =
diff --git a/xen/arch/x86/cpu/intel.c b/xen/arch/x86/cpu/intel.c
index 18b3c79dc97f..51a3d1c4b5f3 100644
--- a/xen/arch/x86/cpu/intel.c
+++ b/xen/arch/x86/cpu/intel.c
@@ -671,6 +671,7 @@ const struct cpu_dev __initconst_cf_clobber intel_cpu_dev = {
 
 void __init intel_init_arat(void)
 {
+    printk("%s:%d: opt_arat: %d, cpu_has_arat: %d\n", __func__, __LINE__, opt_arat, cpu_has_arat);
     if ( opt_arat && cpu_has_arat )
         setup_force_cpu_cap(X86_FEATURE_XEN_ARAT);
 }
diff --git a/xen/arch/x86/hpet.c b/xen/arch/x86/hpet.c
index 1ea8ae457424..cef060cb18bb 100644
--- a/xen/arch/x86/hpet.c
+++ b/xen/arch/x86/hpet.c
@@ -283,6 +283,7 @@ static int hpet_msi_write(struct hpet_event_channel *ch, struct msi_msg *msg)
     if ( iommu_intremap != iommu_intremap_off )
     {
         int rc = iommu_update_ire_from_msi(&ch->msi, msg);
+        printk("%s:%d: iommu_update_ire_from_msi rc: %d\n", __func__, __LINE__, rc);
 
         if ( rc < 0 )
             return rc;
@@ -658,6 +659,8 @@ void hpet_broadcast_resume(void)
     u32 cfg;
     unsigned int i, n;
 
+    printk("%s:%d: hpet_events: %p\n", __func__, __LINE__, hpet_events);
+
     if ( !hpet_events )
         return;
 
@@ -667,25 +670,35 @@ void hpet_broadcast_resume(void)
 
     if ( num_hpets_used > 0 )
     {
+        printk("%s:%d: num_hpets_used: %d\n", __func__, __LINE__, num_hpets_used);
         /* Stop HPET legacy interrupts */
         cfg &= ~HPET_CFG_LEGACY;
         n = num_hpets_used;
     }
     else if ( hpet_events->flags & HPET_EVT_DISABLE )
+    {
+        printk("%s:%d: hpet_events->flags: %#x\n", __func__, __LINE__, hpet_events->flags);
         return;
+    }
     else
     {
         /* Start HPET legacy interrupts */
+        printk("%s:%d\n", __func__, __LINE__);
         cfg |= HPET_CFG_LEGACY;
         n = 1;
     }
 
+    printk("%s:%d: cfg: %#x\n", __func__, __LINE__, cfg);
     hpet_write32(cfg, HPET_CFG);
 
     for ( i = 0; i < n; i++ )
     {
+        printk("%s:%d: i:%d, hpet_events[i].msi.irq: %d, hpet_events[i].flags: %#x\n", __func__, __LINE__, i, hpet_events[i].msi.irq, hpet_events[i].flags);
         if ( hpet_events[i].msi.irq >= 0 )
-            __hpet_setup_msi_irq(irq_to_desc(hpet_events[i].msi.irq));
+        {
+            int ret = __hpet_setup_msi_irq(irq_to_desc(hpet_events[i].msi.irq));
+            printk("%s:%d: i:%d, __hpet_setup_msi_irq ret: %d\n", __func__, __LINE__, i, ret);
+        }
 
         /* set HPET Tn as oneshot */
         cfg = hpet_read32(HPET_Tn_CFG(hpet_events[i].idx));
@@ -694,8 +707,10 @@ void hpet_broadcast_resume(void)
         if ( !(hpet_events[i].flags & HPET_EVT_LEGACY) )
             cfg |= HPET_TN_FSB;
         hpet_write32(cfg, HPET_Tn_CFG(hpet_events[i].idx));
+        printk("%s:%d: i:%d, cfg: %#x, HPET_Tn_ROUTE(hpet_events[i].idx): %#x\n", __func__, __LINE__, i, cfg, HPET_Tn_ROUTE(hpet_events[i].idx));
 
         hpet_events[i].next_event = STIME_MAX;
+        printk("%s:%d: HPET_Tn_ROUTE(hpet_events[i].idx): %#x\n", __func__, __LINE__, HPET_Tn_ROUTE(hpet_events[i].idx));
     }
 }
 
diff --git a/xen/arch/x86/time.c b/xen/arch/x86/time.c
index fed30a919d2c..15113ebdfb6c 100644
--- a/xen/arch/x86/time.c
+++ b/xen/arch/x86/time.c
@@ -2646,6 +2646,7 @@ static int _disable_pit_irq(bool init)
 {
     int ret = 1;
 
+    printk("%s:%d: using_pit: %d, cpu_has_apic: %d\n", __func__, __LINE__, using_pit, cpu_has_apic);
     if ( using_pit || !cpu_has_apic )
         return -1;
 
@@ -2655,8 +2656,10 @@ static int _disable_pit_irq(bool init)
      * XXX dom0 may rely on RTC interrupt delivery, so only enable
      * hpet_broadcast if FSB mode available or if force_hpet_broadcast.
      */
+    printk("%s:%d: cpuidle_using_deep_cstate: %d, boot_cpu_has(X86_FEATURE_XEN_ARAT): %d\n", __func__, __LINE__, cpuidle_using_deep_cstate(), boot_cpu_has(X86_FEATURE_XEN_ARAT));
     if ( cpuidle_using_deep_cstate() && !boot_cpu_has(X86_FEATURE_XEN_ARAT) )
     {
+        printk("%s:%d: init: %d\n", __func__, __LINE__, init);
         init ? hpet_broadcast_init() : hpet_broadcast_resume();
         if ( !hpet_broadcast_is_available() )
         {
diff --git a/xen/source b/xen/source
new file mode 120000
index 000000000000..945c9b46d684
--- /dev/null
+++ b/xen/source
@@ -0,0 +1 @@
+.
\ No newline at end of file
-- 
2.53.0


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]