From: edward.robbins@domain.hid
To: Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org>
Cc: xenomai@xenomai.org
Subject: Re: [Xenomai-help] Very high latencies under stress testing
Date: Sat, 23 Oct 2010 14:45:13 +0100 (BST) [thread overview]
Message-ID: <1287841513.64613295@domain.hid> (raw)
In-Reply-To: <4CC2C8AB.70708@domain.hid>
[-- Attachment #1: Type: text/plain, Size: 888 bytes --]
Argh.. okay. Something is still wrong..very wrong..and went wrong fairly early in the test I think. Latencies went up to around 4500. I've attached a trace. Any clues?
Edward
On Saturday, 23 October, 2010 12:36pm, "Gilles Chanteperdrix" <gilles.chanteperdrix@xenomai.org> said:
> edward.robbins@domain.hid wrote:
>> Yep, sorry the words got to the keyboard bypassing my brain... it's built
>> already...
>
> So, you are all set-up I guess. In one terminal, launch latency, in
> another terminal, launch dohell. When, in that second terminal, you see:
>
> Listening on any address 5566
>
> From another computer, run:
> netcat the-box-where-dohell-runs 5566 > /dev/null
>
> We can probably do something simpler with the inetd "discard" service,
> but I have not tried yet.
>
> --
> Gilles.
>
[-- Attachment #2: ipipe_trace.txt --]
[-- Type: text/plain, Size: 11083 bytes --]
I-pipe frozen back-tracing service on 2.6.32.15-xenomai-2.5.4/ipipe-2.7-01
------------------------------------------------------------
CPU: 0, Freeze: 35710222406884 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)
:| #begin 0x80000000 -4505 0.251 __ipipe_unstall_root+0x20 (__ipipe_restore_root+0xb1)
:| +end 0x80000000 -4504 0.210 __ipipe_unstall_root+0xce (__ipipe_restore_root+0xb1)
: +func -4504 0.225 file_free_rcu+0x9 (__rcu_process_callbacks+0x1ee)
: +func -4504 0.202 kmem_cache_free+0x11 (file_free_rcu+0x33)
: +func -4504 0.195 ipipe_check_context+0x11 (kmem_cache_free+0x29)
:| +begin 0x80000001 -4503 0.251 ipipe_check_context+0x33 (kmem_cache_free+0x29)
:| +end 0x80000001 -4503 0.236 ipipe_check_context+0xda (kmem_cache_free+0x29)
:| #begin 0x80000001 -4503 0.236 debug_smp_processor_id+0x44 (kmem_cache_free+0x57)
:| #end 0x80000001 -4503 0.217 debug_smp_processor_id+0x94 (kmem_cache_free+0x57)
: #func -4502 0.206 __ipipe_restore_root+0xb (kmem_cache_free+0x231)
:| #begin 0x80000001 -4502 0.225 __ipipe_restore_root+0x2d (kmem_cache_free+0x231)
:| #end 0x80000001 -4502 0.202 __ipipe_restore_root+0x7d (kmem_cache_free+0x231)
: #func -4502 0.199 __ipipe_unstall_root+0x9 (__ipipe_restore_root+0xb1)
:| #begin 0x80000000 -4502 0.255 __ipipe_unstall_root+0x20 (__ipipe_restore_root+0xb1)
:| +end 0x80000000 -4501 0.217 __ipipe_unstall_root+0xce (__ipipe_restore_root+0xb1)
: +func -4501 0.198 ipipe_check_context+0x11 (__rcu_process_callbacks+0x20e)
:| +begin 0x80000001 -4501 0.240 ipipe_check_context+0x33 (__rcu_process_callbacks+0x20e)
:| +end 0x80000001 -4501 0.274 ipipe_check_context+0xda (__rcu_process_callbacks+0x20e)
: #func -4500 0.198 __ipipe_restore_root+0xb (__rcu_process_callbacks+0x309)
:| #begin 0x80000001 -4500 0.221 __ipipe_restore_root+0x2d (__rcu_process_callbacks+0x309)
:| #end 0x80000001 -4500 0.228 __ipipe_restore_root+0x7d (__rcu_process_callbacks+0x309)
: #func -4500 0.187 __ipipe_unstall_root+0x9 (__ipipe_restore_root+0xb1)
:| #begin 0x80000000 -4500 0.236 __ipipe_unstall_root+0x20 (__ipipe_restore_root+0xb1)
:| +end 0x80000000 -4499 0.221 __ipipe_unstall_root+0xce (__ipipe_restore_root+0xb1)
: +func -4499 0.191 raise_softirq+0x7 (__rcu_process_callbacks+0x31a)
: +func -4499 0.198 ipipe_check_context+0x11 (raise_softirq+0x1a)
:| +begin 0x80000001 -4499 0.251 ipipe_check_context+0x33 (raise_softirq+0x1a)
:| +end 0x80000001 -4499 0.243 ipipe_check_context+0xda (raise_softirq+0x1a)
: #func -4498 0.195 __ipipe_restore_root+0xb (raise_softirq+0x86)
:| #begin 0x80000001 -4498 0.236 __ipipe_restore_root+0x2d (raise_softirq+0x86)
:| #end 0x80000001 -4498 0.202 __ipipe_restore_root+0x7d (raise_softirq+0x86)
: #func -4498 0.187 __ipipe_unstall_root+0x9 (__ipipe_restore_root+0xb1)
:| #begin 0x80000000 -4497 0.236 __ipipe_unstall_root+0x20 (__ipipe_restore_root+0xb1)
:| +end 0x80000000 -4497 0.217 __ipipe_unstall_root+0xce (__ipipe_restore_root+0xb1)
:| +begin 0x80000001 -4497 0.225 debug_smp_processor_id+0x44 (rcu_process_callbacks+0x42)
:| +end 0x80000001 -4497 0.217 debug_smp_processor_id+0x94 (rcu_process_callbacks+0x42)
: +func -4497 0.206 __rcu_process_callbacks+0x11 (rcu_process_callbacks+0x5b)
: +func -4496 0.198 force_quiescent_state+0x11 (__rcu_process_callbacks+0x6c)
: +func -4496 0.191 rcu_process_gp_end+0xd (__rcu_process_callbacks+0x78)
: +func -4496 0.187 ipipe_check_context+0x11 (rcu_process_gp_end+0x21)
:| +begin 0x80000001 -4496 0.247 ipipe_check_context+0x33 (rcu_process_gp_end+0x21)
:| +end 0x80000001 -4496 0.243 ipipe_check_context+0xda (rcu_process_gp_end+0x21)
: #func -4495 0.187 __ipipe_restore_root+0xb (rcu_process_gp_end+0x79)
:| #begin 0x80000001 -4495 0.236 __ipipe_restore_root+0x2d (rcu_process_gp_end+0x79)
:| #end 0x80000001 -4495 0.210 __ipipe_restore_root+0x7d (rcu_process_gp_end+0x79)
: #func -4495 0.187 __ipipe_unstall_root+0x9 (__ipipe_restore_root+0xb1)
:| #begin 0x80000000 -4494 0.240 __ipipe_unstall_root+0x20 (__ipipe_restore_root+0xb1)
:| +end 0x80000000 -4494 0.221 __ipipe_unstall_root+0xce (__ipipe_restore_root+0xb1)
: +func -4494 0.195 check_for_new_grace_period+0xb (__rcu_process_callbacks+0x84)
: +func -4494! 4474.777 ipipe_check_context+0x11 (check_for_new_grace_period+0x22)
:| +begin 0x000000f6 -19 0.228 common_interrupt+0x20 (__ipipe_trace+0x729)
:| +func -19 0.251 __ipipe_handle_irq+0x11 (common_interrupt+0x27)
:| +func -19 0.202 irq_to_desc+0x4 (__ipipe_handle_irq+0x134)
:| +func -18 0.195 __ipipe_ack_apic+0x4 (__ipipe_handle_irq+0x13c)
:| +func -18 0.228 native_apic_mem_write+0x4 (__ipipe_ack_apic+0x1d)
:| +func -18 0.221 __ipipe_dispatch_wired+0xd (__ipipe_handle_irq+0x147)
:| +func -18 0.270 __ipipe_dispatch_wired_nocheck+0x11 (__ipipe_dispatch_wired+0xba)
:| # func -17 0.240 xnintr_clock_handler+0xb (__ipipe_dispatch_wired_nocheck+0x12b)
:| # func -17 0.243 xntimer_tick_aperiodic+0xb (xnintr_clock_handler+0x81)
:| # func -17 0.202 xnthread_periodic_handler+0x4 (xntimer_tick_aperiodic+0x8d)
:| # func -17 0.221 xnpod_resume_thread+0x11 (xnthread_periodic_handler+0x2d)
:| # [31843] -<?>- 99 -17 0.461 xnpod_resume_thread+0xfa (xnthread_periodic_handler+0x2d)
:| # func -16 0.206 xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x191)
:| # event tick@25 -16 0.210 xntimer_next_local_shot+0xb0 (xntimer_tick_aperiodic+0x191)
:| # func -16 0.251 native_apic_mem_write+0x4 (xntimer_next_local_shot+0xe5)
:| # func -15 0.274 __xnpod_schedule+0x11 (xnintr_clock_handler+0x130)
:| # [17400] -<?>- -1 -15 0.221 __xnpod_schedule+0x189 (xnintr_clock_handler+0x130)
:| # func -15 0.409 xnsched_pick_next+0x4 (__xnpod_schedule+0x1e3)
:| # func -14 0.536 __phys_addr+0x4 (__xnpod_schedule+0x562)
:| # [31843] -<?>- 99 -14 0.375 __xnpod_schedule+0x834 (xnpod_suspend_thread+0x281)
:| # func -14 0.247 xntimer_get_overruns+0x8 (xnpod_wait_thread_period+0x14c)
:| # func -13 0.214 __ipipe_restore_pipeline_head+0x7 (xnpod_wait_thread_period+0x1cb)
:| + end 0x80000000 -13 0.521 __ipipe_restore_pipeline_head+0x137 (xnpod_wait_thread_period+0x1cb)
:| + begin 0x00000039 -13 0.244 common_interrupt+0x20 (__ipipe_restore_pipeline_head+0x139)
:| + func -12 0.656 __ipipe_handle_irq+0x11 (common_interrupt+0x27)
:| + func -12 0.337 __ipipe_set_irq_pending+0xd (__ipipe_handle_irq+0x173)
:| + func -11 0.304 irq_to_desc+0x4 (__ipipe_handle_irq+0x18b)
:| + func -11 0.401 __ipipe_ack_fasteoi_irq+0x4 (__ipipe_handle_irq+0x194)
:| + func -11 0.292 ack_apic_level+0xd (__ipipe_ack_fasteoi_irq+0x10)
:| + func -10 0.394 native_apic_mem_read+0x4 (ack_apic_level+0x4d)
:| + func -10+ 2.134 io_apic_modify_irq+0xb (ack_apic_level+0xb6)
:| + func -8+ 1.432 io_apic_sync+0x4 (io_apic_modify_irq+0x9e)
:| + func -6 0.296 native_apic_mem_write+0x4 (ack_apic_level+0xd0)
:| + end 0x00000039 -6 0.468 common_interrupt+0x39 (__ipipe_restore_pipeline_head+0x139)
:| + begin 0x80000001 -6 0.262 __ipipe_dispatch_event+0x1d9 (__ipipe_syscall_root+0xcd)
:| + end 0x80000001 -5 0.214 __ipipe_dispatch_event+0x3f0 (__ipipe_syscall_root+0xcd)
:| + begin 0x80000001 -5+ 1.488 __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
: + func -4 0.210 __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
: + func -3 0.195 __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
:| + begin 0x80000001 -3 0.262 __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
:| + end 0x80000001 -3 0.199 __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
: + func -3 0.570 hisyscall_event+0x11 (__ipipe_dispatch_event+0x1b7)
: + func -2 0.371 xnshadow_sys_trace+0x7 (hisyscall_event+0x151)
: + func -2 0.337 ipipe_trace_frozen_reset+0xb (xnshadow_sys_trace+0x69)
: + func -2 0.202 __ipipe_global_path_lock+0x4 (ipipe_trace_frozen_reset+0x1c)
: + func -1 0.199 __ipipe_spin_lock_irqsave+0xb (__ipipe_global_path_lock+0x15)
:| + begin 0x80000001 -1+ 1.110 __ipipe_spin_lock_irqsave+0x2a (__ipipe_global_path_lock+0x15)
:| # func 0 0.273 __ipipe_spin_unlock_irqcomplete+0xb (__ipipe_global_path_unlock+0x7d)
:| + end 0x80000001 0 0.244 __ipipe_spin_unlock_irqcomplete+0xcf (__ipipe_global_path_unlock+0x7d)
< + freeze 0x00442d3e 0 0.266 xnshadow_sys_trace+0x73 (hisyscall_event+0x151)
| + begin 0x80000001 0 0.270 __ipipe_dispatch_event+0x1d9 (__ipipe_syscall_root+0xcd)
| + end 0x80000001 0 0.229 __ipipe_dispatch_event+0x3f0 (__ipipe_syscall_root+0xcd)
| + begin 0x80000001 0 0.386 __ipipe_syscall_root+0xec (__ipipe_syscall_root_thunk+0x35)
+ func 1 0.214 __ipipe_syscall_root+0x11 (__ipipe_syscall_root_thunk+0x35)
+ func 1 0.198 __ipipe_dispatch_event+0x11 (__ipipe_syscall_root+0xcd)
| + begin 0x80000001 1 0.277 __ipipe_dispatch_event+0x34 (__ipipe_syscall_root+0xcd)
| + end 0x80000001 1 0.225 __ipipe_dispatch_event+0x1a6 (__ipipe_syscall_root+0xcd)
+ func 2 0.225 hisyscall_event+0x11 (__ipipe_dispatch_event+0x1b7)
+ func 2 0.187 __rt_task_wait_period+0xb (hisyscall_event+0x151)
+ func 2 0.000 rt_task_wait_period+0x4 (__rt_task_wait_period+0x1c)
next prev parent reply other threads:[~2010-10-23 13:45 UTC|newest]
Thread overview: 38+ messages / expand[flat|nested] mbox.gz Atom feed top
2010-08-13 14:17 [Xenomai-help] Very high latencies under stress testing edward.robbins
2010-08-13 14:35 ` Gilles Chanteperdrix
2010-08-16 12:13 ` edward.robbins
2010-08-16 12:32 ` Gilles Chanteperdrix
2010-09-03 16:30 ` edward.robbins
2010-09-04 8:51 ` Philippe Gerum
2010-10-15 9:21 ` edward.robbins
2010-10-15 11:54 ` edward.robbins
2010-10-15 13:51 ` Gilles Chanteperdrix
2010-10-15 14:13 ` edward.robbins
2010-10-15 14:25 ` Gilles Chanteperdrix
2010-10-15 14:33 ` Philippe Gerum
2010-10-19 13:52 ` edward.robbins
2010-10-19 20:01 ` Gilles Chanteperdrix
2010-10-23 11:08 ` edward.robbins
2010-10-23 11:13 ` Gilles Chanteperdrix
2010-10-23 11:22 ` edward.robbins
2010-10-23 11:36 ` Gilles Chanteperdrix
2010-10-23 13:45 ` edward.robbins [this message]
2010-10-23 13:51 ` Gilles Chanteperdrix
2010-10-23 13:56 ` edward.robbins
2010-10-23 13:58 ` Gilles Chanteperdrix
2010-10-23 14:32 ` edward.robbins
2010-10-23 14:37 ` Gilles Chanteperdrix
2010-10-23 14:48 ` edward.robbins
2010-10-23 15:16 ` edward.robbins
2010-10-23 14:10 ` Gilles Chanteperdrix
2010-08-13 14:40 ` Philippe Gerum
2010-08-13 16:15 ` Philippe Gerum
-- strict thread matches above, loose matches on Subject: below --
2010-10-23 14:54 edward.robbins
2010-10-23 15:37 ` Gilles Chanteperdrix
2010-10-23 16:21 ` edward.robbins
2010-10-23 16:26 ` edward.robbins
2010-10-23 18:46 ` edward.robbins
2010-10-23 21:52 ` Gilles Chanteperdrix
2010-10-24 15:55 ` edward.robbins
2010-10-23 16:13 ` Gilles Chanteperdrix
2010-10-23 16:22 ` Gilles Chanteperdrix
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=1287841513.64613295@domain.hid \
--to=edward.robbins@domain.hid \
--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.