From: Manuel Huber <manuel.h87@gmail.com>
To: Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org>
Cc: xenomai@xenomai.org
Subject: Re: [Xenomai] Decrease Latency (below 10 us) on x32 or x32_64?
Date: Tue, 26 Mar 2013 11:18:34 +0100 [thread overview]
Message-ID: <515175FA.4030901@gmail.com> (raw)
In-Reply-To: <5148CEA9.7060700@xenomai.org>
Hello!
Sorry for the delay. I have re-compiled the Kernel with the I-pipe
tracer enabled, and I disabled the HPET. Then, I tried to reset the
tracer by writing 0 to /proc/ipipe/trace/frozen and some string to
/proc/ipipe/trace/max. Then I started the latency program with the -f
option for some minutes and afterwards captured the variables in
/proc/ipipe/trace/. One test has been made in single-user mode and
without the nouveau driver (plain-vga_300.txt) and the other trace has
been made in normal multi-user mode with gdm running (and the nouveau
driver; gui_300.txt). There is one trace without any USB-device
attached (plain-vga_300_no_usb.txt), but I'm not sure if that makes
any difference.
I hope I used the I-pipe tracer correctly. I'm sorry to bother you
again, but I can't interpret the results :( Maybe you could interpret
the trace, if you have time for it...
Thanks for all your effort...
On 2013-03-19 21:46, Gilles Chanteperdrix wrote:
> On 03/19/2013 09:14 PM, Manuel Huber wrote:
>
>> Hello!
>>
>> We use a AMD FX-61000 CPU together with Xenomai 2.6.2.1 and Kernel
>> 3.5.7 (thanks to Jan Kiszka) and I was wondering if it's possible to
>> further decrease the latency of the system. I currently can get more
>> than 30 us when interacting with the system.
>>
>> My first guess was the graphics card + graphics card driver because I
>> read about such problems and tested another graphics card which caused
>> a huge amount of extra-latency... I tried to get the real system
>> latency by booting the system in recovery mode (single) with vga=792
>> option + setting the nouveau driver on the blacklist... This seems to
>> work, but I still get roughly the same latencies (>20us) even after
>> 1hour by using the latency program in interrupt mode (-t 2). Only a
>> few times the latency grows beyond 10us but still it does... I have
>> unplugged the usb mouse and keyboard before running the test and
>> started ten instances of burnK7 with nice -n -20. I also tried
>> booting with isolcpus=2,3 and assigned the latency program to cpu 3
>> (-c 3). This didn't really improve the worst case latency (still the
>> same setup as above, no gui, single). Is it possible to further
>> decrease latency (especially worst case latency) by using one cpu just
>> for real-time tasks? Is there some other way to keep Linux from using
>> a core?
>>
>> The next thing I want to test is using 64bits; It seems rational that
>> using 32 bits with 16GB ram causes some extra latencies but is it
>> possible that it causes about 10 us extra? Is there some other option
>> I can tune? I know that the I-Pipe system isn't trivial but to me,
>> using interrupts seems pretty low-level and I would expect this to
>> have minimal latency (and jitter). I don't want to complain, it's just
>> that my supervisor asked me about the source of the latency and I
>> can't really explain... After having read just about all papers
>> about I-Pipe, I still don't have a deep understanding of the system.
>> Is there a good reference I missed?
>
> First, to know where the latency comes from, enable the I-pipe tracer,
> and run latency with the "-f" option.
>
> Now, common ways to reduce latencies are:
> - optimize the kernel for size
> - disable high res timers, you can try fiddling with the various preempt
> settings, this used to have a big impact on code size, but with the
> "optimize for size" option, they no longer seem to have one.
> - check what the processor does when idle; if it enters C1 state, try to
> avoid that with the BIOS settings, or pass "nohlt" on the kernel command
> line.
>
> But of course, what you should do probably depends on the I-pipe tracer
> results. And to really know what your worst case latency is, you should
> always run the test the same time with the same load, you can use
> xeno-test for that.
>
-------------- next part --------------
I-pipe trace results
--------------------
[parameters]
enable = 1
verbose = 5
pre_trace_points = 10
back_trace_points = 100
post_trace_points = 10
[frozen]
I-pipe frozen back-tracing service on 3.5.7-trace/ipipe release #3
------------------------------------------------------------
CPU: 0, Freeze: 30387304420200 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.078 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)
:| #end 0x80000001 -63 0.462 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -62 0.506 update_rq_clock+0x6 (scheduler_tick+0x3d)
:| #begin 0x80000001 -62 0.407 debug_smp_processor_id+0x36 (__cycles_2_ns+0x17)
:| #end 0x80000001 -61 0.471 debug_smp_processor_id+0x82 (__cycles_2_ns+0x17)
: #func -61 0.466 __update_cpu_load+0x9 (scheduler_tick+0x54)
: #func -60 0.469 sched_avg_update+0x9 (__update_cpu_load+0xa5)
: #func -60 0.366 task_tick_idle+0x3 (scheduler_tick+0x9e)
: #func -59 0.331 _raw_spin_unlock+0x3 (scheduler_tick+0xa5)
: #func -59 0.476 sub_preempt_count+0x3 (_raw_spin_unlock+0x15)
:| #begin 0x80000001 -59 0.441 debug_smp_processor_id+0x36 (perf_event_task_tick+0x13)
:| #end 0x80000001 -58 0.516 debug_smp_processor_id+0x82 (perf_event_task_tick+0x13)
: #func -58 0.363 trigger_load_balance+0x9 (scheduler_tick+0xeb)
: #func -57 0.458 raise_softirq+0x4 (trigger_load_balance+0x3f)
: #func -57 0.366 __raise_softirq_irqoff+0x5 (raise_softirq_irqoff+0x8)
: #func -57 0.344 ipipe_restore_root+0x4 (arch_local_irq_restore+0x11)
: #func -56 0.398 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
:| #begin 0x80000001 -56 0.558 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -55 0.511 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -55 0.483 idle_cpu+0x3 (trigger_load_balance+0x4e)
: #func -54 0.548 run_posix_cpu_timers+0x9 (update_process_times+0x58)
: #func -54 0.450 hrtimer_forward+0xc (tick_sched_timer+0x74)
: #func -53 0.414 ktime_add_safe+0x8 (hrtimer_forward+0xfb)
: #func -53 0.411 ktime_add_safe+0x8 (hrtimer_forward+0x114)
: #func -52 0.327 _raw_spin_lock+0x4 (__run_hrtimer+0x10a)
: #func -52 0.391 add_preempt_count+0x4 (_raw_spin_lock+0x15)
: #func -52 0.363 ipipe_root_only+0x5 (add_preempt_count+0x10)
:| #begin 0x80000001 -51 0.527 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -51 0.487 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -50 0.741 enqueue_hrtimer+0x6 (__run_hrtimer+0x123)
: #func -50 0.359 _raw_spin_unlock+0x3 (hrtimer_interrupt+0x127)
: #func -49 0.400 sub_preempt_count+0x3 (_raw_spin_unlock+0x15)
: #func -49 0.416 tick_program_event+0x4 (hrtimer_interrupt+0x13f)
: #func -48 0.348 clockevents_program_event+0x9 (tick_program_event+0x24)
: #func -48 0.568 ktime_get+0x9 (clockevents_program_event+0x71)
: #func -47 0.406 xnarch_next_htick_shot+0x5 (clockevents_program_event+0xd8)
:| #begin 0x80000000 -47 0.610 ipipe_test_and_stall_pipeline_head+0x15 (T.1349+0x16)
:| *#func -46 0.456 xntimer_start_aperiodic+0x9 (xnarch_next_htick_shot+0x42)
:| *#func -46 0.843 xnarch_ns_to_tsc+0x9 (xntimer_start_aperiodic+0x78)
:| *#func -45 0.362 __ipipe_restore_head+0x4 (ipipe_restore_pipeline_head+0x4d)
:| #end 0x80000000 -45 0.525 hard_local_irq_enable+0x14 (__ipipe_restore_head+0x66)
: #func -44 0.391 irq_exit+0x3 (smp_apic_timer_interrupt+0x5d)
: #func -44 0.519 sub_preempt_count+0x3 (irq_exit+0x12)
: #func -43 0.575 do_softirq+0x9 (irq_exit+0x3a)
: #func -43 0.364 __do_softirq+0x9 (do_softirq+0x86)
: #func -42 0.320 add_preempt_count+0x4 (__do_softirq+0x1f)
: #func -42 0.331 ipipe_root_only+0x5 (add_preempt_count+0x10)
:| #begin 0x80000001 -42 0.503 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -41 0.409 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
:| #begin 0x80000001 -41 0.420 debug_smp_processor_id+0x36 (__do_softirq+0x24)
:| #end 0x80000001 -40+ 1.265 debug_smp_processor_id+0x82 (__do_softirq+0x24)
:| #begin 0x000000fd -39 0.390 reschedule_interrupt+0x37 (debug_smp_processor_id+0x86)
:| #func -39 0.475 __ipipe_handle_irq+0x9 (reschedule_interrupt+0x3e)
:| #func -38 0.449 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| #func -38 0.508 __ipipe_ack_apic+0x3 (__ipipe_dispatch_irq+0xa4)
:| #func -37 0.650 __ipipe_set_irq_pending+0x6 (__ipipe_dispatch_irq+0x19a)
:| #func -37 0.768 __ipipe_do_sync_pipeline+0x4 (__ipipe_sync_pipeline+0x1c)
:| #end 0x000000fd -36+ 1.720 reschedule_interrupt+0x4f (debug_smp_processor_id+0x86)
:| #begin 0x000000ef -34 0.433 apic_timer_interrupt+0x37 (debug_smp_processor_id+0x86)
:| #func -34 0.493 __ipipe_handle_irq+0x9 (apic_timer_interrupt+0x3e)
:| #func -33 0.375 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| #func -33 0.396 __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0xa4)
:| #func -33 0.604 lapic_itimer_ack+0x3 (__ipipe_ack_hrtimer_irq+0x59)
:| #*func -32 0.793 xnintr_clock_handler+0x5 (__ipipe_dispatch_irq+0x14d)
:| #*func -31+ 3.220 __xnlock_spin+0x9 (T.1249+0x47)
:| #*func -28 0.784 xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x97)
:| #*func -27 0.705 xnthread_periodic_handler+0x3 (xntimer_tick_aperiodic+0x78)
:| #*func -26 0.952 xnpod_resume_thread+0x9 (xnthread_periodic_handler+0x20)
:| #*[ 2722] -<?>- 99 -25+ 1.144 xnpod_resume_thread+0x4a (xnthread_periodic_handler+0x20)
:| #*func -24 0.607 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x143)
:| #*event tick@57 -24 0.597 xntimer_next_local_shot+0xbd (xntimer_tick_aperiodic+0x143)
:| #*func -23 0.727 ipipe_timer_set+0x9 (xntimer_next_local_shot+0xc4)
:| #*func -22+ 1.501 lapic_next_event+0x3 (ipipe_timer_set+0x77)
:| #*func -21+ 1.055 __xnpod_schedule+0x9 (xnintr_clock_handler+0x124)
:| #*func -20+ 1.743 __xnlock_spin+0x9 (T.1349+0x55)
:| #*[ 0] -<?>- -1 -18 0.562 __xnpod_schedule+0x69 (xnintr_clock_handler+0x124)
:| #*func -18+ 1.407 xnsched_pick_next+0x6 (__xnpod_schedule+0xae)
:| #*func -16+ 1.576 __switch_to+0x9 (__xnpod_schedule+0x3c6)
:| #*[ 2722] -<?>- 99 -15+ 1.453 __xnpod_schedule+0x43e (xnpod_schedule+0x32)
:| #*func -13 0.842 xntimer_get_overruns+0x9 (xnpod_wait_thread_period+0xa8)
:| #*func -12 0.423 __ipipe_restore_head+0x4 (ipipe_restore_pipeline_head+0x4d)
:| +*end 0x80000000 -12 0.645 hard_local_irq_enable+0x14 (__ipipe_restore_head+0x66)
:| +*begin 0x80000001 -11 0.586 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6a)
:| +*end 0x80000001 -11 0.480 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xc5)
:| +*begin 0x80000001 -10+ 1.896 hard_local_irq_save+0x16 (__ipipe_syscall_root+0x35)
: +*func -8 0.449 __ipipe_syscall_root+0x6 (sysenter_past_esp+0x55)
: +*func -8 0.392 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
:| +*begin 0x80000001 -7 0.552 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
:| +*end 0x80000001 -7 0.429 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
: +*func -6 0.434 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
:| +*begin 0x80000001 -6 0.409 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
:| +*end 0x80000001 -6 0.409 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
: +*func -5 0.740 hisyscall_event+0x9 (ipipe_syscall_hook+0x88)
: +*func -4 0.722 xnshadow_sys_trace+0x6 (hisyscall_event+0x11b)
: +*func -4 0.475 ipipe_trace_frozen_reset+0x6 (xnshadow_sys_trace+0x5c)
: +*func -3 0.381 __ipipe_global_path_lock+0x9 (ipipe_trace_frozen_reset+0x1a)
: +*func -3 0.363 __ipipe_spin_lock_irqsave+0x5 (__ipipe_global_path_lock+0x1d)
:| +*begin 0x80000001 -2+ 1.884 hard_local_irq_save+0x16 (__ipipe_spin_lock_irqsave+0x11)
:| #*func -1 0.562 __ipipe_spin_unlock_irqcomplete+0x4 (__ipipe_global_path_unlock+0x62)
:| +*end 0x80000001 0 0.495 hard_local_irq_restore+0x15 (__ipipe_spin_unlock_irqcomplete+0x24)
< +*freeze 0x000070c6 0 0.551 xnshadow_sys_trace+0x65 (hisyscall_event+0x11b)
| +*begin 0x80000001 0 0.486 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6a)
| +*end 0x80000001 1 0.472 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xc5)
| +*begin 0x80000001 1 1.392 hard_local_irq_save+0x16 (__ipipe_syscall_root+0x35)
+*func 2 0.409 __ipipe_syscall_root+0x6 (sysenter_past_esp+0x55)
+*func 3 0.409 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
| +*begin 0x80000001 3 0.591 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
| +*end 0x80000001 4 0.499 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
+*func 4 0.344 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
| +*begin 0x80000001 5 0.438 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
| +*end 0x80000001 5 0.000 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
[max]
I-pipe worst-case tracing service on 3.5.7-trace/ipipe release #3
-------------------------------------------------------------
CPU: 0, Begin: 29765921826239 cycles, Trace Points: 8 (-10/+5), Length: 1922 us
Calibrated minimum trace-point overhead: 0.078 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)
#func -3 0.254 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
| #begin 0x80000001 -3 0.381 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
| #end 0x80000001 -2 0.374 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
#func -2 0.307 default_idle+0x3 (cpu_idle+0x5d)
| #begin 0x80000001 -1 0.325 debug_smp_processor_id+0x36 (default_idle+0xd)
| #end 0x80000001 -1 0.323 debug_smp_processor_id+0x82 (default_idle+0xd)
| #begin 0x80000001 -1 0.327 debug_smp_processor_id+0x36 (default_idle+0x1e)
| #end 0x80000001 0 0.380 debug_smp_processor_id+0x82 (default_idle+0x1e)
#func 0 0.249 __ipipe_halt_root+0x3 (default_idle+0x48)
| #begin 0x80000000 0 0.334 __ipipe_halt_root+0x1a (default_idle+0x48)
>| +end 0x8000000e 0! 1920.059 __ipipe_halt_root+0x4c (default_idle+0x48)
:| +func 1920 0.417 __ipipe_handle_irq+0x9 (reschedule_interrupt+0x3e)
:| +func 1920 0.477 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| +func 1920 0.398 __ipipe_ack_apic+0x3 (__ipipe_dispatch_irq+0xa4)
:| +func 1921 0.492 __ipipe_set_irq_pending+0x6 (__ipipe_dispatch_irq+0x19a)
:| +func 1921 0.419 __ipipe_do_sync_pipeline+0x4 (__ipipe_sync_pipeline+0x1c)
:| +func 1922 0.438 __ipipe_do_sync_stage+0x9 (__ipipe_do_sync_pipeline+0x63)
<| #end 0x80000000 1922 0.369 hard_local_irq_enable+0x14 (__ipipe_do_sync_stage+0xbd)
#func 1923 0.322 __ipipe_do_IRQ+0x5 (__ipipe_do_sync_stage+0x137)
#func 1923 0.354 __ipipe_get_ioapic_irq_vector+0x3 (__ipipe_do_IRQ+0x1d)
#func 1923 0.337 smp_reschedule_interrupt+0x3 (__ipipe_do_IRQ+0x42)
#func 1924 0.376 scheduler_ipi+0x4 (smp_reschedule_interrupt+0x14)
| #begin 0x80000001 1924 0.000 debug_smp_processor_id+0x36 (scheduler_ipi+0x13)
-------------- next part --------------
I-pipe trace results
--------------------
[parameters]
enable = 1
verbose = 1
pre_trace_points = 10
back_trace_points = 100
post_trace_points = 10
[frozen]
I-pipe frozen back-tracing service on 3.5.7-trace/ipipe release #3
------------------------------------------------------------
CPU: 0, Freeze: 1144846449662 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.078 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)
: + func -139 0.282 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
:| + begin 0x80000001 -139 0.406 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
:| + end 0x80000001 -139 0.328 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
: + func -138 0.283 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
:| + begin 0x80000001 -138 0.335 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
:| + end 0x80000001 -138 0.306 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
: + func -137 0.305 hisyscall_event+0x9 (ipipe_syscall_hook+0x88)
: + func -137 0.255 __rt_task_wait_period+0x7 (hisyscall_event+0x11b)
: + func -137 0.265 rt_task_wait_period+0x3 (__rt_task_wait_period+0x16)
: + func -136 0.276 xnpod_wait_thread_period+0x9 (rt_task_wait_period+0x3d)
:| + begin 0x80000000 -136 0.479 ipipe_test_and_stall_pipeline_head+0x15 (T.1349+0x16)
:| # func -136 0.390 xnpod_suspend_thread+0x9 (xnpod_wait_thread_period+0x7b)
:| # func -135 0.461 __xnpod_schedule+0x9 (xnpod_schedule+0x32)
:| # [ 1187] -<?>- 99 -135 0.313 __xnpod_schedule+0x69 (xnpod_schedule+0x32)
:| # func -135 0.686 xnsched_pick_next+0x6 (__xnpod_schedule+0xae)
:| # func -134 0.706 __switch_to+0x9 (__xnpod_schedule+0x3c6)
:| # [ 0] -<?>- -1 -133 0.834 __xnpod_schedule+0x43e (xnintr_clock_handler+0x124)
:| +func -132 0.483 __ipipe_do_sync_pipeline+0x4 (__ipipe_dispatch_irq+0x18c)
:| +end 0x000000ef -132 0.744 apic_timer_interrupt+0x4f (__ipipe_halt_root+0x4e)
:| +begin 0x80000001 -131 0.352 debug_smp_processor_id+0x36 (default_idle+0x5f)
:| +end 0x80000001 -131 0.321 debug_smp_processor_id+0x82 (default_idle+0x5f)
:| +begin 0x80000001 -130 0.336 debug_smp_processor_id+0x36 (default_idle+0x69)
:| +end 0x80000001 -130 0.336 debug_smp_processor_id+0x82 (default_idle+0x69)
: +func -130 0.323 rcu_idle_exit+0x9 (cpu_idle+0x62)
:| #begin 0x80000001 -129 0.347 debug_smp_processor_id+0x36 (rcu_idle_exit+0x4b)
:| #end 0x80000001 -129 0.325 debug_smp_processor_id+0x82 (rcu_idle_exit+0x4b)
: #func -129 0.320 rcu_idle_exit_common+0x5 (rcu_idle_exit+0xaa)
:| #begin 0x80000001 -128 0.325 debug_smp_processor_id+0x36 (rcu_idle_exit_common+0x39)
:| #end 0x80000001 -128 0.308 debug_smp_processor_id+0x82 (rcu_idle_exit_common+0x39)
: #func -128 0.263 ipipe_restore_root+0x4 (arch_local_irq_restore+0x11)
: #func -128 0.260 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
:| #begin 0x80000001 -127 0.371 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -127 0.307 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -127 0.260 ipipe_unstall_root+0x3 (ipipe_restore_root+0x2e)
:| #begin 0x80000000 -126 0.325 hard_local_irq_disable+0x15 (ipipe_unstall_root+0xd)
:| #func -126 0.401 ipipe_root_only+0x5 (ipipe_unstall_root+0x12)
:| +end 0x80000000 -126 0.316 hard_local_irq_enable+0x14 (ipipe_unstall_root+0x2b)
:| +begin 0x80000001 -125 0.352 debug_smp_processor_id+0x36 (cpu_idle+0x2b)
:| +end 0x80000001 -125 0.320 debug_smp_processor_id+0x82 (cpu_idle+0x2b)
: +func -125 0.281 local_touch_nmi+0x3 (cpu_idle+0x3f)
: #func -124 0.329 rcu_idle_enter+0x9 (cpu_idle+0x57)
:| #begin 0x80000001 -124 0.342 debug_smp_processor_id+0x36 (rcu_idle_enter+0x4b)
:| #end 0x80000001 -124 0.308 debug_smp_processor_id+0x82 (rcu_idle_enter+0x4b)
: #func -123 0.278 rcu_idle_enter_common+0x6 (rcu_idle_enter+0xb0)
:| #begin 0x80000001 -123 0.329 debug_smp_processor_id+0x36 (rcu_idle_enter_common+0x79)
:| #end 0x80000001 -123 0.327 debug_smp_processor_id+0x82 (rcu_idle_enter_common+0x79)
: #func -122 0.254 ipipe_restore_root+0x4 (arch_local_irq_restore+0x11)
: #func -122 0.262 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
:| #begin 0x80000001 -122 0.373 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -122 0.320 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -121 0.260 default_idle+0x3 (cpu_idle+0x5d)
:| #begin 0x80000001 -121 0.322 debug_smp_processor_id+0x36 (default_idle+0xd)
:| #end 0x80000001 -121 0.326 debug_smp_processor_id+0x82 (default_idle+0xd)
:| #begin 0x80000001 -120 0.321 debug_smp_processor_id+0x36 (default_idle+0x1e)
:| #end 0x80000001 -120 0.383 debug_smp_processor_id+0x82 (default_idle+0x1e)
: #func -120 0.261 __ipipe_halt_root+0x3 (default_idle+0x48)
:| #begin 0x80000000 -119 0.324 __ipipe_halt_root+0x1a (default_idle+0x48)
:| +end 0x8000000e -119! 68.058 __ipipe_halt_root+0x4c (default_idle+0x48)
:| +begin 0x000000ef -51 0.311 apic_timer_interrupt+0x37 (__ipipe_halt_root+0x4e)
:| +func -51 0.362 __ipipe_handle_irq+0x9 (apic_timer_interrupt+0x3e)
:| +func -50 0.273 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| +func -50 0.296 __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0xa4)
:| +func -50 0.441 lapic_itimer_ack+0x3 (__ipipe_ack_hrtimer_irq+0x59)
:| # func -49 0.567 xnintr_clock_handler+0x5 (__ipipe_dispatch_irq+0x14d)
:| # func -49+ 2.264 xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x97)
:| # func -46 0.364 xnthread_periodic_handler+0x3 (xntimer_tick_aperiodic+0x78)
:| # func -46 0.452 xnpod_resume_thread+0x9 (xnthread_periodic_handler+0x20)
:| # [ 1187] -<?>- 99 -46 0.696 xnpod_resume_thread+0x4a (xnthread_periodic_handler+0x20)
:| # func -45 0.388 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x143)
:| # event tick@45 -45 0.384 xntimer_next_local_shot+0xbd (xntimer_tick_aperiodic+0x143)
:| # func -44 0.428 ipipe_timer_set+0x9 (xntimer_next_local_shot+0xc4)
:| # func -44+ 1.980 lapic_next_event+0x3 (ipipe_timer_set+0x77)
:| # func -42+ 2.429 __xnpod_schedule+0x9 (xnintr_clock_handler+0x124)
:| # func -39! 21.147 __xnlock_spin+0x9 (T.1349+0x55)
:| # [ 0] -<?>- -1 -18 0.740 __xnpod_schedule+0x69 (xnintr_clock_handler+0x124)
:| # func -17+ 1.250 xnsched_pick_next+0x6 (__xnpod_schedule+0xae)
:| # func -16+ 1.489 __switch_to+0x9 (__xnpod_schedule+0x3c6)
:| # [ 1187] -<?>- 99 -15+ 1.301 __xnpod_schedule+0x43e (xnpod_schedule+0x32)
:| # func -13 0.806 xntimer_get_overruns+0x9 (xnpod_wait_thread_period+0xa8)
:| # func -13 0.463 __ipipe_restore_head+0x4 (ipipe_restore_pipeline_head+0x4d)
:| + end 0x80000000 -12 0.654 hard_local_irq_enable+0x14 (__ipipe_restore_head+0x66)
:| + begin 0x80000001 -11 0.519 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6a)
:| + end 0x80000001 -11 0.445 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xc5)
:| + begin 0x80000001 -10+ 2.091 hard_local_irq_save+0x16 (__ipipe_syscall_root+0x35)
: + func -8 0.417 __ipipe_syscall_root+0x6 (sysenter_past_esp+0x55)
: + func -8 0.384 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
:| + begin 0x80000001 -8 0.549 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
:| + end 0x80000001 -7 0.368 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
: + func -7 0.381 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
:| + begin 0x80000001 -6 0.440 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
:| + end 0x80000001 -6 0.403 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
: + func -5 0.512 hisyscall_event+0x9 (ipipe_syscall_hook+0x88)
: + func -5+ 1.265 xnshadow_sys_trace+0x6 (hisyscall_event+0x11b)
: + func -4 0.546 ipipe_trace_frozen_reset+0x6 (xnshadow_sys_trace+0x5c)
: + func -3 0.376 __ipipe_global_path_lock+0x9 (ipipe_trace_frozen_reset+0x1a)
: + func -3 0.392 __ipipe_spin_lock_irqsave+0x5 (__ipipe_global_path_lock+0x1d)
:| + begin 0x80000001 -2+ 1.843 hard_local_irq_save+0x16 (__ipipe_spin_lock_irqsave+0x11)
:| # func -1 0.575 __ipipe_spin_unlock_irqcomplete+0x4 (__ipipe_global_path_unlock+0x62)
:| + end 0x80000001 0 0.433 hard_local_irq_restore+0x15 (__ipipe_spin_unlock_irqcomplete+0x24)
< + freeze 0x00009e32 0 0.525 xnshadow_sys_trace+0x65 (hisyscall_event+0x11b)
| + begin 0x80000001 0 0.536 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6a)
| + end 0x80000001 1 0.444 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xc5)
| + begin 0x80000001 1 1.467 hard_local_irq_save+0x16 (__ipipe_syscall_root+0x35)
+ func 2 0.390 __ipipe_syscall_root+0x6 (sysenter_past_esp+0x55)
+ func 3 0.385 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
| + begin 0x80000001 3 0.519 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
| + end 0x80000001 4 0.414 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
+ func 4 0.371 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
| + begin 0x80000001 5 0.451 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
| + end 0x80000001 5 0.000 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
[max]
I-pipe worst-case tracing service on 3.5.7-trace/ipipe release #3
-------------------------------------------------------------
CPU: 0, Begin: 265702610058 cycles, Trace Points: 17 (-10/+5), Length: 3861 us
Calibrated minimum trace-point overhead: 0.078 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)
#func -4 0.381 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
| #begin 0x80000001 -4 0.514 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
| #end 0x80000001 -3 0.528 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
#func -3 0.395 default_idle+0x3 (cpu_idle+0x5d)
| #begin 0x80000001 -2 0.448 debug_smp_processor_id+0x36 (default_idle+0xd)
| #end 0x80000001 -2 0.475 debug_smp_processor_id+0x82 (default_idle+0xd)
| #begin 0x80000001 -1 0.458 debug_smp_processor_id+0x36 (default_idle+0x1e)
| #end 0x80000001 -1 0.599 debug_smp_processor_id+0x82 (default_idle+0x1e)
#func 0 0.378 __ipipe_halt_root+0x3 (default_idle+0x48)
| #begin 0x80000000 0 0.477 __ipipe_halt_root+0x1a (default_idle+0x48)
>| +end 0x8000000e 0! 3849.338 __ipipe_halt_root+0x4c (default_idle+0x48)
:| +func 3849 0.670 __ipipe_handle_irq+0x9 (apic_timer_interrupt+0x3e)
:| +func 3850 0.435 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| +func 3850 0.439 __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0xa4)
:| +func 3850 0.967 lapic_itimer_ack+0x3 (__ipipe_ack_hrtimer_irq+0x59)
:| # func 3851 0.925 xnintr_clock_handler+0x5 (__ipipe_dispatch_irq+0x14d)
:| # func 3852+ 2.877 __xnlock_spin+0x9 (T.1249+0x47)
:| # func 3855 0.555 xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x97)
:| # func 3856 0.468 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x143)
:| # event tick@972129 3856 0.396 xntimer_next_local_shot+0xbd (xntimer_tick_aperiodic+0x143)
:| # func 3857 0.408 ipipe_timer_set+0x9 (xntimer_next_local_shot+0xc4)
:| # func 3857+ 1.316 lapic_next_event+0x3 (ipipe_timer_set+0x77)
:| # func 3858 0.427 xnintr_host_tick+0x4 (xnintr_clock_handler+0x151)
:| # func 3859 0.881 __ipipe_set_irq_pending+0x6 (xnintr_host_tick+0x50)
:| +func 3860 0.729 __ipipe_do_sync_pipeline+0x4 (__ipipe_dispatch_irq+0x18c)
:| +func 3860 0.653 __ipipe_do_sync_stage+0x9 (__ipipe_do_sync_pipeline+0x63)
<| #end 0x80000000 3861 0.682 hard_local_irq_enable+0x14 (__ipipe_do_sync_stage+0xbd)
#func 3862 0.444 __ipipe_do_IRQ+0x5 (__ipipe_do_sync_stage+0x137)
#func 3862 0.487 __ipipe_get_ioapic_irq_vector+0x3 (__ipipe_do_IRQ+0x1d)
#func 3863 0.417 smp_apic_timer_interrupt+0x5 (__ipipe_do_IRQ+0x42)
#func 3863 0.470 irq_enter+0x4 (smp_apic_timer_interrupt+0x21)
| #begin 0x80000001 3863 0.000 debug_smp_processor_id+0x36 (irq_enter+0xe)
-------------- next part --------------
I-pipe trace results
--------------------
[parameters]
enable = 1
verbose = 1
pre_trace_points = 10
back_trace_points = 100
post_trace_points = 10
[frozen]
I-pipe frozen back-tracing service on 3.5.7-trace/ipipe release #3
------------------------------------------------------------
CPU: 0, Freeze: 2155918028459 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.078 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)
:| # func -123 0.345 xnpod_suspend_thread+0x9 (xnpod_wait_thread_period+0x7b)
:| # func -123 0.394 __xnpod_schedule+0x9 (xnpod_schedule+0x32)
:| # [ 1205] -<?>- 99 -122 0.314 __xnpod_schedule+0x69 (xnpod_schedule+0x32)
:| # func -122 0.636 xnsched_pick_next+0x6 (__xnpod_schedule+0xae)
:| # func -121 0.710 __switch_to+0x9 (__xnpod_schedule+0x3c6)
:| # [ 0] -<?>- -1 -121 0.863 __xnpod_schedule+0x43e (xnintr_clock_handler+0x124)
:| +func -120 0.478 __ipipe_do_sync_pipeline+0x4 (__ipipe_dispatch_irq+0x18c)
:| +end 0x000000ef -119 0.740 apic_timer_interrupt+0x4f (__ipipe_halt_root+0x4e)
:| +begin 0x80000001 -119 0.335 debug_smp_processor_id+0x36 (default_idle+0x5f)
:| +end 0x80000001 -118 0.346 debug_smp_processor_id+0x82 (default_idle+0x5f)
:| +begin 0x80000001 -118 0.330 debug_smp_processor_id+0x36 (default_idle+0x69)
:| +end 0x80000001 -118 0.335 debug_smp_processor_id+0x82 (default_idle+0x69)
: +func -117 0.337 rcu_idle_exit+0x9 (cpu_idle+0x62)
:| #begin 0x80000001 -117 0.341 debug_smp_processor_id+0x36 (rcu_idle_exit+0x4b)
:| #end 0x80000001 -116 0.320 debug_smp_processor_id+0x82 (rcu_idle_exit+0x4b)
: #func -116 0.340 rcu_idle_exit_common+0x5 (rcu_idle_exit+0xaa)
:| #begin 0x80000001 -116 0.315 debug_smp_processor_id+0x36 (rcu_idle_exit_common+0x39)
:| #end 0x80000001 -116 0.312 debug_smp_processor_id+0x82 (rcu_idle_exit_common+0x39)
: #func -115 0.288 ipipe_restore_root+0x4 (arch_local_irq_restore+0x11)
: #func -115 0.263 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
:| #begin 0x80000001 -115 0.369 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -114 0.322 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -114 0.246 ipipe_unstall_root+0x3 (ipipe_restore_root+0x2e)
:| #begin 0x80000000 -114 0.317 hard_local_irq_disable+0x15 (ipipe_unstall_root+0xd)
:| #func -113 0.415 ipipe_root_only+0x5 (ipipe_unstall_root+0x12)
:| +end 0x80000000 -113 0.299 hard_local_irq_enable+0x14 (ipipe_unstall_root+0x2b)
:| +begin 0x80000001 -113 0.324 debug_smp_processor_id+0x36 (cpu_idle+0x2b)
:| +end 0x80000001 -112 0.322 debug_smp_processor_id+0x82 (cpu_idle+0x2b)
: +func -112 0.300 local_touch_nmi+0x3 (cpu_idle+0x3f)
: #func -112 0.322 rcu_idle_enter+0x9 (cpu_idle+0x57)
:| #begin 0x80000001 -111 0.321 debug_smp_processor_id+0x36 (rcu_idle_enter+0x4b)
:| #end 0x80000001 -111 0.310 debug_smp_processor_id+0x82 (rcu_idle_enter+0x4b)
: #func -111 0.263 rcu_idle_enter_common+0x6 (rcu_idle_enter+0xb0)
:| #begin 0x80000001 -111 0.332 debug_smp_processor_id+0x36 (rcu_idle_enter_common+0x79)
:| #end 0x80000001 -110 0.321 debug_smp_processor_id+0x82 (rcu_idle_enter_common+0x79)
: #func -110 0.262 ipipe_restore_root+0x4 (arch_local_irq_restore+0x11)
: #func -110 0.249 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
:| #begin 0x80000001 -109 0.372 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
:| #end 0x80000001 -109 0.326 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
: #func -109 0.266 default_idle+0x3 (cpu_idle+0x5d)
:| #begin 0x80000001 -108 0.317 debug_smp_processor_id+0x36 (default_idle+0xd)
:| #end 0x80000001 -108 0.314 debug_smp_processor_id+0x82 (default_idle+0xd)
:| #begin 0x80000001 -108 0.347 debug_smp_processor_id+0x36 (default_idle+0x1e)
:| #end 0x80000001 -107 0.379 debug_smp_processor_id+0x82 (default_idle+0x1e)
: #func -107 0.259 __ipipe_halt_root+0x3 (default_idle+0x48)
:| #begin 0x80000000 -107 0.334 __ipipe_halt_root+0x1a (default_idle+0x48)
:| +end 0x8000000e -106! 68.184 __ipipe_halt_root+0x4c (default_idle+0x48)
:| +begin 0x000000ef -38 0.326 apic_timer_interrupt+0x37 (__ipipe_halt_root+0x4e)
:| +func -38 0.355 __ipipe_handle_irq+0x9 (apic_timer_interrupt+0x3e)
:| +func -38+ 2.057 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| +func -36 0.478 __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0xa4)
:| +func -35 0.560 lapic_itimer_ack+0x3 (__ipipe_ack_hrtimer_irq+0x59)
:| # func -34 0.622 xnintr_clock_handler+0x5 (__ipipe_dispatch_irq+0x14d)
:| # func -34 0.378 xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x97)
:| # func -33 0.344 xnthread_periodic_handler+0x3 (xntimer_tick_aperiodic+0x78)
:| # func -33 0.437 xnpod_resume_thread+0x9 (xnthread_periodic_handler+0x20)
:| # [ 1205] -<?>- 99 -33 0.640 xnpod_resume_thread+0x4a (xnthread_periodic_handler+0x20)
:| # func -32 0.518 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x143)
:| # event tick@-31 -32 0.338 xntimer_next_local_shot+0xbd (xntimer_tick_aperiodic+0x143)
:| # func -31 0.747 ipipe_timer_set+0x9 (xntimer_next_local_shot+0xc4)
:| # func -30 0.627 ipipe_raise_irq+0x8 (ipipe_timer_set+0x82)
:| # func -30 0.948 __ipipe_handle_irq+0x9 (ipipe_raise_irq+0x2b)
:| # func -29 0.899 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| # func -28+ 1.301 __ipipe_set_irq_pending+0x6 (__ipipe_dispatch_irq+0x112)
:| # func -27 0.653 __xnpod_schedule+0x9 (xnintr_clock_handler+0x124)
:| # func -26+ 6.431 __xnlock_spin+0x9 (T.1349+0x55)
:| # [ 0] -<?>- -1 -20 0.412 __xnpod_schedule+0x69 (xnintr_clock_handler+0x124)
:| # func -19 0.828 xnsched_pick_next+0x6 (__xnpod_schedule+0xae)
:| # func -18+ 1.197 __switch_to+0x9 (__xnpod_schedule+0x3c6)
:| # [ 1205] -<?>- 99 -17 0.793 __xnpod_schedule+0x43e (xnpod_schedule+0x32)
:| # func -16 0.626 xntimer_get_overruns+0x9 (xnpod_wait_thread_period+0xa8)
:| # func -16 0.614 __ipipe_restore_head+0x4 (ipipe_restore_pipeline_head+0x4d)
:| + func -15 0.707 __ipipe_do_sync_stage+0x9 (__ipipe_sync_pipeline+0x2e)
:| # func -14 0.639 xnintr_clock_handler+0x5 (__ipipe_do_sync_stage+0xd5)
:| # func -14 0.422 xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0x97)
:| # func -13 0.643 xnsched_watchdog_handler+0x5 (xntimer_tick_aperiodic+0x78)
:| # func -13 0.388 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x143)
:| # event tick@58 -12 0.379 xntimer_next_local_shot+0xbd (xntimer_tick_aperiodic+0x143)
:| # func -12 0.425 ipipe_timer_set+0x9 (xntimer_next_local_shot+0xc4)
:| # func -11 0.852 lapic_next_event+0x3 (ipipe_timer_set+0x77)
:| + end 0x80000000 -11 0.680 hard_local_irq_enable+0x14 (__ipipe_restore_head+0x66)
:| + begin 0x80000001 -10 0.562 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6a)
:| + end 0x80000001 -9 0.456 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xc5)
:| + begin 0x80000001 -9+ 1.795 hard_local_irq_save+0x16 (__ipipe_syscall_root+0x35)
: + func -7 0.398 __ipipe_syscall_root+0x6 (sysenter_past_esp+0x55)
: + func -7 0.408 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
:| + begin 0x80000001 -6 0.524 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
:| + end 0x80000001 -6 0.392 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
: + func -5 0.373 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
:| + begin 0x80000001 -5 0.391 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
:| + end 0x80000001 -5 0.423 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
: + func -4 0.567 hisyscall_event+0x9 (ipipe_syscall_hook+0x88)
: + func -4 0.456 xnshadow_sys_trace+0x6 (hisyscall_event+0x11b)
: + func -3 0.395 ipipe_trace_frozen_reset+0x6 (xnshadow_sys_trace+0x5c)
: + func -3 0.384 __ipipe_global_path_lock+0x9 (ipipe_trace_frozen_reset+0x1a)
: + func -2+ 1.048 __ipipe_spin_lock_irqsave+0x5 (__ipipe_global_path_lock+0x1d)
:| + begin 0x80000001 -1+ 1.176 hard_local_irq_save+0x16 (__ipipe_spin_lock_irqsave+0x11)
:| # func 0 0.367 __ipipe_spin_unlock_irqcomplete+0x4 (__ipipe_global_path_unlock+0x62)
:| + end 0x80000001 0 0.333 hard_local_irq_restore+0x15 (__ipipe_spin_unlock_irqcomplete+0x24)
< + freeze 0x00007222 0 0.356 xnshadow_sys_trace+0x65 (hisyscall_event+0x11b)
| + begin 0x80000001 0 0.353 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6a)
| + end 0x80000001 0 0.378 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xc5)
| + begin 0x80000001 1 1.140 hard_local_irq_save+0x16 (__ipipe_syscall_root+0x35)
+ func 2 0.256 __ipipe_syscall_root+0x6 (sysenter_past_esp+0x55)
+ func 2 0.335 __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x2e)
| + begin 0x80000001 2 0.371 hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
| + end 0x80000001 3 0.305 hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x58)
+ func 3 0.253 ipipe_syscall_hook+0x9 (__ipipe_notify_syscall+0x63)
| + begin 0x80000001 3 0.303 ipipe_syscall_hook+0x2b (__ipipe_notify_syscall+0x63)
| + end 0x80000001 4 0.000 ipipe_syscall_hook+0x75 (__ipipe_notify_syscall+0x63)
[max]
I-pipe worst-case tracing service on 3.5.7-trace/ipipe release #3
-------------------------------------------------------------
CPU: 0, Begin: 1681313869013 cycles, Trace Points: 8 (-10/+5), Length: 3884 us
Calibrated minimum trace-point overhead: 0.078 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)
#func -4 0.333 ipipe_root_only+0x5 (ipipe_restore_root+0x10)
| #begin 0x80000001 -3 0.449 hard_local_irq_save+0x16 (ipipe_root_only+0xf)
| #end 0x80000001 -3 0.431 hard_local_irq_restore+0x15 (ipipe_root_only+0x40)
#func -2 0.426 default_idle+0x3 (cpu_idle+0x5d)
| #begin 0x80000001 -2 0.388 debug_smp_processor_id+0x36 (default_idle+0xd)
| #end 0x80000001 -2 0.412 debug_smp_processor_id+0x82 (default_idle+0xd)
| #begin 0x80000001 -1 0.434 debug_smp_processor_id+0x36 (default_idle+0x1e)
| #end 0x80000001 -1 0.461 debug_smp_processor_id+0x82 (default_idle+0x1e)
#func 0 0.353 __ipipe_halt_root+0x3 (default_idle+0x48)
| #begin 0x80000000 0 0.443 __ipipe_halt_root+0x1a (default_idle+0x48)
>| +end 0x8000000e 0! 3880.483 __ipipe_halt_root+0x4c (default_idle+0x48)
:| +func 3880 0.532 __ipipe_handle_irq+0x9 (reschedule_interrupt+0x3e)
:| +func 3881 0.422 __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xba)
:| +func 3881 0.605 __ipipe_ack_apic+0x3 (__ipipe_dispatch_irq+0xa4)
:| +func 3882 0.756 __ipipe_set_irq_pending+0x6 (__ipipe_dispatch_irq+0x19a)
:| +func 3882 0.689 __ipipe_do_sync_pipeline+0x4 (__ipipe_sync_pipeline+0x1c)
:| +func 3883 0.545 __ipipe_do_sync_stage+0x9 (__ipipe_do_sync_pipeline+0x63)
<| #end 0x80000000 3884 0.600 hard_local_irq_enable+0x14 (__ipipe_do_sync_stage+0xbd)
#func 3884 0.393 __ipipe_do_IRQ+0x5 (__ipipe_do_sync_stage+0x137)
#func 3885 0.481 __ipipe_get_ioapic_irq_vector+0x3 (__ipipe_do_IRQ+0x1d)
#func 3885 0.621 smp_reschedule_interrupt+0x3 (__ipipe_do_IRQ+0x42)
#func 3886 0.383 scheduler_ipi+0x4 (smp_reschedule_interrupt+0x14)
| #begin 0x80000001 3886 0.000 debug_smp_processor_id+0x36 (scheduler_ipi+0x13)
next prev parent reply other threads:[~2013-03-26 10:18 UTC|newest]
Thread overview: 12+ messages / expand[flat|nested] mbox.gz Atom feed top
2013-03-19 20:14 [Xenomai] Decrease Latency (below 10 us) on x32 or x32_64? Manuel Huber
2013-03-19 20:46 ` Gilles Chanteperdrix
2013-03-26 10:18 ` Manuel Huber [this message]
2013-03-26 11:57 ` Gilles Chanteperdrix
2013-03-28 10:06 ` Manuel Huber
2013-03-28 12:46 ` Gilles Chanteperdrix
2013-03-28 13:04 ` Manuel Huber
2013-03-28 20:24 ` Gilles Chanteperdrix
2013-04-02 17:49 ` Manuel Huber
2013-04-02 22:20 ` Gilles Chanteperdrix
2013-04-13 16:42 ` Gilles Chanteperdrix
2013-04-18 5:51 ` Manuel Huber
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=515175FA.4030901@gmail.com \
--to=manuel.h87@gmail.com \
--cc=gilles.chanteperdrix@xenomai.org \
--cc=xenomai@xenomai.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.