Re: [Xenomai-help] Very high latencies under stress testing

[edward.robbins@domain.hid]

[-- Attachment #1: Type: text/plain, Size: 12486 bytes --]

I am also finding that tasks are frequently hanging, causing ipipetraces with "INFO: task xxx:xxx blocked for more than 120 seconds". Ihave just had this with apt-get update, and was previously getting itwith grub-install. Could this be related?

Thanks again

On Friday, 15 October, 2010 10:21am, edward.robbins@domain.hid said:

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)

[-- Attachment #2: Type: text/html, Size: 22680 bytes --]