* [Xenomai-core] I-pipe latency tracer for ppc
@ 2006-04-26 22:13 Philippe Gerum
2006-05-01 18:44 ` Wolfgang Grandegger
0 siblings, 1 reply; 6+ messages in thread
From: Philippe Gerum @ 2006-04-26 22:13 UTC (permalink / raw)
To: xenomai; +Cc: adeos-main
As promised, the I-pipe tracer has been ported to ppc. People working on
this architecture are invited to give it a try, it's a great tool to
find out where the cycles are actually going.
Just apply the tracer patch on top of the Adeos patch bearing the same
revision number, and select the feature from the kernel configuration.
If you happen to have some issue while booting the instrumented kernel
on embedded setups (e.g. freeze after kernel decompression), try
reducing the size of the trace log (CONFIG_IPIPE_TRACE_SHIFT).
http://download.gna.org/adeos/patches/v2.6/ppc/tracer/
--
Philippe.
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Xenomai-core] I-pipe latency tracer for ppc
2006-04-26 22:13 [Xenomai-core] I-pipe latency tracer for ppc Philippe Gerum
@ 2006-05-01 18:44 ` Wolfgang Grandegger
2006-05-01 18:58 ` [Adeos-main] " Jan Kiszka
0 siblings, 1 reply; 6+ messages in thread
From: Wolfgang Grandegger @ 2006-05-01 18:44 UTC (permalink / raw)
To: Philippe Gerum; +Cc: adeos-main, xenomai
[-- Attachment #1: Type: text/plain, Size: 1009 bytes --]
Philippe Gerum wrote:
>
> As promised, the I-pipe tracer has been ported to ppc. People working on
> this architecture are invited to give it a try, it's a great tool to
> find out where the cycles are actually going.
>
> Just apply the tracer patch on top of the Adeos patch bearing the same
> revision number, and select the feature from the kernel configuration.
> If you happen to have some issue while booting the instrumented kernel
> on embedded setups (e.g. freeze after kernel decompression), try
> reducing the size of the trace log (CONFIG_IPIPE_TRACE_SHIFT).
>
> http://download.gna.org/adeos/patches/v2.6/ppc/tracer/
I gave it a try on a rather low-end PowerPC Walnut board (AMCC PowerPC
405GP, Rev. E at 200 MHz, 16 kB I-Cache 8 kB D-Cache). A nice tool,
indeed, and it works fine. I have attached the results from running the
Xenomai latency "-t0" test with some load showing latencies up to 140
us. The trace seems not to show any obvious problems, I think.
Thanks.
Wolfgang.
[-- Attachment #2: walnut-latency-trace.log --]
[-- Type: text/x-log, Size: 18799 bytes --]
bash-3.00# cat /proc/ipipe/version
1.3-00
bash-3.00# ./latency -p500
== Sampling period: 500 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
...
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTS| 59.020| 67.260| 138.910| 0| 00:54:31/00:54:31
bash-3.00# cat /proc/ipipe/trace/max
I-pipe worst-case tracing service on 2.6.14/ipipe-1.3-00
------------------------------------------------------------
Begin: 182095500 cycles, Trace Points: 192 (-10/+3), Length: 265 us
+----- Hard IRQs ('|': locked)
|+---- <unused>
||+--- <unused>
|||+-- Xenomai
||||+- Linux ('*': domain stalled)
||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
||||| | +- NMI noise ('N')
||||| | |
Type User Val. Time Delay Function (Parent)
*fn -30 3.465 timer_interrupt+0x14 (__ipipe_do_timer+0x30)
*fn -26 2.430 profile_tick+0x14 (timer_interrupt+0x130)
*fn -24 1.865 profile_hit+0x14 (profile_tick+0x78)
*fn -22 1.700 update_process_times+0x14 (timer_interrupt+0x13c)
*fn -20 3.505 account_system_time+0x14 (update_process_times+0xac)
*fn -17 2.195 update_mem_hiwater+0x14 (account_system_time+0x78)
*fn -15 1.200 run_local_timers+0x14 (update_process_times+0xb0)
*fn -14 11.905 raise_softirq+0x14 (run_local_timers+0x30)
*fn -2 1.200 __ipipe_restore_root+0x14 (raise_softirq+0x84)
*fn -1 1.095 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
>| *begin 0x80000000 0+ 3.950 __ipipe_stall_root+0x98 (__ipipe_restore_root+0x34)
:| *fn 3+ 1.500 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 5+ 4.040 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 9+ 1.160 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 10+ 3.120 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 13+ 2.920 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 16+ 1.500 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 18+ 1.140 profile_hit+0x14 (profile_tick+0x78)
:| *fn 19+ 1.270 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 20+ 1.370 account_system_time+0x14 (update_process_times+0xac)
:| *fn 21+ 1.325 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 23 0.995 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 24+ 1.140 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 25+ 1.350 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 26+ 1.205 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 27+ 1.735 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 29+ 1.160 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 30+ 1.565 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 32+ 1.285 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 33+ 1.560 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 35+ 3.075 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 38+ 1.460 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 39+ 1.300 profile_hit+0x14 (profile_tick+0x78)
:| *fn 40+ 1.035 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 41+ 1.350 account_system_time+0x14 (update_process_times+0xac)
:| *fn 43+ 1.275 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 44+ 1.195 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 45 1.000 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 46+ 1.330 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 48+ 1.155 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 49+ 1.940 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 51+ 1.025 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 52+ 1.525 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 53+ 1.245 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 54+ 1.595 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 56+ 1.635 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 58+ 1.445 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 59+ 1.300 profile_hit+0x14 (profile_tick+0x78)
:| *fn 60+ 1.235 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 62+ 1.210 account_system_time+0x14 (update_process_times+0xac)
:| *fn 63+ 1.255 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 64+ 1.155 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 65+ 1.235 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 66+ 1.195 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 68+ 1.095 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 69+ 1.900 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 71+ 1.225 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 72+ 1.420 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 73+ 1.220 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 74+ 1.545 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 76+ 1.835 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 78+ 1.140 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 79+ 1.275 profile_hit+0x14 (profile_tick+0x78)
:| *fn 80+ 1.195 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 81+ 1.400 account_system_time+0x14 (update_process_times+0xac)
:| *fn 83+ 1.120 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 84+ 1.130 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 85+ 1.160 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 86+ 1.400 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 88 1.000 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 89+ 1.875 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 90+ 1.185 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 92+ 1.615 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 93+ 1.085 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 94+ 1.525 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 96+ 1.795 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 98+ 1.320 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 99+ 1.140 profile_hit+0x14 (profile_tick+0x78)
:| *fn 100+ 1.130 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 101+ 1.370 account_system_time+0x14 (update_process_times+0xac)
:| *fn 103+ 1.325 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 104 0.995 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 105+ 1.140 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 106+ 1.345 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 107+ 1.160 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 108+ 1.735 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 110+ 1.160 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 111+ 1.565 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 113+ 1.265 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 114+ 1.390 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 116+ 1.770 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 117+ 1.295 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 119+ 1.340 profile_hit+0x14 (profile_tick+0x78)
:| *fn 120+ 1.035 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 121+ 1.350 account_system_time+0x14 (update_process_times+0xac)
:| *fn 122+ 1.275 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 124+ 1.195 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 125 1.000 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 126+ 1.325 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 127+ 1.120 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 128+ 1.920 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 130+ 1.025 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 131+ 1.545 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 133+ 1.245 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 134+ 1.595 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 135+ 1.635 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 137+ 1.275 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 138+ 1.300 profile_hit+0x14 (profile_tick+0x78)
:| *fn 140+ 1.235 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 141+ 1.210 account_system_time+0x14 (update_process_times+0xac)
:| *fn 142+ 1.255 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 143+ 1.135 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 144+ 1.210 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 146+ 1.190 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 147+ 1.135 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 148+ 1.900 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 150+ 1.225 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 151+ 1.410 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 153+ 1.220 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 154+ 1.525 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 155+ 1.830 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 157+ 1.135 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 158+ 1.230 profile_hit+0x14 (profile_tick+0x78)
:| *fn 159+ 1.165 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 161+ 1.370 account_system_time+0x14 (update_process_times+0xac)
:| *fn 162+ 1.115 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 163+ 1.090 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 164+ 1.160 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 165+ 1.400 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 167 1.000 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 168+ 2.215 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 170+ 1.185 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 171+ 1.615 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 173+ 1.085 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 174+ 1.525 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 175+ 2.090 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 177+ 1.300 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 179+ 1.135 profile_hit+0x14 (profile_tick+0x78)
:| *fn 180+ 1.170 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 181+ 1.370 account_system_time+0x14 (update_process_times+0xac)
:| *fn 182+ 1.325 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 184 0.995 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 185+ 1.140 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 186+ 1.350 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 187+ 1.205 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 188+ 1.735 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 190+ 1.140 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 191+ 1.565 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 193+ 1.285 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 194+ 1.390 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 195+ 1.770 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 197+ 1.295 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 198+ 1.340 profile_hit+0x14 (profile_tick+0x78)
:| *fn 200+ 1.035 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 201+ 1.350 account_system_time+0x14 (update_process_times+0xac)
:| *fn 202+ 1.275 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 203+ 1.195 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 205 1.000 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 206+ 1.310 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 207+ 1.155 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 208+ 1.940 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 210+ 1.025 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 211+ 1.525 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 213+ 1.245 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 214+ 1.590 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 215+ 1.630 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 217+ 1.235 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 218+ 1.300 profile_hit+0x14 (profile_tick+0x78)
:| *fn 219+ 1.235 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 221+ 1.360 account_system_time+0x14 (update_process_times+0xac)
:| *fn 222+ 1.215 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 223+ 1.155 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 224+ 1.205 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 226+ 1.195 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 227+ 1.090 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 228+ 1.855 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 230+ 1.220 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 231+ 1.405 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 232+ 1.180 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 234+ 1.545 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 235+ 1.835 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 237+ 1.140 profile_tick+0x14 (timer_interrupt+0x130)
:| *fn 238+ 1.255 profile_hit+0x14 (profile_tick+0x78)
:| *fn 239+ 1.195 update_process_times+0x14 (timer_interrupt+0x13c)
:| *fn 240+ 1.420 account_system_time+0x14 (update_process_times+0xac)
:| *fn 242+ 1.120 update_mem_hiwater+0x14 (account_system_time+0x78)
:| *fn 243+ 1.130 run_local_timers+0x14 (update_process_times+0xb0)
:| *fn 244+ 1.155 raise_softirq+0x14 (run_local_timers+0x30)
:| *fn 245+ 1.350 __ipipe_test_and_stall_root+0x14 (raise_softirq+0x30)
:| *fn 247 0.995 __ipipe_restore_root+0x14 (raise_softirq+0x84)
:| *fn 248+ 1.835 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
:| *fn 249+ 1.185 scheduler_tick+0x14 (update_process_times+0x7c)
:| *fn 251+ 1.615 sched_clock+0x14 (scheduler_tick+0x34)
:| *fn 252+ 1.085 run_posix_cpu_timers+0x14 (update_process_times+0x84)
:| *fn 253+ 1.670 __ipipe_test_root+0x14 (run_posix_cpu_timers+0x44)
:| *fn 255+ 2.260 do_timer+0x14 (timer_interrupt+0x154)
:| *fn 257+ 1.920 irq_exit+0x14 (timer_interrupt+0xa4)
:| *fn 259+ 1.240 do_softirq+0x14 (irq_exit+0x6c)
:| *fn 260+ 1.660 __ipipe_test_and_stall_root+0x14 (do_softirq+0x54)
:| *fn 262+ 1.810 __do_softirq+0x14 (do_softirq+0x90)
:| *fn 264+ 1.565 __ipipe_unstall_root+0x14 (__do_softirq+0x64)
<| end 0x80000000 265 1.795 __ipipe_unstall_root+0x70 (__do_softirq+0x64)
fn 267 1.755 run_timer_softirq+0x14 (__do_softirq+0x90)
fn 269 1.310 __ipipe_stall_root+0x14 (run_timer_softirq+0x50)
| *begin 0x80000000 270 0.000 __ipipe_stall_root+0x98 (run_timer_softirq+0x50)
bash-3.00#
bash-3.00#
bash-3.00#
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Adeos-main] Re: [Xenomai-core] I-pipe latency tracer for ppc
2006-05-01 18:44 ` Wolfgang Grandegger
@ 2006-05-01 18:58 ` Jan Kiszka
2006-05-01 19:33 ` Wolfgang Grandegger
0 siblings, 1 reply; 6+ messages in thread
From: Jan Kiszka @ 2006-05-01 18:58 UTC (permalink / raw)
To: Wolfgang Grandegger; +Cc: adeos-main, xenomai
[-- Attachment #1: Type: text/plain, Size: 4213 bytes --]
Wolfgang Grandegger wrote:
> Philippe Gerum wrote:
>>
>> As promised, the I-pipe tracer has been ported to ppc. People working
>> on this architecture are invited to give it a try, it's a great tool
>> to find out where the cycles are actually going.
>>
>> Just apply the tracer patch on top of the Adeos patch bearing the same
>> revision number, and select the feature from the kernel configuration.
>> If you happen to have some issue while booting the instrumented kernel
>> on embedded setups (e.g. freeze after kernel decompression), try
>> reducing the size of the trace log (CONFIG_IPIPE_TRACE_SHIFT).
>>
>> http://download.gna.org/adeos/patches/v2.6/ppc/tracer/
>
> I gave it a try on a rather low-end PowerPC Walnut board (AMCC PowerPC
> 405GP, Rev. E at 200 MHz, 16 kB I-Cache 8 kB D-Cache). A nice tool,
> indeed, and it works fine. I have attached the results from running the
> Xenomai latency "-t0" test with some load showing latencies up to 140
> us. The trace seems not to show any obvious problems, I think.
>
> Thanks.
>
> Wolfgang.
>
>
> ------------------------------------------------------------------------
>
>
> bash-3.00# cat /proc/ipipe/version
> 1.3-00
>
> bash-3.00# ./latency -p500
> == Sampling period: 500 us
> == Test mode: periodic user-mode task
> == All results in microseconds
> warming up...
> ...
> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
> RTS| 59.020| 67.260| 138.910| 0| 00:54:31/00:54:31
>
> bash-3.00# cat /proc/ipipe/trace/max
> I-pipe worst-case tracing service on 2.6.14/ipipe-1.3-00
> ------------------------------------------------------------
> Begin: 182095500 cycles, Trace Points: 192 (-10/+3), Length: 265 us
>
> +----- Hard IRQs ('|': locked)
> |+---- <unused>
> ||+--- <unused>
> |||+-- Xenomai
> ||||+- Linux ('*': domain stalled)
> ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
> ||||| | +- NMI noise ('N')
> ||||| | |
> Type User Val. Time Delay Function (Parent)
> *fn -30 3.465 timer_interrupt+0x14 (__ipipe_do_timer+0x30)
> *fn -26 2.430 profile_tick+0x14 (timer_interrupt+0x130)
> *fn -24 1.865 profile_hit+0x14 (profile_tick+0x78)
> *fn -22 1.700 update_process_times+0x14 (timer_interrupt+0x13c)
> *fn -20 3.505 account_system_time+0x14 (update_process_times+0xac)
> *fn -17 2.195 update_mem_hiwater+0x14 (account_system_time+0x78)
> *fn -15 1.200 run_local_timers+0x14 (update_process_times+0xb0)
> *fn -14 11.905 raise_softirq+0x14 (run_local_timers+0x30)
> *fn -2 1.200 __ipipe_restore_root+0x14 (raise_softirq+0x84)
> *fn -1 1.095 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
>> | *begin 0x80000000 0+ 3.950 __ipipe_stall_root+0x98 (__ipipe_restore_root+0x34)
> :| *fn 3+ 1.500 scheduler_tick+0x14 (update_process_times+0x7c)
> :| *fn 5+ 4.040 sched_clock+0x14 (scheduler_tick+0x34)
This trace covers some long stall of the root domain, not the maximum
stall of the Xenomai domain that caused the 140 us above. See the
explanation for the stall bits above.
Maybe the maximum irq latency tracing is broken, I haven't tested it
with latest ipipe patch revision yet. Well, that max path should not
trigger on root-domain stalls as long as there is some higher priority
domain running - and it should have been reset on xenomai mounting. Hmm,
maybe only that reset does not work, please check by running "echo >
/proc/ipipe/trace/max" before the latency test.
You could also test if the -f option of latency works for you. You will
find the result of the back-trace freezing on max latency under
/proc/ipipe/trace/frozen. The number of back-trace points can be tuned
even after the event (only post-tracing required ahead-of-time tuning).
Jan
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 252 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Adeos-main] Re: [Xenomai-core] I-pipe latency tracer for ppc
2006-05-01 18:58 ` [Adeos-main] " Jan Kiszka
@ 2006-05-01 19:33 ` Wolfgang Grandegger
2006-05-01 21:42 ` Jan Kiszka
0 siblings, 1 reply; 6+ messages in thread
From: Wolfgang Grandegger @ 2006-05-01 19:33 UTC (permalink / raw)
To: Jan Kiszka; +Cc: adeos-main, xenomai
[-- Attachment #1: Type: text/plain, Size: 4404 bytes --]
Jan Kiszka wrote:
> Wolfgang Grandegger wrote:
>> Philippe Gerum wrote:
>>> As promised, the I-pipe tracer has been ported to ppc. People working
>>> on this architecture are invited to give it a try, it's a great tool
>>> to find out where the cycles are actually going.
>>>
>>> Just apply the tracer patch on top of the Adeos patch bearing the same
>>> revision number, and select the feature from the kernel configuration.
>>> If you happen to have some issue while booting the instrumented kernel
>>> on embedded setups (e.g. freeze after kernel decompression), try
>>> reducing the size of the trace log (CONFIG_IPIPE_TRACE_SHIFT).
>>>
>>> http://download.gna.org/adeos/patches/v2.6/ppc/tracer/
>> I gave it a try on a rather low-end PowerPC Walnut board (AMCC PowerPC
>> 405GP, Rev. E at 200 MHz, 16 kB I-Cache 8 kB D-Cache). A nice tool,
>> indeed, and it works fine. I have attached the results from running the
>> Xenomai latency "-t0" test with some load showing latencies up to 140
>> us. The trace seems not to show any obvious problems, I think.
>>
>> Thanks.
>>
>> Wolfgang.
>>
>>
>> ------------------------------------------------------------------------
>>
>>
>> bash-3.00# cat /proc/ipipe/version
>> 1.3-00
>>
>> bash-3.00# ./latency -p500
>> == Sampling period: 500 us
>> == Test mode: periodic user-mode task
>> == All results in microseconds
>> warming up...
>> ...
>> RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
>> RTS| 59.020| 67.260| 138.910| 0| 00:54:31/00:54:31
>>
>> bash-3.00# cat /proc/ipipe/trace/max
>> I-pipe worst-case tracing service on 2.6.14/ipipe-1.3-00
>> ------------------------------------------------------------
>> Begin: 182095500 cycles, Trace Points: 192 (-10/+3), Length: 265 us
>>
>> +----- Hard IRQs ('|': locked)
>> |+---- <unused>
>> ||+--- <unused>
>> |||+-- Xenomai
>> ||||+- Linux ('*': domain stalled)
>> ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
>> ||||| | +- NMI noise ('N')
>> ||||| | |
>> Type User Val. Time Delay Function (Parent)
>> *fn -30 3.465 timer_interrupt+0x14 (__ipipe_do_timer+0x30)
>> *fn -26 2.430 profile_tick+0x14 (timer_interrupt+0x130)
>> *fn -24 1.865 profile_hit+0x14 (profile_tick+0x78)
>> *fn -22 1.700 update_process_times+0x14 (timer_interrupt+0x13c)
>> *fn -20 3.505 account_system_time+0x14 (update_process_times+0xac)
>> *fn -17 2.195 update_mem_hiwater+0x14 (account_system_time+0x78)
>> *fn -15 1.200 run_local_timers+0x14 (update_process_times+0xb0)
>> *fn -14 11.905 raise_softirq+0x14 (run_local_timers+0x30)
>> *fn -2 1.200 __ipipe_restore_root+0x14 (raise_softirq+0x84)
>> *fn -1 1.095 __ipipe_stall_root+0x14 (__ipipe_restore_root+0x34)
>>> | *begin 0x80000000 0+ 3.950 __ipipe_stall_root+0x98 (__ipipe_restore_root+0x34)
>> :| *fn 3+ 1.500 scheduler_tick+0x14 (update_process_times+0x7c)
>> :| *fn 5+ 4.040 sched_clock+0x14 (scheduler_tick+0x34)
>
> This trace covers some long stall of the root domain, not the maximum
> stall of the Xenomai domain that caused the 140 us above. See the
> explanation for the stall bits above.
Ah, some feed for the real experts.
>
> Maybe the maximum irq latency tracing is broken, I haven't tested it
> with latest ipipe patch revision yet. Well, that max path should not
> trigger on root-domain stalls as long as there is some higher priority
> domain running - and it should have been reset on xenomai mounting. Hmm,
> maybe only that reset does not work, please check by running "echo >
> /proc/ipipe/trace/max" before the latency test.
Yes, that changed something. I have attached the new output listing.
> You could also test if the -f option of latency works for you. You will
> find the result of the back-trace freezing on max latency under
> /proc/ipipe/trace/frozen. The number of back-trace points can be tuned
> even after the event (only post-tracing required ahead-of-time tuning).
Seem to work. The output has been added to the attached file.
Wolfgang.
[-- Attachment #2: walnut-latency-trace2.log --]
[-- Type: text/x-log, Size: 8428 bytes --]
bash-3.00# cat /proc/ipipe/trace/max
I-pipe worst-case tracing service on 2.6.14/ipipe-1.3-00
------------------------------------------------------------
Begin: 90358006525 cycles, Trace Points: 25 (-10/+4), Length: 69 us
+----- Hard IRQs ('|': locked)
|+---- <unused>
||+--- <unused>
|||+-- Xenomai
||||+- Linux ('*': domain stalled)
||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
||||| | +- NMI noise ('N')
||||| | |
Type User Val. Time Delay Function (Parent)
fn -25 1.935 schedule+0x14 (syscall_exit_work+0x110)
fn -23 2.075 profile_hit+0x14 (schedule+0x68)
fn -21 2.390 sched_clock+0x14 (schedule+0xa0)
fn -19 4.400 __ipipe_stall_root+0x14 (schedule+0x118)
*fn -14 2.040 __ipipe_dispatch_event+0x14 (schedule+0x300)
| *begin 0x80000001 -12 3.190 __ipipe_dispatch_event+0x240 (schedule+0x300)
| *end 0x80000001 -9 1.990 __ipipe_dispatch_event+0x228 (schedule+0x300)
*fn -7 4.115 schedule_event+0x14 (__ipipe_dispatch_event+0x160)
| *begin 0x80000001 -3 1.835 __ipipe_dispatch_event+0x198 (schedule+0x300)
| *end 0x80000001 -1 1.815 __ipipe_dispatch_event+0x1b8 (schedule+0x300)
>| *begin 0x80000000 0+ 4.715 schedule+0x6ac (syscall_exit_work+0x110)
:| *fn 4+ 1.225 __switch_to+0x14 (schedule+0x358)
:| *fn 5+ 5.025 __ipipe_test_and_stall_root+0x14 (__switch_to+0x30)
: *fn 10+ 1.445 schedule_tail+0x14 (ret_from_fork+0x60)
: *fn 12+ 3.450 __ipipe_unstall_root+0x14 (schedule_tail+0x48)
:| *fn 15+ 1.145 __ipipe_grab_timer+0x14 (__ipipe_ret_from_except+0x0)
:| *begin 0xc00466f4 16+ 1.615 __ipipe_grab_timer+0x34 (__ipipe_ret_from_except+0x0)
:| *fn 18+ 3.665 __ipipe_handle_irq+0x14 (__ipipe_grab_timer+0x4c)
:| *fn 22+ 1.980 __ipipe_walk_pipeline+0x14 (__ipipe_handle_irq+0x174)
:| *fn 24+ 2.540 ipipe_suspend_domain+0x14 (__ipipe_walk_pipeline+0xe4)
:| *fn 26+ 3.600 __ipipe_sync_stage+0x14 (ipipe_suspend_domain+0xa8)
:| **fn 30+ 1.650 xnintr_clock_handler+0x14 (__ipipe_sync_stage+0x1ac)
:| **fn 31+ 2.150 xnintr_irq_handler+0x14 (xnintr_clock_handler+0x38)
:| **fn 34+ 1.980 xnpod_announce_tick+0x14 (xnintr_irq_handler+0x58)
:| **fn 36+ 3.395 xntimer_do_tick_aperiodic+0x14 (xnpod_announce_tick+0x3c)
:| **fn 39+ 1.645 xnthread_periodic_handler+0x14 (xntimer_do_tick_aperiodic+0x2b4)
:| **fn 41+ 1.420 xnpod_resume_thread+0x14 (xnthread_periodic_handler+0x3c)
:| **fn 42+ 4.010 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_resume_thread+0x34)
:| **fn 46+ 4.910 ipipe_restore_pipeline_head+0x14 (xnpod_resume_thread+0x120)
:| **fn 51+ 1.870 xnpod_schedule+0x14 (xnintr_irq_handler+0xf0)
:| **fn 53+ 9.430 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_schedule+0x80)
:| **fn 62+ 2.215 ipipe_restore_pipeline_head+0x14 (xnpod_schedule+0x46c)
:| **fn 64+ 2.865 ipipe_restore_pipeline_head+0x14 (xnpod_suspend_thread+0x94)
:| **fn 67+ 1.945 ipipe_restore_pipeline_head+0x14 (xnpod_wait_thread_period+0x11c)
<| *end 0x80000000 69 7.185 ipipe_restore_pipeline_head+0xbc (xnpod_wait_thread_period+0x11c)
*end 0x80000001 76 10.310 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
*fn 86 1.495 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
*fn 88 1.660 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
| *begin 0x80000001 90 0.000 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
bash-3.00# cat /proc/ipipe/trace/frozen
I-pipe frozen back-tracing service on 2.6.14/ipipe-1.3-00
------------------------------------------------------------
Freeze: 155250522464 cycles, Trace Points: 30 (+10)
+----- Hard IRQs ('|': locked)
|+---- <unused>
||+--- <unused>
|||+-- Xenomai
||||+- Linux ('*': domain stalled)
||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
||||| | +- NMI noise ('N')
||||| | |
Type User Val. Time Delay Function (Parent)
:| *fn -80+ 1.485 __ipipe_ack_irq+0x14 (__ipipe_handle_irq+0x158)
:| *fn -78+ 1.515 ipipe_test_and_stall_pipeline_from+0x14 (__ipipe_ack_irq+0x54)
:| **fn -77+ 1.730 ppc4xx_uic0_ack+0x14 (__ipipe_ack_irq+0x6c)
:| *fn -75+ 1.390 __ipipe_walk_pipeline+0x14 (__ipipe_handle_irq+0x174)
:| *end 0xc0043f18 -74+ 9.065 __ipipe_grab_irq+0x64 (__ipipe_ret_from_except+0x0)
: *end 0x80000001 -65! 10.695 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
: *fn -54+ 1.650 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
: *fn -53+ 1.710 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
:| *begin 0x80000001 -51+ 2.660 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
:| *fn -48+ 4.420 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
:| *fn -44+ 2.540 __rt_timer_tsc2ns+0x14 (hisyscall_event+0x224)
:| *fn -41+ 5.630 rt_timer_tsc2ns+0x14 (__rt_timer_tsc2ns+0x48)
:| *end 0x80000001 -36+ 4.420 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
: *fn -31+ 1.475 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
: *fn -30+ 1.715 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
:| *begin 0x80000001 -28+ 1.960 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
:| *fn -26+ 2.880 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
:| *fn -23+ 1.610 sys_rtdm_ioctl+0x14 (hisyscall_event+0x224)
:| *fn -22+ 2.145 _rtdm_ioctl+0x14 (sys_rtdm_ioctl+0x3c)
:| *fn -20+ 1.325 rtdm_context_get+0x14 (_rtdm_ioctl+0x70)
:| *fn -18+ 2.205 ipipe_test_and_stall_pipeline_head+0x14 (rtdm_context_get+0x58)
:| **fn -16+ 1.630 ipipe_restore_pipeline_head+0x14 (rtdm_context_get+0xcc)
:| *end 0x80000000 -14+ 2.525 ipipe_restore_pipeline_head+0xbc (rtdm_context_get+0xcc)
: *fn -12+ 1.410 rt_tmbench_ioctl_rt+0x14 (_rtdm_ioctl+0xb0)
: *fn -10+ 1.940 tracer_ioctl+0x14 (rt_tmbench_ioctl_rt+0x44)
: *fn -9+ 1.550 ipipe_trace_frozen_reset+0x14 (tracer_ioctl+0x148)
: *fn -7+ 1.600 __ipipe_global_path_lock+0x14 (ipipe_trace_frozen_reset+0x2c)
:| *begin 0x80000001 -5+ 3.920 __ipipe_global_path_lock+0x98 (ipipe_trace_frozen_reset+0x2c)
:| *end 0x80000001 -2+ 2.020 __ipipe_global_path_unlock+0x84 (ipipe_trace_frozen_reset+0x8c)
< *freeze 0x00000000 0 3.980 tracer_ioctl+0x150 (rt_tmbench_ioctl_rt+0x44)
*end 0x80000001 3 4.270 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
*fn 8 1.310 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
*fn 9 1.740 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
| *begin 0x80000001 11 1.690 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
| *fn 12 3.020 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
| *fn 15 1.750 __rt_task_wait_period+0x14 (hisyscall_event+0x224)
| *fn 17 1.760 rt_task_wait_period+0x14 (__rt_task_wait_period+0x44)
| *fn 19 1.385 xnpod_wait_thread_period+0x14 (rt_task_wait_period+0x88)
| *fn 20 2.465 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_wait_thread_period+0x3c)
| **fn 23 0.000 xnpod_suspend_thread+0x14 (xnpod_wait_thread_period+0x9c)
bash-3.00#
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Adeos-main] Re: [Xenomai-core] I-pipe latency tracer for ppc
2006-05-01 19:33 ` Wolfgang Grandegger
@ 2006-05-01 21:42 ` Jan Kiszka
2006-05-02 7:49 ` Philippe Gerum
0 siblings, 1 reply; 6+ messages in thread
From: Jan Kiszka @ 2006-05-01 21:42 UTC (permalink / raw)
To: Philippe Gerum; +Cc: adeos-main, xenomai
[-- Attachment #1: Type: text/plain, Size: 10585 bytes --]
Wolfgang Grandegger wrote:
> Jan Kiszka wrote:
>> Wolfgang Grandegger wrote:
>> ...
>> This trace covers some long stall of the root domain, not the maximum
>> stall of the Xenomai domain that caused the 140 us above. See the
>> explanation for the stall bits above.
>
> Ah, some feed for the real experts.
Indeed :), comments below.
>
>>
>> Maybe the maximum irq latency tracing is broken, I haven't tested it
>> with latest ipipe patch revision yet. Well, that max path should not
>> trigger on root-domain stalls as long as there is some higher priority
>> domain running - and it should have been reset on xenomai mounting. Hmm,
>> maybe only that reset does not work, please check by running "echo >
>> /proc/ipipe/trace/max" before the latency test.
>
> Yes, that changed something. I have attached the new output listing.
>
>> You could also test if the -f option of latency works for you. You will
>> find the result of the back-trace freezing on max latency under
>> /proc/ipipe/trace/frozen. The number of back-trace points can be tuned
>> even after the event (only post-tracing required ahead-of-time tuning).
>
> Seem to work. The output has been added to the attached file.
>
> Wolfgang.
>
>
> ------------------------------------------------------------------------
>
> bash-3.00# cat /proc/ipipe/trace/max
> I-pipe worst-case tracing service on 2.6.14/ipipe-1.3-00
> ------------------------------------------------------------
> Begin: 90358006525 cycles, Trace Points: 25 (-10/+4), Length: 69 us
>
> +----- Hard IRQs ('|': locked)
> |+---- <unused>
> ||+--- <unused>
> |||+-- Xenomai
> ||||+- Linux ('*': domain stalled)
> ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
> ||||| | +- NMI noise ('N')
> ||||| | |
> Type User Val. Time Delay Function (Parent)
> fn -25 1.935 schedule+0x14 (syscall_exit_work+0x110)
> fn -23 2.075 profile_hit+0x14 (schedule+0x68)
> fn -21 2.390 sched_clock+0x14 (schedule+0xa0)
> fn -19 4.400 __ipipe_stall_root+0x14 (schedule+0x118)
> *fn -14 2.040 __ipipe_dispatch_event+0x14 (schedule+0x300)
> | *begin 0x80000001 -12 3.190 __ipipe_dispatch_event+0x240 (schedule+0x300)
> | *end 0x80000001 -9 1.990 __ipipe_dispatch_event+0x228 (schedule+0x300)
> *fn -7 4.115 schedule_event+0x14 (__ipipe_dispatch_event+0x160)
> | *begin 0x80000001 -3 1.835 __ipipe_dispatch_event+0x198 (schedule+0x300)
> | *end 0x80000001 -1 1.815 __ipipe_dispatch_event+0x1b8 (schedule+0x300)
>> | *begin 0x80000000 0+ 4.715 schedule+0x6ac (syscall_exit_work+0x110)
> :| *fn 4+ 1.225 __switch_to+0x14 (schedule+0x358)
> :| *fn 5+ 5.025 __ipipe_test_and_stall_root+0x14 (__switch_to+0x30)
> : *fn 10+ 1.445 schedule_tail+0x14 (ret_from_fork+0x60)
> : *fn 12+ 3.450 __ipipe_unstall_root+0x14 (schedule_tail+0x48)
Instrumentation of the maximum IRQs-off path seems to be broken. The two
functions above were entered with hard-IRQs on, so they should have
interrupted the trace path.
> :| *fn 15+ 1.145 __ipipe_grab_timer+0x14 (__ipipe_ret_from_except+0x0)
> :| *begin 0xc00466f4 16+ 1.615 __ipipe_grab_timer+0x34 (__ipipe_ret_from_except+0x0)
Hmm, the User Value on x86 would contain the IRQ number here. Some
forgotten dereferencing? Looks like a pointer.
> :| *fn 18+ 3.665 __ipipe_handle_irq+0x14 (__ipipe_grab_timer+0x4c)
> :| *fn 22+ 1.980 __ipipe_walk_pipeline+0x14 (__ipipe_handle_irq+0x174)
> :| *fn 24+ 2.540 ipipe_suspend_domain+0x14 (__ipipe_walk_pipeline+0xe4)
> :| *fn 26+ 3.600 __ipipe_sync_stage+0x14 (ipipe_suspend_domain+0xa8)
> :| **fn 30+ 1.650 xnintr_clock_handler+0x14 (__ipipe_sync_stage+0x1ac)
> :| **fn 31+ 2.150 xnintr_irq_handler+0x14 (xnintr_clock_handler+0x38)
> :| **fn 34+ 1.980 xnpod_announce_tick+0x14 (xnintr_irq_handler+0x58)
> :| **fn 36+ 3.395 xntimer_do_tick_aperiodic+0x14 (xnpod_announce_tick+0x3c)
> :| **fn 39+ 1.645 xnthread_periodic_handler+0x14 (xntimer_do_tick_aperiodic+0x2b4)
> :| **fn 41+ 1.420 xnpod_resume_thread+0x14 (xnthread_periodic_handler+0x3c)
> :| **fn 42+ 4.010 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_resume_thread+0x34)
> :| **fn 46+ 4.910 ipipe_restore_pipeline_head+0x14 (xnpod_resume_thread+0x120)
> :| **fn 51+ 1.870 xnpod_schedule+0x14 (xnintr_irq_handler+0xf0)
> :| **fn 53+ 9.430 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_schedule+0x80)
> :| **fn 62+ 2.215 ipipe_restore_pipeline_head+0x14 (xnpod_schedule+0x46c)
> :| **fn 64+ 2.865 ipipe_restore_pipeline_head+0x14 (xnpod_suspend_thread+0x94)
> :| **fn 67+ 1.945 ipipe_restore_pipeline_head+0x14 (xnpod_wait_thread_period+0x11c)
> <| *end 0x80000000 69 7.185 ipipe_restore_pipeline_head+0xbc (xnpod_wait_thread_period+0x11c)
> *end 0x80000001 76 10.310 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
> *fn 86 1.495 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
> *fn 88 1.660 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
> | *begin 0x80000001 90 0.000 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
>
>
>
> bash-3.00# cat /proc/ipipe/trace/frozen
> I-pipe frozen back-tracing service on 2.6.14/ipipe-1.3-00
> ------------------------------------------------------------
> Freeze: 155250522464 cycles, Trace Points: 30 (+10)
>
> +----- Hard IRQs ('|': locked)
> |+---- <unused>
> ||+--- <unused>
> |||+-- Xenomai
> ||||+- Linux ('*': domain stalled)
> ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
> ||||| | +- NMI noise ('N')
> ||||| | |
> Type User Val. Time Delay Function (Parent)
> :| *fn -80+ 1.485 __ipipe_ack_irq+0x14 (__ipipe_handle_irq+0x158)
> :| *fn -78+ 1.515 ipipe_test_and_stall_pipeline_from+0x14 (__ipipe_ack_irq+0x54)
> :| **fn -77+ 1.730 ppc4xx_uic0_ack+0x14 (__ipipe_ack_irq+0x6c)
> :| *fn -75+ 1.390 __ipipe_walk_pipeline+0x14 (__ipipe_handle_irq+0x174)
> :| *end 0xc0043f18 -74+ 9.065 __ipipe_grab_irq+0x64 (__ipipe_ret_from_except+0x0)
> : *end 0x80000001 -65! 10.695 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
> : *fn -54+ 1.650 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
> : *fn -53+ 1.710 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
> :| *begin 0x80000001 -51+ 2.660 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
> :| *fn -48+ 4.420 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
> :| *fn -44+ 2.540 __rt_timer_tsc2ns+0x14 (hisyscall_event+0x224)
> :| *fn -41+ 5.630 rt_timer_tsc2ns+0x14 (__rt_timer_tsc2ns+0x48)
> :| *end 0x80000001 -36+ 4.420 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
> : *fn -31+ 1.475 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
> : *fn -30+ 1.715 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
> :| *begin 0x80000001 -28+ 1.960 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
> :| *fn -26+ 2.880 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
> :| *fn -23+ 1.610 sys_rtdm_ioctl+0x14 (hisyscall_event+0x224)
> :| *fn -22+ 2.145 _rtdm_ioctl+0x14 (sys_rtdm_ioctl+0x3c)
> :| *fn -20+ 1.325 rtdm_context_get+0x14 (_rtdm_ioctl+0x70)
> :| *fn -18+ 2.205 ipipe_test_and_stall_pipeline_head+0x14 (rtdm_context_get+0x58)
> :| **fn -16+ 1.630 ipipe_restore_pipeline_head+0x14 (rtdm_context_get+0xcc)
> :| *end 0x80000000 -14+ 2.525 ipipe_restore_pipeline_head+0xbc (rtdm_context_get+0xcc)
> : *fn -12+ 1.410 rt_tmbench_ioctl_rt+0x14 (_rtdm_ioctl+0xb0)
> : *fn -10+ 1.940 tracer_ioctl+0x14 (rt_tmbench_ioctl_rt+0x44)
> : *fn -9+ 1.550 ipipe_trace_frozen_reset+0x14 (tracer_ioctl+0x148)
> : *fn -7+ 1.600 __ipipe_global_path_lock+0x14 (ipipe_trace_frozen_reset+0x2c)
> :| *begin 0x80000001 -5+ 3.920 __ipipe_global_path_lock+0x98 (ipipe_trace_frozen_reset+0x2c)
> :| *end 0x80000001 -2+ 2.020 __ipipe_global_path_unlock+0x84 (ipipe_trace_frozen_reset+0x8c)
> < *freeze 0x00000000 0 3.980 tracer_ioctl+0x150 (rt_tmbench_ioctl_rt+0x44)
Here we should see the observed latency in User Value, reported with the
ioctl down to the driver, then to ipipe_trace_freeze. 0 indicates some
remaining minor issue here as well.
> *end 0x80000001 3 4.270 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
> *fn 8 1.310 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
> *fn 9 1.740 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
> | *begin 0x80000001 11 1.690 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
> | *fn 12 3.020 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
> | *fn 15 1.750 __rt_task_wait_period+0x14 (hisyscall_event+0x224)
> | *fn 17 1.760 rt_task_wait_period+0x14 (__rt_task_wait_period+0x44)
> | *fn 19 1.385 xnpod_wait_thread_period+0x14 (rt_task_wait_period+0x88)
> | *fn 20 2.465 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_wait_thread_period+0x3c)
> | **fn 23 0.000 xnpod_suspend_thread+0x14 (xnpod_wait_thread_period+0x9c)
> bash-3.00#
>
Jan
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 252 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Adeos-main] Re: [Xenomai-core] I-pipe latency tracer for ppc
2006-05-01 21:42 ` Jan Kiszka
@ 2006-05-02 7:49 ` Philippe Gerum
0 siblings, 0 replies; 6+ messages in thread
From: Philippe Gerum @ 2006-05-02 7:49 UTC (permalink / raw)
To: Jan Kiszka; +Cc: adeos-main, xenomai
Jan Kiszka wrote:
> Wolfgang Grandegger wrote:
>
>>Jan Kiszka wrote:
>>
>>>Wolfgang Grandegger wrote:
>>>...
>>>This trace covers some long stall of the root domain, not the maximum
>>>stall of the Xenomai domain that caused the 140 us above. See the
>>>explanation for the stall bits above.
>>
>>Ah, some feed for the real experts.
>
>
> Indeed :), comments below.
>
>
>>>Maybe the maximum irq latency tracing is broken, I haven't tested it
>>>with latest ipipe patch revision yet. Well, that max path should not
>>>trigger on root-domain stalls as long as there is some higher priority
>>>domain running - and it should have been reset on xenomai mounting. Hmm,
>>>maybe only that reset does not work, please check by running "echo >
>>>/proc/ipipe/trace/max" before the latency test.
>>
>>Yes, that changed something. I have attached the new output listing.
>>
>>
>>>You could also test if the -f option of latency works for you. You will
>>>find the result of the back-trace freezing on max latency under
>>>/proc/ipipe/trace/frozen. The number of back-trace points can be tuned
>>>even after the event (only post-tracing required ahead-of-time tuning).
>>
>>Seem to work. The output has been added to the attached file.
>>
>>Wolfgang.
>>
>>
>>------------------------------------------------------------------------
>>
>>bash-3.00# cat /proc/ipipe/trace/max
>>I-pipe worst-case tracing service on 2.6.14/ipipe-1.3-00
>>------------------------------------------------------------
>>Begin: 90358006525 cycles, Trace Points: 25 (-10/+4), Length: 69 us
>>
>> +----- Hard IRQs ('|': locked)
>> |+---- <unused>
>> ||+--- <unused>
>> |||+-- Xenomai
>> ||||+- Linux ('*': domain stalled)
>> ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
>> ||||| | +- NMI noise ('N')
>> ||||| | |
>> Type User Val. Time Delay Function (Parent)
>> fn -25 1.935 schedule+0x14 (syscall_exit_work+0x110)
>> fn -23 2.075 profile_hit+0x14 (schedule+0x68)
>> fn -21 2.390 sched_clock+0x14 (schedule+0xa0)
>> fn -19 4.400 __ipipe_stall_root+0x14 (schedule+0x118)
>> *fn -14 2.040 __ipipe_dispatch_event+0x14 (schedule+0x300)
>> | *begin 0x80000001 -12 3.190 __ipipe_dispatch_event+0x240 (schedule+0x300)
>> | *end 0x80000001 -9 1.990 __ipipe_dispatch_event+0x228 (schedule+0x300)
>> *fn -7 4.115 schedule_event+0x14 (__ipipe_dispatch_event+0x160)
>> | *begin 0x80000001 -3 1.835 __ipipe_dispatch_event+0x198 (schedule+0x300)
>> | *end 0x80000001 -1 1.815 __ipipe_dispatch_event+0x1b8 (schedule+0x300)
>>
>>>| *begin 0x80000000 0+ 4.715 schedule+0x6ac (syscall_exit_work+0x110)
>>
>>:| *fn 4+ 1.225 __switch_to+0x14 (schedule+0x358)
>>:| *fn 5+ 5.025 __ipipe_test_and_stall_root+0x14 (__switch_to+0x30)
>>: *fn 10+ 1.445 schedule_tail+0x14 (ret_from_fork+0x60)
>>: *fn 12+ 3.450 __ipipe_unstall_root+0x14 (schedule_tail+0x48)
>
>
> Instrumentation of the maximum IRQs-off path seems to be broken. The two
> functions above were entered with hard-IRQs on, so they should have
> interrupted the trace path.
>
You mean that something in the instrumentation of local_irq*_hw() might
be broken (asm/hw_irq.h on this arch), or would some tracepoint be
missing somewhere?
>
>>:| *fn 15+ 1.145 __ipipe_grab_timer+0x14 (__ipipe_ret_from_except+0x0)
>>:| *begin 0xc00466f4 16+ 1.615 __ipipe_grab_timer+0x34 (__ipipe_ret_from_except+0x0)
>
>
> Hmm, the User Value on x86 would contain the IRQ number here. Some
> forgotten dereferencing? Looks like a pointer.
>
That was intended, but merely useless actually. It's the value of the
link register when the interrupt handler is branched to, and this value
is always __ipipe_ret_from_exception. Will fix.
>
>>:| *fn 18+ 3.665 __ipipe_handle_irq+0x14 (__ipipe_grab_timer+0x4c)
>>:| *fn 22+ 1.980 __ipipe_walk_pipeline+0x14 (__ipipe_handle_irq+0x174)
>>:| *fn 24+ 2.540 ipipe_suspend_domain+0x14 (__ipipe_walk_pipeline+0xe4)
>>:| *fn 26+ 3.600 __ipipe_sync_stage+0x14 (ipipe_suspend_domain+0xa8)
>>:| **fn 30+ 1.650 xnintr_clock_handler+0x14 (__ipipe_sync_stage+0x1ac)
>>:| **fn 31+ 2.150 xnintr_irq_handler+0x14 (xnintr_clock_handler+0x38)
>>:| **fn 34+ 1.980 xnpod_announce_tick+0x14 (xnintr_irq_handler+0x58)
>>:| **fn 36+ 3.395 xntimer_do_tick_aperiodic+0x14 (xnpod_announce_tick+0x3c)
>>:| **fn 39+ 1.645 xnthread_periodic_handler+0x14 (xntimer_do_tick_aperiodic+0x2b4)
>>:| **fn 41+ 1.420 xnpod_resume_thread+0x14 (xnthread_periodic_handler+0x3c)
>>:| **fn 42+ 4.010 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_resume_thread+0x34)
>>:| **fn 46+ 4.910 ipipe_restore_pipeline_head+0x14 (xnpod_resume_thread+0x120)
>>:| **fn 51+ 1.870 xnpod_schedule+0x14 (xnintr_irq_handler+0xf0)
>>:| **fn 53+ 9.430 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_schedule+0x80)
>>:| **fn 62+ 2.215 ipipe_restore_pipeline_head+0x14 (xnpod_schedule+0x46c)
>>:| **fn 64+ 2.865 ipipe_restore_pipeline_head+0x14 (xnpod_suspend_thread+0x94)
>>:| **fn 67+ 1.945 ipipe_restore_pipeline_head+0x14 (xnpod_wait_thread_period+0x11c)
>><| *end 0x80000000 69 7.185 ipipe_restore_pipeline_head+0xbc (xnpod_wait_thread_period+0x11c)
>> *end 0x80000001 76 10.310 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
>> *fn 86 1.495 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
>> *fn 88 1.660 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
>> | *begin 0x80000001 90 0.000 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
>>
>>
>>
>>bash-3.00# cat /proc/ipipe/trace/frozen
>>I-pipe frozen back-tracing service on 2.6.14/ipipe-1.3-00
>>------------------------------------------------------------
>>Freeze: 155250522464 cycles, Trace Points: 30 (+10)
>>
>> +----- Hard IRQs ('|': locked)
>> |+---- <unused>
>> ||+--- <unused>
>> |||+-- Xenomai
>> ||||+- Linux ('*': domain stalled)
>> ||||| +---------- Delay flag ('+': > 1 us, '!': > 10 us)
>> ||||| | +- NMI noise ('N')
>> ||||| | |
>> Type User Val. Time Delay Function (Parent)
>>:| *fn -80+ 1.485 __ipipe_ack_irq+0x14 (__ipipe_handle_irq+0x158)
>>:| *fn -78+ 1.515 ipipe_test_and_stall_pipeline_from+0x14 (__ipipe_ack_irq+0x54)
>>:| **fn -77+ 1.730 ppc4xx_uic0_ack+0x14 (__ipipe_ack_irq+0x6c)
>>:| *fn -75+ 1.390 __ipipe_walk_pipeline+0x14 (__ipipe_handle_irq+0x174)
>>:| *end 0xc0043f18 -74+ 9.065 __ipipe_grab_irq+0x64 (__ipipe_ret_from_except+0x0)
>>: *end 0x80000001 -65! 10.695 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
>>: *fn -54+ 1.650 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
>>: *fn -53+ 1.710 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
>>:| *begin 0x80000001 -51+ 2.660 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
>>:| *fn -48+ 4.420 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
>>:| *fn -44+ 2.540 __rt_timer_tsc2ns+0x14 (hisyscall_event+0x224)
>>:| *fn -41+ 5.630 rt_timer_tsc2ns+0x14 (__rt_timer_tsc2ns+0x48)
>>:| *end 0x80000001 -36+ 4.420 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
>>: *fn -31+ 1.475 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
>>: *fn -30+ 1.715 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
>>:| *begin 0x80000001 -28+ 1.960 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
>>:| *fn -26+ 2.880 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
>>:| *fn -23+ 1.610 sys_rtdm_ioctl+0x14 (hisyscall_event+0x224)
>>:| *fn -22+ 2.145 _rtdm_ioctl+0x14 (sys_rtdm_ioctl+0x3c)
>>:| *fn -20+ 1.325 rtdm_context_get+0x14 (_rtdm_ioctl+0x70)
>>:| *fn -18+ 2.205 ipipe_test_and_stall_pipeline_head+0x14 (rtdm_context_get+0x58)
>>:| **fn -16+ 1.630 ipipe_restore_pipeline_head+0x14 (rtdm_context_get+0xcc)
>>:| *end 0x80000000 -14+ 2.525 ipipe_restore_pipeline_head+0xbc (rtdm_context_get+0xcc)
>>: *fn -12+ 1.410 rt_tmbench_ioctl_rt+0x14 (_rtdm_ioctl+0xb0)
>>: *fn -10+ 1.940 tracer_ioctl+0x14 (rt_tmbench_ioctl_rt+0x44)
>>: *fn -9+ 1.550 ipipe_trace_frozen_reset+0x14 (tracer_ioctl+0x148)
>>: *fn -7+ 1.600 __ipipe_global_path_lock+0x14 (ipipe_trace_frozen_reset+0x2c)
>>:| *begin 0x80000001 -5+ 3.920 __ipipe_global_path_lock+0x98 (ipipe_trace_frozen_reset+0x2c)
>>:| *end 0x80000001 -2+ 2.020 __ipipe_global_path_unlock+0x84 (ipipe_trace_frozen_reset+0x8c)
>>< *freeze 0x00000000 0 3.980 tracer_ioctl+0x150 (rt_tmbench_ioctl_rt+0x44)
>
>
> Here we should see the observed latency in User Value, reported with the
> ioctl down to the driver, then to ipipe_trace_freeze. 0 indicates some
> remaining minor issue here as well.
Uh? Oh, well...
>
>
>> *end 0x80000001 3 4.270 __ipipe_dispatch_event+0x1b8 (__ipipe_syscall_root+0x4c)
>> *fn 8 1.310 __ipipe_syscall_root+0x14 (DoSyscall+0x24)
>> *fn 9 1.740 __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0x4c)
>> | *begin 0x80000001 11 1.690 __ipipe_dispatch_event+0x240 (__ipipe_syscall_root+0x4c)
>> | *fn 12 3.020 hisyscall_event+0x14 (__ipipe_dispatch_event+0xa4)
>> | *fn 15 1.750 __rt_task_wait_period+0x14 (hisyscall_event+0x224)
>> | *fn 17 1.760 rt_task_wait_period+0x14 (__rt_task_wait_period+0x44)
>> | *fn 19 1.385 xnpod_wait_thread_period+0x14 (rt_task_wait_period+0x88)
>> | *fn 20 2.465 ipipe_test_and_stall_pipeline_head+0x14 (xnpod_wait_thread_period+0x3c)
>> | **fn 23 0.000 xnpod_suspend_thread+0x14 (xnpod_wait_thread_period+0x9c)
>>bash-3.00#
>>
>
>
> Jan
>
>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> Adeos-main mailing list
> Adeos-main@domain.hid
> https://mail.gna.org/listinfo/adeos-main
--
Philippe.
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2006-05-02 7:49 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2006-04-26 22:13 [Xenomai-core] I-pipe latency tracer for ppc Philippe Gerum
2006-05-01 18:44 ` Wolfgang Grandegger
2006-05-01 18:58 ` [Adeos-main] " Jan Kiszka
2006-05-01 19:33 ` Wolfgang Grandegger
2006-05-01 21:42 ` Jan Kiszka
2006-05-02 7:49 ` Philippe Gerum
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.