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

[edward.robbins@domain.hid]

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

I have now installed the i-pipe tracer and run some tests. Yesterday I thought I had gotten a high latency without X running, while compiling the kernel to stress the system, but now I think I might have been mistaken. Either way I was using a kernel whose configuration I couldn't remember, and didn't have the I-Pipe tracer installed at that time, so the observation wasn't particularly useful.

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.

A couple of other things:

Yesterday when running xeno-test, I got a few of these messages:
   "INFO: task sync:20539 blocked for more than 120 seconds...."
I have not seen this again today, and I don't know if it could be related, but I was also getting lots of strange USB disconnect sort of messages yesterday... I haven't seen any more today, and as I said before that kernel may have been useless anyway.

I am also getting this message from xeno-test:
   "FATAL: module xeno-nucleus not found"

And:
   "Warning Linux is compiled to use FPU in kernel space
    For this reason, switch test can not test using FPU in Linux Kernel-space"

I presume these last two are because I did something wrong at kernel compile time?

Also, I tried to compile Xenomai 2.5.4 with a 2.6.34 kernel because it has a network driver that I really need, but the build failed. I think this has been resolved previously (as I have seen some information in the mailing list about a problem in the debian kernel patch script), but am not sure how to use the corrected script with my system. Can anyone help?

I will keep testing.

Thanks,

Edward


On Monday, 16 August, 2010 1:32pm, "Gilles Chanteperdrix" <gilles.chanteperdrix@xenomai.org> said:

> edward.robbins@domain.hid wrote:
>>
>> On Friday, 13 August, 2010 3:35pm, "Gilles Chanteperdrix"
>> <gilles.chanteperdrix@xenomai.org> said:
>>
>>> edward.robbins@domain.hid wrote:
>>>> I wonder if this is to do with graphics? I have set "NoAccel" in the
>>>> driver section of Xorg.conf (I am using fbdev). I also notice that
>>>> latencies go massive (e.g. 4200uS) the first time I run glxgears.
>>>> "glxinfo" reports "Direct rendering: no".
>>> This is bad news. It could come either from the fact that the Xorg
>>> driver shuts hardware interrupts off (there is nothing xenomai can do
>>> about that), or it could be an SMI issue. What about using the driver
>>> for the real graphic card you have ? Probably intel card? Do you observe
>>> any big latencies if you stress the system with anything else than X?
>>>
>>>> Power management options (ACPUI, APM): Disable ACPI (Advanced
>>>> Configuration and Power Interface) Support --> Processor Disable CPU
>>>> Frequency Scaling Disable CPU idle PM support Disable Power Managment
>>>> Support
>>> Disabling ACPI is a bad idea. As repeated many times, only
>>> ACPI_PROCESSOR should be disabled, not ACPI.
>>>
>>
>> Thanks for your helpful responses.
>>
>> I'm not working on this project again until next week, but on Friday I was able
>> to
>>
>>  o Recompile the kernel with ACPI enabled
>>  o Boot with the 'SMI handler' BIOS option set to disabled....
>>    according to the help text this option should be disabled if 'an RTOS
>>    is installed' - I presume this means that SMIs are completely disabled
>>    and therefore SMIs cannot be the source of the problem
>>   (very convenient BIOS option... now I begin to appreciate the expense of this
>> board!)
>>  o Changed xorg to use the intel video driver
> 
> Now you can try NoAccel with the intel video driver too....
> 
> 
> --
> 					    Gilles.
> 

[-- Attachment #2: ipipe_trace --]
[-- Type: application/octet-stream, Size: 11226 bytes --]

I-pipe frozen back-tracing service on 2.6.32.15-xenomai-2.5.4/ipipe-2.7-01
------------------------------------------------------------
CPU: 0, Freeze: 5423344453447 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               -1215    0.378  xnsched_pick_next+0x4 (__xnpod_schedule+0x1e3)
:|  #*func               -1214    0.491  __phys_addr+0x4 (__xnpod_schedule+0x562)
:|  #*[14670] samplin 99 -1214    0.378  __xnpod_schedule+0x834 (xnpod_suspend_thread+0x281)
:|  #*func               -1214    0.221  xntimer_get_overruns+0x8 (xnpod_wait_thread_period+0x14c)
:|  #*func               -1213    0.213  __ipipe_restore_pipeline_head+0x7 (xnpod_wait_thread_period+0x1cb)
:|  +*end     0x80000000 -1213    0.319  __ipipe_restore_pipeline_head+0x137 (xnpod_wait_thread_period+0x1cb)
:|  +*begin   0x80000001 -1213    0.281  __ipipe_dispatch_event+0x1d9 (__ipipe_syscall_root+0xcd)
:|  +*end     0x80000001 -1213    0.229  __ipipe_dispatch_event+0x3f0 (__ipipe_syscall_root+0xcd)
:|  +*begin   0x80000001 -1212    0.573  __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
:   +*func               -1212    0.214  __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
:   +*func               -1212    0.210  __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
:|  +*begin   0x80000001 -1211    0.281  __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
:|  +*end     0x80000001 -1211    0.214  __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
:   +*func               -1211    0.217  hisyscall_event+0x11 (__ipipe_dispatch_event+0x1b7)
:   +*func               -1211    0.187  __rt_task_wait_period+0xb (hisyscall_event+0x151)
:   +*func               -1210    0.195  rt_task_wait_period+0x4 (__rt_task_wait_period+0x1c)
:   +*func               -1210    0.198  xnpod_wait_thread_period+0xb (rt_task_wait_period+0x3b)
:|  +*begin   0x80000000 -1210    0.270  xnpod_wait_thread_period+0x3d (rt_task_wait_period+0x3b)
:|  #*func               -1210    0.262  xnpod_suspend_thread+0x11 (xnpod_wait_thread_period+0x126)
:|  #*func               -1210    0.240  __xnpod_schedule+0x11 (xnpod_suspend_thread+0x281)
:|  #*[14670] samplin 99 -1209    0.217  __xnpod_schedule+0x189 (xnpod_suspend_thread+0x281)
:|  #*func               -1209    0.367  xnsched_pick_next+0x4 (__xnpod_schedule+0x1e3)
:|  #*func               -1209    0.424  __phys_addr+0x4 (__xnpod_schedule+0x562)
:|  #*[13273] dd      -1 -1208    0.420  __xnpod_schedule+0x834 (xnintr_clock_handler+0x130)
:|   #func               -1208    0.408  __ipipe_walk_pipeline+0x11 (__ipipe_dispatch_wired_nocheck+0x1da)
:|   #end     0x000000f6 -1207    0.345  common_interrupt+0x39 (__ipipe_sync_stage+0x195)
:    #func               -1207    0.221  __ipipe_get_ioapic_irq_vector+0x4 (__ipipe_sync_stage+0x1ce)
:    #func               -1207    0.202  smp_call_function_single_interrupt+0x4 (__ipipe_sync_stage+0x21b)
:    #func               -1207    0.195  irq_enter+0x9 (smp_call_function_single_interrupt+0xe)
:|   #begin   0x80000001 -1206    0.243  debug_smp_processor_id+0x44 (irq_enter+0x13)
:|   #end     0x80000001 -1206    0.251  debug_smp_processor_id+0x94 (irq_enter+0x13)
:    #func               -1206    0.195  rcu_irq_enter+0x9 (irq_enter+0x1a)
:|   #begin   0x80000001 -1206    0.240  debug_smp_processor_id+0x44 (rcu_irq_enter+0x1a)
:|   #end     0x80000001 -1206    0.255  debug_smp_processor_id+0x94 (rcu_irq_enter+0x1a)
:    #func               -1205    0.202  idle_cpu+0x4 (irq_enter+0x21)
:    #func               -1205    0.206  add_preempt_count+0x9 (irq_enter+0x59)
:    #func               -1205    0.195  ipipe_check_context+0x11 (add_preempt_count+0x1c)
:|   #begin   0x80000001 -1205    0.262  ipipe_check_context+0x33 (add_preempt_count+0x1c)
:|   #end     0x80000001 -1204    0.229  ipipe_check_context+0xda (add_preempt_count+0x1c)
:    #func               -1204    0.195  generic_smp_call_function_single_interrupt+0xd (smp_call_function_single_interrupt+0x13)
:|   #begin   0x80000001 -1204    0.240  debug_smp_processor_id+0x44 (generic_smp_call_function_single_interrupt+0x1e)
:|   #end     0x80000001 -1204    0.225  debug_smp_processor_id+0x94 (generic_smp_call_function_single_interrupt+0x1e)
:|   #begin   0x80000001 -1204    0.232  debug_smp_processor_id+0x44 (generic_smp_call_function_single_interrupt+0x39)
:|   #end     0x80000001 -1203    0.221  debug_smp_processor_id+0x94 (generic_smp_call_function_single_interrupt+0x39)
:    #func               -1203    0.199  _spin_lock+0x9 (generic_smp_call_function_single_interrupt+0x7d)
:    #func               -1203    0.191  add_preempt_count+0x9 (_spin_lock+0x1b)
:    #func               -1203    0.187  ipipe_check_context+0x11 (add_preempt_count+0x1c)
:|   #begin   0x80000001 -1203    0.251  ipipe_check_context+0x33 (add_preempt_count+0x1c)
:|   #end     0x80000001 -1202    0.277  ipipe_check_context+0xda (add_preempt_count+0x1c)
:    #func               -1202    0.191  _spin_unlock+0x4 (generic_smp_call_function_single_interrupt+0xa7)
:    #func               -1202    0.195  sub_preempt_count+0x9 (_spin_unlock+0x15)
:    #func               -1202    0.187  ipipe_check_context+0x11 (sub_preempt_count+0x1c)
:|   #begin   0x80000001 -1201    0.251  ipipe_check_context+0x33 (sub_preempt_count+0x1c)
:|   #end     0x80000001 -1201    0.258  ipipe_check_context+0xda (sub_preempt_count+0x1c)
:    #func               -1201    0.195  __cpa_flush_all+0x9 (generic_smp_call_function_single_interrupt+0xe6)
:    #func               -1201    0.191  ipipe_check_context+0x11 (__cpa_flush_all+0x26)
:|   #begin   0x80000001 -1201    0.255  ipipe_check_context+0x33 (__cpa_flush_all+0x26)
:|   #end     0x80000001 -1200    0.547  ipipe_check_context+0xda (__cpa_flush_all+0x26)
:    #func               -1200    0.195  __ipipe_restore_root+0xb (__cpa_flush_all+0x67)
:|   #begin   0x80000001 -1200    0.240  __ipipe_restore_root+0x2d (__cpa_flush_all+0x67)
:|   #end     0x80000001 -1199! 1173.258  __ipipe_restore_root+0x7d (__cpa_flush_all+0x67)
:|   #begin   0x000000f6   -26+   1.549  common_interrupt+0x20 (__cpa_flush_all+0x7f)
:|   #func                 -24    0.472  __ipipe_handle_irq+0x11 (common_interrupt+0x27)
:|   #func                 -24    0.292  irq_to_desc+0x4 (__ipipe_handle_irq+0x134)
:|   #func                 -24    0.390  __ipipe_ack_apic+0x4 (__ipipe_handle_irq+0x13c)
:|   #func                 -23    0.630  native_apic_mem_write+0x4 (__ipipe_ack_apic+0x1d)
:|   #func                 -23    0.318  __ipipe_dispatch_wired+0xd (__ipipe_handle_irq+0x147)
:|   #func                 -22    0.442  __ipipe_dispatch_wired_nocheck+0x11 (__ipipe_dispatch_wired+0xba)
:|  #*func                 -22    0.592  xnintr_clock_handler+0xb (__ipipe_dispatch_wired_nocheck+0x12b)
:|  #*func                 -21    0.862  xntimer_tick_aperiodic+0xb (xnintr_clock_handler+0x81)
:|  #*func                 -20    0.274  xnthread_periodic_handler+0x4 (xntimer_tick_aperiodic+0x8d)
:|  #*func                 -20+   1.050  xnpod_resume_thread+0x11 (xnthread_periodic_handler+0x2d)
:|  #*[14670] samplin 99   -19    0.686  xnpod_resume_thread+0xfa (xnthread_periodic_handler+0x2d)
:|  #*func                 -18    0.292  xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x191)
:|  #*event   tick@79      -18    0.307  xntimer_next_local_shot+0xb0 (xntimer_tick_aperiodic+0x191)
:|  #*func                 -18    0.499  native_apic_mem_write+0x4 (xntimer_next_local_shot+0xe5)
:|  #*func                 -17    0.660  __xnpod_schedule+0x11 (xnintr_clock_handler+0x130)
:|  #*[13273] dd      -1   -17    0.273  __xnpod_schedule+0x189 (xnintr_clock_handler+0x130)
:|  #*func                 -16+   1.691  xnsched_pick_next+0x4 (__xnpod_schedule+0x1e3)
:|  #*func                 -15+   1.282  __phys_addr+0x4 (__xnpod_schedule+0x562)
:|  #*[14670] samplin 99   -13    0.896  __xnpod_schedule+0x834 (xnpod_suspend_thread+0x281)
:|  #*func                 -13    0.247  xntimer_get_overruns+0x8 (xnpod_wait_thread_period+0x14c)
:|  #*func                 -12    0.311  __ipipe_restore_pipeline_head+0x7 (xnpod_wait_thread_period+0x1cb)
:|  +*end     0x80000000   -12+   1.710  __ipipe_restore_pipeline_head+0x137 (xnpod_wait_thread_period+0x1cb)
:|  +*begin   0x80000001   -10    0.363  __ipipe_dispatch_event+0x1d9 (__ipipe_syscall_root+0xcd)
:|  +*end     0x80000001   -10    0.330  __ipipe_dispatch_event+0x3f0 (__ipipe_syscall_root+0xcd)
:|  +*begin   0x80000001   -10+   5.135  __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
:   +*func                  -4    0.330  __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
:   +*func                  -4    0.213  __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
:|  +*begin   0x80000001    -4    0.480  __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
:|  +*end     0x80000001    -3    0.259  __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
:   +*func                  -3    0.615  hisyscall_event+0x11 (__ipipe_dispatch_event+0x1b7)
:   +*func                  -3    0.547  xnshadow_sys_trace+0x7 (hisyscall_event+0x151)
:   +*func                  -2    0.292  ipipe_trace_frozen_reset+0xb (xnshadow_sys_trace+0x69)
:   +*func                  -2    0.198  __ipipe_global_path_lock+0x4 (ipipe_trace_frozen_reset+0x1c)
:   +*func                  -2    0.191  __ipipe_spin_lock_irqsave+0xb (__ipipe_global_path_lock+0x15)
:|  +*begin   0x80000001    -1+   1.316  __ipipe_spin_lock_irqsave+0x2a (__ipipe_global_path_lock+0x15)
:|  #*func                   0    0.266  __ipipe_spin_unlock_irqcomplete+0xb (__ipipe_global_path_unlock+0x7d)
:|  +*end     0x80000001     0    0.236  __ipipe_spin_unlock_irqcomplete+0xcf (__ipipe_global_path_unlock+0x7d)
<   +*freeze  0x0010fc66     0    0.214  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.648  __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
    +*func                   1    0.210  __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
    +*func                   1    0.187  __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
 |  +*begin   0x80000001     1    0.262  __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
 |  +*end     0x80000001     1    0.199  __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
    +*func                   2    0.348  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)