[Xenomai] Interpreting I-pipe trace

[Xenomai] Interpreting I-pipe trace

[Doug Brunner]

While running my latency testing earlier I saw some rather high 
worst-case latencies (~70us) compared to average case (~14us), so I ran 
again with I-pipe tracing enabled. However, I'm not sure what to make of 
the results.

My worst case involves an IRQ (common_interrupt appears in the trace 
with user value 0xFFFFFFC4) and the wiki page talks about being able to 
translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on 
how this correspondence works. I'm not horribly concerned since it's a 
delay of 53 us on a rather slow processor (Geode LX800) but it would be 
nice to know what interrupt is taking so long.

The trace is attached.

Thanks,

-- 
     Doug Brunner

-------------- next part --------------
I-pipe frozen back-tracing service on 3.2.21rtipc-ipipe-small-5-ipd/ipipe release #1
------------------------------------------------------------
CPU: 0, Freeze: 684744353683 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.446 us

 +----- Hard IRQs ('|': locked)
 |+-- Xenomai
 ||+- Linux ('*': domain stalled, '+': current, '#': current+stalled)
 |||                          +---------- Delay flag ('+': > 1 us, '!': > 10 us)
 |||                          |        +- NMI noise ('N')
 |||                          |        |
      Type    User Val.   Time    Delay  Function (Parent)
:|  + begin   0x80000001  -138+   1.922  __ipipe_syscall_root+0x95 (sysenter_past_esp+0x55)
:   + func                -136    0.706  __ipipe_syscall_root+0x9 (sysenter_past_esp+0x55)
:   + func                -135    0.612  __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
:|  + begin   0x80000001  -135    0.526  __ipipe_notify_syscall+0x127 (__ipipe_syscall_root+0x2e)
:|  + end     0x80000001  -134    0.702  __ipipe_notify_syscall+0xc9 (__ipipe_syscall_root+0x2e)
:   + func                -134    0.698  ipipe_syscall_hook+0x4 (__ipipe_notify_syscall+0x49)
:   + func                -133    0.914  hisyscall_event+0x9 (ipipe_syscall_hook+0x24)
:   + func                -132    0.520  __rt_task_wait_period+0x8 (hisyscall_event+0x16a)
:   + func                -132    0.634  rt_task_wait_period+0x3 (__rt_task_wait_period+0x17)
:   + func                -131    0.594  xnpod_wait_thread_period+0x8 (rt_task_wait_period+0x37)
:|  + begin   0x80000000  -130    0.902  xnpod_wait_thread_period+0xec (rt_task_wait_period+0x37)
:|  # func                -129    0.732  xnpod_suspend_thread+0x9 (xnpod_wait_thread_period+0x86)
:|  # func                -129    0.676  __xnpod_schedule+0x9 (xnpod_suspend_thread+0x22e)
:|  # [ 1588] samplin 99  -128    0.628  __xnpod_schedule+0x6b (xnpod_suspend_thread+0x22e)
:|  # func                -127+   1.534  xnsched_pick_next+0x6 (__xnpod_schedule+0xcc)
:|  # [    0] -<?>-   -1  -126    0.872  __xnpod_schedule+0x356 (xnintr_clock_handler+0xeb)
:|   +func                -125    0.744  __ipipe_do_sync_pipeline+0x4 (__ipipe_dispatch_irq_fast+0x79)
:|   +end     0xffffffcf  -124    0.870  common_interrupt+0x40 (__ipipe_halt_root+0x2d)
:    +func                -123    0.582  local_touch_nmi+0x3 (cpu_idle+0x35)
:    #func                -123    0.608  cpuidle_idle_call+0x9 (cpu_idle+0x42)
:    #func                -122    0.692  cpuidle_get_driver+0x3 (cpuidle_idle_call+0x19)
:    #func                -121    0.642  default_idle+0x8 (cpu_idle+0x4c)
:    #func                -121    0.562  __ipipe_halt_root+0x3 (default_idle+0x55)
:|   #begin   0x80000000  -120    0.738  __ipipe_halt_root+0x3a (default_idle+0x55)
:|   +end     0x8000000e  -120!  53.132  __ipipe_halt_root+0x2b (default_idle+0x55)
:|   +begin   0xffffffcf   -66    0.838  common_interrupt+0x2f (__ipipe_halt_root+0x2d)
:|   +func                 -66    0.574  __ipipe_handle_irq+0x5 (common_interrupt+0x36)
:|   +func                 -65    0.486  __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0x31)
:|   +func                 -64    0.622  irq_to_desc+0x3 (__ipipe_dispatch_irq+0x10d)
:|   +func                 -64    0.662  irq_to_desc+0x3 (__ipipe_dispatch_irq+0x118)
:|   +func                 -63    0.518  __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0x56)
:|   +func                 -63    0.508  __ipipe_ack_level_irq+0x7 (__ipipe_ack_hrtimer_irq+0x1c)
:|   +func                 -62    0.494  mask_and_ack_8259A+0x8 (__ipipe_ack_level_irq+0x1d)
:|   +func                 -62+   1.828  __ipipe_spin_lock_irqsave+0x6 (mask_and_ack_8259A+0x23)
:|   #func                 -60    0.734  __ipipe_spin_unlock_irqrestore+0x6 (mask_and_ack_8259A+0xcf)
:|   +func                 -59    0.490  __ipipe_end_level_irq+0x3 (__ipipe_ack_hrtimer_irq+0x30)
:|   +func                 -59    0.494  enable_8259A_irq+0x3 (__ipipe_end_level_irq+0x10)
:|   +func                 -58    0.496  unmask_8259A_irq+0x7 (enable_8259A_irq+0xf)
:|   +func                 -58    0.554  __ipipe_spin_lock_irqsave+0x6 (unmask_8259A_irq+0x22)
:|   #func                 -57    0.716  __ipipe_spin_unlock_irqrestore+0x6 (unmask_8259A_irq+0x63)
:|   +func                 -56    0.686  irq_to_desc+0x3 (__ipipe_dispatch_irq+0x61)
:|   +func                 -56    0.542  __ipipe_dispatch_irq_fast+0x9 (__ipipe_dispatch_irq+0xa0)
:|  # func                 -55    0.794  xnintr_clock_handler+0x4 (__ipipe_dispatch_irq_fast+0x5f)
:|  # func                 -54    0.880  xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x61)
:|  # func                 -53    0.632  xnthread_periodic_handler+0x3 (xntimer_tick_aperiodic+0x21e)
:|  # func                 -53    0.654  xnpod_resume_thread+0x9 (xnthread_periodic_handler+0x22)
:|  # [ 1588] samplin 99   -52+   1.132  xnpod_resume_thread+0x4f (xnthread_periodic_handler+0x22)
:|  # func                 -51    0.622  xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x63)
:|  # event   tick@-44     -50    0.732  xntimer_next_local_shot+0x7d (xntimer_tick_aperiodic+0x63)
:|  # func                 -50    0.664  ipipe_timer_set+0x4 (xntimer_next_local_shot+0xb2)
:|  # func                 -49+   3.302  pit_next_event+0x3 (ipipe_timer_set+0x1a)
:|  # func                 -46    0.584  __xnpod_schedule+0x9 (xnintr_clock_handler+0xeb)
:|  # [    0] -<?>-   -1   -45    0.638  __xnpod_schedule+0x6b (xnintr_clock_handler+0xeb)
:|  # func                 -45+   1.826  xnsched_pick_next+0x6 (__xnpod_schedule+0xcc)
:|  # [ 1588] samplin 99   -43+   1.028  __xnpod_schedule+0x356 (xnpod_suspend_thread+0x22e)
:|  # func                 -42    0.670  xntimer_get_overruns+0x9 (xnpod_wait_thread_period+0xac)
:|  # func                 -41    0.604  __ipipe_restore_head+0x6 (xnpod_wait_thread_period+0xd8)
:|  + end     0x80000000   -40    0.980  __ipipe_restore_head+0x4b (xnpod_wait_thread_period+0xd8)
:|  + begin   0x80000001   -39    0.932  __ipipe_notify_syscall+0xdc (__ipipe_syscall_root+0x2e)
:|  + end     0x80000001   -38+   2.364  __ipipe_notify_syscall+0xf8 (__ipipe_syscall_root+0x2e)
:|  + begin   0xffffffcf   -36    0.784  common_interrupt+0x2f (__ipipe_notify_syscall+0xff)
:|  + func                 -35    0.688  __ipipe_handle_irq+0x5 (common_interrupt+0x36)
:|  + func                 -35    0.600  __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0x31)
:|  + func                 -34    0.638  irq_to_desc+0x3 (__ipipe_dispatch_irq+0x10d)
:|  + func                 -33    0.764  irq_to_desc+0x3 (__ipipe_dispatch_irq+0x118)
:|  + func                 -33    0.634  __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0x56)
:|  + func                 -32    0.616  __ipipe_ack_level_irq+0x7 (__ipipe_ack_hrtimer_irq+0x1c)
:|  + func                 -31    0.516  mask_and_ack_8259A+0x8 (__ipipe_ack_level_irq+0x1d)
:|  + func                 -31+   1.944  __ipipe_spin_lock_irqsave+0x6 (mask_and_ack_8259A+0x23)
:|  # func                 -29    0.774  __ipipe_spin_unlock_irqrestore+0x6 (mask_and_ack_8259A+0xcf)
:|  + func                 -28    0.626  __ipipe_end_level_irq+0x3 (__ipipe_ack_hrtimer_irq+0x30)
:|  + func                 -28    0.510  enable_8259A_irq+0x3 (__ipipe_end_level_irq+0x10)
:|  + func                 -27    0.596  unmask_8259A_irq+0x7 (enable_8259A_irq+0xf)
:|  + func                 -26    0.658  __ipipe_spin_lock_irqsave+0x6 (unmask_8259A_irq+0x22)
:|  # func                 -26    0.754  __ipipe_spin_unlock_irqrestore+0x6 (unmask_8259A_irq+0x63)
:|  + func                 -25    0.700  irq_to_desc+0x3 (__ipipe_dispatch_irq+0x61)
:|  + func                 -24    0.646  __ipipe_dispatch_irq_fast+0x9 (__ipipe_dispatch_irq+0xa0)
:|  # func                 -24    0.802  xnintr_clock_handler+0x4 (__ipipe_dispatch_irq_fast+0x5f)
:|  # func                 -23+   1.130  xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x61)
:|  # func                 -22+   1.102  xnsched_watchdog_handler+0x7 (xntimer_tick_aperiodic+0x21e)
:|  # func                 -21    0.718  xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x63)
:|  # event   tick@24      -20    0.746  xntimer_next_local_shot+0x7d (xntimer_tick_aperiodic+0x63)
:|  # func                 -19    0.658  ipipe_timer_set+0x4 (xntimer_next_local_shot+0xb2)
:|  # func                 -18+   3.530  pit_next_event+0x3 (ipipe_timer_set+0x1a)
:|  + end     0xffffffcf   -15    0.872  common_interrupt+0x40 (__ipipe_notify_syscall+0xff)
:|  + begin   0x80000001   -14+   3.120  __ipipe_syscall_root+0x95 (sysenter_past_esp+0x55)
:   + func                 -11    0.736  __ipipe_syscall_root+0x9 (sysenter_past_esp+0x55)
:   + func                 -10    0.498  __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
:|  + begin   0x80000001   -10    0.618  __ipipe_notify_syscall+0x127 (__ipipe_syscall_root+0x2e)
:|  + end     0x80000001    -9    0.706  __ipipe_notify_syscall+0xc9 (__ipipe_syscall_root+0x2e)
:   + func                  -8    0.748  ipipe_syscall_hook+0x4 (__ipipe_notify_syscall+0x49)
:   + func                  -8+   1.210  hisyscall_event+0x9 (ipipe_syscall_hook+0x24)
:   + func                  -6+   1.296  xnshadow_sys_trace+0x6 (hisyscall_event+0x16a)
:   + func                  -5    0.706  ipipe_trace_frozen_reset+0x4 (xnshadow_sys_trace+0xcb)
:   + func                  -4    0.614  __ipipe_global_path_lock+0x7 (ipipe_trace_frozen_reset+0xe)
:   + func                  -4    0.512  __ipipe_spin_lock_irqsave+0x6 (__ipipe_global_path_lock+0x16)
:|  + begin   0x80000001    -3+   2.214  __ipipe_spin_lock_irqsave+0x47 (__ipipe_global_path_lock+0x16)
:|  # func                  -1    0.698  __ipipe_spin_unlock_irqcomplete+0x6 (__ipipe_global_path_unlock+0x61)
:|  + end     0x80000001     0    0.920  __ipipe_spin_unlock_irqcomplete+0x36 (__ipipe_global_path_unlock+0x61)
<   + freeze  0x0000d5ef     0    0.812  xnshadow_sys_trace+0xbf (hisyscall_event+0x16a)
 |  + begin   0x80000001     0    0.738  __ipipe_notify_syscall+0xdc (__ipipe_syscall_root+0x2e)
 |  + end     0x80000001     1    0.702  __ipipe_notify_syscall+0xf8 (__ipipe_syscall_root+0x2e)
 |  + begin   0x80000001     2    1.514  __ipipe_syscall_root+0x95 (sysenter_past_esp+0x55)
    + func                   3    0.638  __ipipe_syscall_root+0x9 (sysenter_past_esp+0x55)
    + func                   4    0.512  __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
 |  + begin   0x80000001     4    0.658  __ipipe_notify_syscall+0x127 (__ipipe_syscall_root+0x2e)
 |  + end     0x80000001     5    0.686  __ipipe_notify_syscall+0xc9 (__ipipe_syscall_root+0x2e)
    + func                   6    0.580  ipipe_syscall_hook+0x4 (__ipipe_notify_syscall+0x49)
    + func                   6    0.902  hisyscall_event+0x9 (ipipe_syscall_hook+0x24)
    + func                   7    0.000  __rt_task_wait_period+0x8 (hisyscall_event+0x16a)

Re: [Xenomai] Interpreting I-pipe trace

[Gilles Chanteperdrix]

On 09/11/2012 07:01 AM, Doug Brunner wrote:

> While running my latency testing earlier I saw some rather high 
> worst-case latencies (~70us) compared to average case (~14us), so I ran 
> again with I-pipe tracing enabled. However, I'm not sure what to make of 
> the results.
> 
> My worst case involves an IRQ (common_interrupt appears in the trace 
> with user value 0xFFFFFFC4) and the wiki page talks about being able to 
> translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on 
> how this correspondence works. I'm not horribly concerned since it's a 
> delay of 53 us on a rather slow processor (Geode LX800) but it would be 
> nice to know what interrupt is taking so long.
> 
> The trace is attached.


Have you tried booting with "idle=poll" ?

-- 
                                                                Gilles.

Re: [Xenomai] Interpreting I-pipe trace

[Philippe Gerum]

On 09/11/2012 07:01 AM, Doug Brunner wrote:
> While running my latency testing earlier I saw some rather high
> worst-case latencies (~70us) compared to average case (~14us), so I ran
> again with I-pipe tracing enabled. However, I'm not sure what to make of
> the results.
> 
> My worst case involves an IRQ (common_interrupt appears in the trace
> with user value 0xFFFFFFC4) and the wiki page talks about being able to
> translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on
> how this correspondence works.

The kernel pushes ~irq_num on top of the interrupt stack.

 I'm not horribly concerned since it's a
> delay of 53 us on a rather slow processor (Geode LX800) but it would be
> nice to know what interrupt is taking so long.
> 

Looks like a very slow wakeup from idle state.

> The trace is attached.
> 
> Thanks,
> 


-- 
Philippe.

Re: [Xenomai] Interpreting I-pipe trace

[Gilles Chanteperdrix]

On 09/11/2012 07:01 AM, Doug Brunner wrote:

> While running my latency testing earlier I saw some rather high 
> worst-case latencies (~70us) compared to average case (~14us), so I ran 
> again with I-pipe tracing enabled. However, I'm not sure what to make of 
> the results.
> 
> My worst case involves an IRQ (common_interrupt appears in the trace 
> with user value 0xFFFFFFC4) and the wiki page talks about being able to 
> translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on 
> how this correspondence works. I'm not horribly concerned since it's a 
> delay of 53 us on a rather slow processor (Geode LX800) but it would be 
> nice to know what interrupt is taking so long.


You may also want to apply the following patch for SMI on Geode LX, and 
enable CONFIG_XENO_HW_SMI_WORKAROUND. You can remove the '#if 0', if you
do not use PCI.

diff --git a/ksrc/arch/x86/smi.c b/ksrc/arch/x86/smi.c
index d80b14b..6d641be 100644
--- a/ksrc/arch/x86/smi.c
+++ b/ksrc/arch/x86/smi.c
@@ -31,6 +31,7 @@
 #include <linux/reboot.h>
 #include <asm-generic/xenomai/pci_ids.h>
 #include <asm/xenomai/hal.h>
+#include <asm/geode.h>
 
 static struct pci_device_id rthal_smi_pci_tbl[] = {
 	{PCI_DEVICE(PCI_VENDOR_ID_INTEL, PCI_DEVICE_ID_INTEL_82801AA_0)},
@@ -192,6 +193,35 @@ void rthal_smi_init(void)
 	struct pci_dev *dev = NULL;
 	struct pci_device_id *id;
 
+#ifdef CONFIG_XENO_HW_SMI_WORKAROUND
+	if (is_geode_lx()) {
+		unsigned long long val;
+#define SMM_CTRL_MSR 0x00001301
+
+/* Do not clear 0x10, that is SMI_IO */
+#define SMM_CTRL_MSR_CLR 0x0000000000000020ULL
+#define GLIU0_MSR_SMI 0x10002002
+#define GLIU1_MSR_SMI 0x40002002
+#define GLIU0_ASMI 0x10000083
+#define GLIU1_ASMI 0x40000083
+#define CS5536_MSR_SMI 0x4c002002
+#define CS5536_PCI_MSR_SMI 0x50002002
+
+		printk("Geode LX found, trying SMI workaround\n");
+		rdmsrl(SMM_CTRL_MSR, val);
+		wrmsrl(SMM_CTRL_MSR, val & ~SMM_CTRL_MSR_CLR);
+		wrmsrl(GLIU0_MSR_SMI, 0x0000001800000018ULL);
+		wrmsrl(GLIU1_MSR_SMI, 0x0000001800000018ULL);
+		wrmsrl(GLIU0_ASMI, 0x000000000000ffffULL);
+		wrmsrl(GLIU1_ASMI, 0x000000000000ffffULL);
+		wrmsrl(CS5536_MSR_SMI, 0x00000000001f001fULL);
+#if 0
+	       /* PCI SMI are needed to get PCI running. */
+		wrmsrl(CS5536_PCI_MSR_SMI, 0x00000000003f003fULL);
+#endif
+	}
+#endif
+
 	/*
 	 * Do not use pci_register_driver, pci_enable_device, ...
 	 * Just register the used ports.


-- 
                                                                Gilles.

Re: [Xenomai] Interpreting I-pipe trace

[Gilles Chanteperdrix]

On 09/11/2012 09:21 PM, Gilles Chanteperdrix wrote:

> On 09/11/2012 07:01 AM, Doug Brunner wrote:
> 
>> While running my latency testing earlier I saw some rather high 
>> worst-case latencies (~70us) compared to average case (~14us), so I ran 
>> again with I-pipe tracing enabled. However, I'm not sure what to make of 
>> the results.
>>
>> My worst case involves an IRQ (common_interrupt appears in the trace 
>> with user value 0xFFFFFFC4) and the wiki page talks about being able to 
>> translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on 
>> how this correspondence works. I'm not horribly concerned since it's a 
>> delay of 53 us on a rather slow processor (Geode LX800) but it would be 
>> nice to know what interrupt is taking so long.
> 
> 
> You may also want to apply the following patch for SMI on Geode LX, and 
> enable CONFIG_XENO_HW_SMI_WORKAROUND. You can remove the '#if 0', if you
> do not use PCI.


You have to pass cs5536.msr=1 to avoid using PCI registers access (which
use SMIs) in the IDE driver.

-- 
                                                                Gilles.

Re: [Xenomai] Interpreting I-pipe trace

[Gilles Chanteperdrix]

On 09/11/2012 11:19 PM, Gilles Chanteperdrix wrote:

> On 09/11/2012 09:21 PM, Gilles Chanteperdrix wrote:
> 
>> On 09/11/2012 07:01 AM, Doug Brunner wrote:
>>
>>> While running my latency testing earlier I saw some rather high 
>>> worst-case latencies (~70us) compared to average case (~14us), so I ran 
>>> again with I-pipe tracing enabled. However, I'm not sure what to make of 
>>> the results.
>>>
>>> My worst case involves an IRQ (common_interrupt appears in the trace 
>>> with user value 0xFFFFFFC4) and the wiki page talks about being able to 
>>> translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on 
>>> how this correspondence works. I'm not horribly concerned since it's a 
>>> delay of 53 us on a rather slow processor (Geode LX800) but it would be 
>>> nice to know what interrupt is taking so long.
>>
>>
>> You may also want to apply the following patch for SMI on Geode LX, and 
>> enable CONFIG_XENO_HW_SMI_WORKAROUND. You can remove the '#if 0', if you
>> do not use PCI.
> 
> 
> You have to pass cs5536.msr=1 to avoid using PCI registers access (which
> use SMIs) in the IDE driver.
> 


These two tricks seem to make a big difference here:
http://sisyphus.hd.free.fr/~gilles/core-3.4-latencies/geode.png

-- 
                                                                Gilles.

Re: [Xenomai] Interpreting I-pipe trace

[Gilles Chanteperdrix]

On 09/17/2012 01:58 AM, Doug Brunner wrote:

> On 09/11/2012 02:19 PM, Gilles Chanteperdrix wrote:
>> On 09/11/2012 09:21 PM, Gilles Chanteperdrix wrote:
>>
>>> On 09/11/2012 07:01 AM, Doug Brunner wrote:
>>>
>>>> While running my latency testing earlier I saw some rather high
>>>> worst-case latencies (~70us) compared to average case (~14us), so I ran
>>>> again with I-pipe tracing enabled. However, I'm not sure what to make of
>>>> the results.
>>>>
>>>> My worst case involves an IRQ (common_interrupt appears in the trace
>>>> with user value 0xFFFFFFC4) and the wiki page talks about being able to
>>>> translate the user value 0xFFFFFFF4 into IRQ 11 but doesn't elaborate on
>>>> how this correspondence works. I'm not horribly concerned since it's a
>>>> delay of 53 us on a rather slow processor (Geode LX800) but it would be
>>>> nice to know what interrupt is taking so long.
>>>
>>> You may also want to apply the following patch for SMI on Geode LX, and
>>> enable CONFIG_XENO_HW_SMI_WORKAROUND. You can remove the '#if 0', if you
>>> do not use PCI.
>>
>> You have to pass cs5536.msr=1 to avoid using PCI registers access (which
>> use SMIs) in the IDE driver.
>>
> It doesn't appear like this patch, or using idle=poll, has any effect. I 
> tried making latency histograms with and without and they were almost 
> identical. Interestingly I don't see any output from the printk in the 
> patch, even though I have earlyprintk set up to run over my serial 
> console hookup. This persisted even when I took out the is_geode_lx() 
> check. This suggests to me that rthal_smi_init is not getting called.


Actually, after some more test, the only thing that made the difference
for me was booting with "cs5536.msr=1", as it causes the cs5536 driver
to use msrs instead of pci config register accesses and pci config
register accesses are emulated with SMIs. When doing, that there does
not seem to be any SMI on my geode, so masking the SMIs is in fact useless.

To shut other SMI off, you may try to add:
                wrmsrl(0x51000002, 0);
+               wrmsrl(0x51010002, 0);
+               wrmsrl(0x51200002, 0);
+               wrmsrl(0x51300002, 0);
+               wrmsrl(0x51400002, 0);
+               wrmsrl(0x51500002, 0);
+               wrmsrl(0x51700002, 0);

The tsc in my case is correctly configured, but if it is not correctly
configured by your bios, you can check its registers. This is all
documented in the Geode datasheet. You have to configure it so that it
does not stop when the idle task calls. You should also configure the
geode so that the geode doe not automatically go into a low power mode
when the "hlt" instruction is called (but if you boot with idle=poll,
"hlt" should never be called anyway).

In any case, the trace you posted is way to short, to actually debug a
high latencies, the trace should capture at least the timer
programmation before the tick which triggers the trace, so that you can
see what happened between the time the timer was supposed to tick and
the time when it really ticked. When you have done that, please post the
trace here, and we will try and continue the debugging.

>

> I do have CONFIG_XENO_HW_SMI_ALL set, which now that I think about it 
> seems like it should already give me the benefit of the patch. However I 
> don't see how it would stop rthal_smi_init from getting called.


This suggests a configuration issue, such as
CONFIG_XENO_HW_SMI_WORKAROUND missing. Nothing magical here.
rthal_smi_init IS called during Xenomai startup if
CONFIG_XENO_HW_SMI_WORKAROUND is enabled.

> For the benefit of my curiosity, could you explain how 0xFFFFFFC4 
> translates into a PCI related SMI?


Well, in the trace you posted, I do not see 0xFFFFFFC4, but in that case
0xFFFFFFC4 is ~0x3b, so, it corresponds to vector 3b. Now, what is
vector 3b probably depends on your setup, and probably has nothing to do
with PCI related SMI.

In any case, an SMI does not go through "common_interrupt", and SMI
jumps directly to, and is handled in BIOS code. So, it is invisible in
the I-pipe trace, except for a large hole in the time line.

-- 
                                                                Gilles.