On Saturday, 4 September, 2010 9:51am, "Philippe Gerum" <rpm@xenomai.org> said:
> On Fri, 2010-09-03 at 17:30 +0100,
> edward.robbins@domain.hid wrote:
> > Today I have tried using the intel video driver with the option "NoAccel",
> and that seems to stop the high latencies; with this option I can kill X, restart
> it, and run glxgears without issues, all while compiling the linux kernel and
> having xeno-test or latency running. The highest latency I have gotten so far is
> 18uS.
> >
> > However, if anyone is interested I have made a trace without the NoAccel
> option, when the latency jumped to 1113uS upon starting X, attached.
> >
>
> Please try this patch. Your trace log reveals that we are only virtually
> masking interrupts while flushing the TLB, which is quite wrong.
>
Hi Phillipe,
I have tried the patch, and the only noticeable difference is that now when I have the NoAccel option set I am getting high latencies when I make actions such as killing the X server. Below is the ipipe trace. I presume this is going to be a problem even if I am not running X?
Thanks again,
Edward
I-pipe frozen back-tracing service on 2.6.32.15-xenomai-2.5.4/ipipe-2.7-01
------------------------------------------------------------
CPU: 0, Freeze: 4761785881144 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.131 us
+----- Hard IRQs ('|': locked)
|+---- <unused>
||+--- <unused>
|||+-- Xenomai
||||+- Linux ('*': domain stalled, '+': current, '#': current+stalled)
||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
||||| | +- NMI noise ('N')
||||| | |
Type User Val. Time Delay Function (Parent)
:| # func -2144 0.326 __phys_addr+0x4 (__xnpod_schedule+0x562)
:| # func -2143 0.390 __switch_to_xtra+0x8 (__switch_to+0x255)
:| # [ 3276] Xorg -1 -2143 0.427 __xnpod_schedule+0x834 (xnintr_clock_handler+0x130)
:| +func -2143 0.408 __ipipe_walk_pipeline+0x11 (__ipipe_dispatch_wired_nocheck+0x1da)
:| +end 0x000000f6 -2142 0.416 common_interrupt+0x39 (debug_smp_processor_id+0x97)
:| +begin 0x80000001 -2142 0.240 debug_smp_processor_id+0x44 (smp_call_function_single+0x122)
:| +end 0x80000001 -2141 0.262 debug_smp_processor_id+0x94 (smp_call_function_single+0x122)
: +func -2141 0.221 generic_exec_single+0x11 (smp_call_function_single+0x160)
: +func -2141 0.195 _spin_lock_irqsave+0x7 (generic_exec_single+0x3d)
: +func -2141 0.195 ipipe_check_context+0x11 (_spin_lock_irqsave+0x1b)
:| +begin 0x80000001 -2141 0.262 ipipe_check_context+0x33 (_spin_lock_irqsave+0x1b)
:| +end 0x80000001 -2140 0.244 ipipe_check_context+0xda (_spin_lock_irqsave+0x1b)
: #func -2140 0.206 add_preempt_count+0x9 (_spin_lock_irqsave+0x4c)
: #func -2140 0.202 ipipe_check_context+0x11 (add_preempt_count+0x1c)
:| #begin 0x80000001 -2140 0.259 ipipe_check_context+0x33 (add_preempt_count+0x1c)
:| #end 0x80000001 -2139 0.251 ipipe_check_context+0xda (add_preempt_count+0x1c)
: #func -2139 0.195 _spin_unlock_irqrestore+0x4 (generic_exec_single+0x5d)
: #func -2139 0.191 __ipipe_restore_root+0xb (_spin_unlock_irqrestore+0x21)
:| #begin 0x80000001 -2139 0.236 __ipipe_restore_root+0x2d (_spin_unlock_irqrestore+0x21)
:| #end 0x80000001 -2139 0.236 __ipipe_restore_root+0x7d (_spin_unlock_irqrestore+0x21)
: #func -2138 0.191 __ipipe_unstall_root+0x9 (__ipipe_restore_root+0xb1)
:| #begin 0x80000000 -2138 0.266 __ipipe_unstall_root+0x20 (__ipipe_restore_root+0xb1)
:| +end 0x80000000 -2138 0.213 __ipipe_unstall_root+0xce (__ipipe_restore_root+0xb1)
: +func -2138 0.206 sub_preempt_count+0x9 (_spin_unlock_irqrestore+0x2b)
: +func -2137 0.206 ipipe_check_context+0x11 (sub_preempt_count+0x1c)
:| +begin 0x80000001 -2137 0.259 ipipe_check_context+0x33 (sub_preempt_count+0x1c)
:| +end 0x80000001 -2137 0.255 ipipe_check_context+0xda (sub_preempt_count+0x1c)
: +func -2137 0.221 native_send_call_func_single_ipi+0x4 (generic_exec_single+0x6b)
: +func -2136 0.199 flat_send_IPI_mask+0x11 (native_send_call_func_single_ipi+0x34)
:| +begin 0x80000001 -2136 0.247 flat_send_IPI_mask+0x36 (native_send_call_func_single_ipi+0x34)
:| +end 0x80000001 -2136 0.228 flat_send_IPI_mask+0x8e (native_send_call_func_single_ipi+0x34)
: +func -2136 0.206 sub_preempt_count+0x9 (smp_call_function_single+0x173)
: +func -2136 0.191 ipipe_check_context+0x11 (sub_preempt_count+0x1c)
:| +begin 0x80000001 -2135 0.244 ipipe_check_context+0x33 (sub_preempt_count+0x1c)
:| +end 0x80000001 -2135 0.262 ipipe_check_context+0xda (sub_preempt_count+0x1c)
: +func -2135 0.191 sub_preempt_count+0x9 (smp_call_function+0x47)
: +func -2135 0.187 ipipe_check_context+0x11 (sub_preempt_count+0x1c)
:| +begin 0x80000001 -2135 0.244 ipipe_check_context+0x33 (sub_preempt_count+0x1c)
:| +end 0x80000001 -2134 0.232 ipipe_check_context+0xda (sub_preempt_count+0x1c)
: +func -2134 0.187 ipipe_check_context+0x11 (set_mtrr+0x77)
:| +begin 0x80000001 -2134 0.251 ipipe_check_context+0x33 (set_mtrr+0x77)
:| +end 0x80000001 -2134! 10.477 ipipe_check_context+0xda (set_mtrr+0x77)
: #func -2123 0.206 generic_set_mtrr+0x11 (set_mtrr+0xdc)
: #func -2123 0.202 ipipe_check_context+0x11 (generic_set_mtrr+0x42)
:| #begin 0x80000001 -2123 0.262 ipipe_check_context+0x33 (generic_set_mtrr+0x42)
:| #end 0x80000001 -2122 0.259 ipipe_check_context+0xda (generic_set_mtrr+0x42)
:| #begin 0x80000001 -2122 0.221 generic_set_mtrr+0x85 (set_mtrr+0xdc)
:| #func -2122 0.199 prepare_set+0x4 (generic_set_mtrr+0x8a)
:| #func -2122 0.213 _spin_lock+0x9 (prepare_set+0x15)
:| #func -2122 0.191 add_preempt_count+0x9 (_spin_lock+0x1b)
:| #func -2121! 1840.932 ipipe_check_context+0x11 (add_preempt_count+0x1c)
:| #func -280! 55.546 mtrr_wrmsr+0xd (prepare_set+0x79)
:| #func -225! 53.303 mtrr_wrmsr+0xd (generic_set_mtrr+0x111)
:| #func -172! 52.380 mtrr_wrmsr+0xd (generic_set_mtrr+0x129)
:| #func -119! 50.782 post_set+0x4 (generic_set_mtrr+0x12e)
:| #func -68! 40.665 mtrr_wrmsr+0xd (post_set+0x25)
:| #func -28+ 1.185 _spin_unlock+0x4 (post_set+0x4f)
:| #func -27 0.356 sub_preempt_count+0x9 (_spin_unlock+0x15)
:| #func -26 0.900 ipipe_check_context+0x11 (sub_preempt_count+0x1c)
:| #end 0x80000001 -25+ 1.050 generic_set_mtrr+0x13f (set_mtrr+0xdc)
:| #begin 0x000000f6 -24 0.566 common_interrupt+0x20 (generic_set_mtrr+0x142)
:| #func -24 0.468 __ipipe_handle_irq+0x11 (common_interrupt+0x27)
:| #func -23 0.266 irq_to_desc+0x4 (__ipipe_handle_irq+0x134)
:| #func -23 0.397 __ipipe_ack_apic+0x4 (__ipipe_handle_irq+0x13c)
:| #func -23 0.465 native_apic_mem_write+0x4 (__ipipe_ack_apic+0x1d)
:| #func -22 0.348 __ipipe_dispatch_wired+0xd (__ipipe_handle_irq+0x147)
:| #func -22 0.450 __ipipe_dispatch_wired_nocheck+0x11 (__ipipe_dispatch_wired+0xba)
:| #*func -21 0.634 xnintr_clock_handler+0xb (__ipipe_dispatch_wired_nocheck+0x12b)
:| #*func -21 0.892 xntimer_tick_aperiodic+0xb (xnintr_clock_handler+0x81)
:| #*func -20 0.352 xnthread_periodic_handler+0x4 (xntimer_tick_aperiodic+0x8d)
:| #*func -19 0.585 xnpod_resume_thread+0x11 (xnthread_periodic_handler+0x2d)
:| #*[ 3272] -<?>- 99 -19 0.682 xnpod_resume_thread+0xfa (xnthread_periodic_handler+0x2d)
:| #*func -18 0.318 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x191)
:| #*event tick@domain.hid -18 0.285 xntimer_next_local_shot+0xb0 (xntimer_tick_aperiodic+0x191)
:| #*func -18 0.420 native_apic_mem_write+0x4 (xntimer_next_local_shot+0xe5)
:| #*func -17 0.517 __xnpod_schedule+0x11 (xnintr_clock_handler+0x130)
:| #*[ 3276] Xorg -1 -17 0.296 __xnpod_schedule+0x189 (xnintr_clock_handler+0x130)
:| #*func -16+ 1.601 xnsched_pick_next+0x4 (__xnpod_schedule+0x1e3)
:| #*func -15+ 1.091 __phys_addr+0x4 (__xnpod_schedule+0x562)
:| #*func -14 0.697 __switch_to_xtra+0x8 (__switch_to+0x255)
:| #*[ 3272] -<?>- 99 -13 0.945 __xnpod_schedule+0x834 (xnpod_suspend_thread+0x281)
:| #*func -12 0.495 xntimer_get_overruns+0x8 (xnpod_wait_thread_period+0x14c)
:| #*func -11 0.307 __ipipe_restore_pipeline_head+0x7 (xnpod_wait_thread_period+0x1cb)
:| +*end 0x80000000 -11+ 1.526 __ipipe_restore_pipeline_head+0x137 (xnpod_wait_thread_period+0x1cb)
:| +*begin 0x80000001 -10 0.442 __ipipe_dispatch_event+0x1d9 (__ipipe_syscall_root+0xcd)
:| +*end 0x80000001 -9 0.341 __ipipe_dispatch_event+0x3f0 (__ipipe_syscall_root+0xcd)
:| +*begin 0x80000001 -9+ 4.351 __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
: +*func -5 0.322 __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
: +*func -4 0.202 __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
:| +*begin 0x80000001 -4 0.510 __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
:| +*end 0x80000001 -3 0.266 __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
: +*func -3 0.791 hisyscall_event+0x11 (__ipipe_dispatch_event+0x1b7)
: +*func -2 0.528 xnshadow_sys_trace+0x7 (hisyscall_event+0x151)
: +*func -2 0.300 ipipe_trace_frozen_reset+0xb (xnshadow_sys_trace+0x69)
: +*func -2 0.199 __ipipe_global_path_lock+0x4 (ipipe_trace_frozen_reset+0x1c)
: +*func -1 0.187 __ipipe_spin_lock_irqsave+0xb (__ipipe_global_path_lock+0x15)
:| +*begin 0x80000001 -1+ 1.226 __ipipe_spin_lock_irqsave+0x2a (__ipipe_global_path_lock+0x15)
:| #*func 0 0.262 __ipipe_spin_unlock_irqcomplete+0xb (__ipipe_global_path_unlock+0x7d)
:| +*end 0x80000001 0 0.229 __ipipe_spin_unlock_irqcomplete+0xcf (__ipipe_global_path_unlock+0x7d)
< +*freeze 0x001f3e65 0 0.225 xnshadow_sys_trace+0x73 (hisyscall_event+0x151)
| +*begin 0x80000001 0 0.251 __ipipe_dispatch_event+0x1d9 (__ipipe_syscall_root+0xcd)
| +*end 0x80000001 0 0.214 __ipipe_dispatch_event+0x3f0 (__ipipe_syscall_root+0xcd)
| +*begin 0x80000001 0 0.708 __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
+*func 1 0.199 __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
+*func 1 0.183 __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
| +*begin 0x80000001 1 0.262 __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
| +*end 0x80000001 2 0.199 __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
+*func 2 0.352 hisyscall_event+0x11 (__ipipe_dispatch_event+0x1b7)
+*func 2 0.281 __rt_task_wait_period+0xb (hisyscall_event+0x151)
+*func 2 0.000 rt_task_wait_period+0x4 (__rt_task_wait_period+0x1c)