[Xenomai-core] Re: [Adeos-main] ipip tracer porting for blackfin

2006-11-12 Thread Li Yi (Adam)
Please see my comments bellow:On 11/11/06, Jan Kiszka [EMAIL PROTECTED] wrote:
Li Yi (Adam) wrote: Hi Jan and Philippe,This must behttp://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2337
saying root thread is about the be scheduled away. But then I'mmissing code here that one would normally see on x86:
http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2442Likely inlined on bfin, but this *must* make some noise:
http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2453Instead we enter the pending timer interrupt. This currently makes nosense to me, rather make me think that something is skewed. Maybe only
the tracer, maybe more...Do you have a tracer-log for i386 for reference? So I can do some compare.
 :|# end 0x8000 -50+ 2.278___sched_text_start+0x5ca (__start+0xf000) :|# func -480.922___ipipe_grab_irq+0x22 (__common_int_entry+0x72) :|# begin 0x0006 -47+ 
1.820___ipipe_grab_irq+0x34 (__start+0xf000) :|# func -45+ 1.530___ipipe_handle_irq+0x1e (___ipipe_grab_irq+0x3c) :|# func -43+ 1.168_rthal_timer_ack+0x8 (___ipipe_handle_irq+0x178)
 :|# func -42+ 1.102___ipipe_dispatch_wired+0x14 (___ipipe_handle_irq+0x190) :|# end 0x0006 -41+ 2.010___ipipe_grab_irq+0x42 (__start+0xf000) : # func -39+ 
1.090_ipipe_unstall_pipeline_head+0x8 (_xnshadow_harden+0xce) :|# begin 0x8001 -38+ 2.308_ipipe_unstall_pipeline_head+0x18 (__start+0xf000)That's another weirdness, but now very likely of the tracer: both
tracepoints should contain the same parent entry, but the second one isjust nonsense. And there are such kind of parents all over the place -hmm, actually any explicit trace point shows this problem. Is there no
way on bfin to get the caller from everywhere in a function? I guessthere is, likely a register, right?Yes, by using the frame-pointer register (FP) it is possible to get parent's return address. The reason is that __builtin_return_address(1) is not implemented for Blackfin gcc. I have submitted feature request for the toolchain developer, hoping they could help. 
Thanks for pointing out.-Yi
___
Xenomai-core mailing list
Xenomai-core@gna.org
https://mail.gna.org/listinfo/xenomai-core


Re: [Xenomai-core] Re: [Adeos-main] ipip tracer porting for blackfin

2006-11-10 Thread Philippe Gerum
On Fri, 2006-11-10 at 21:54 +0800, Li Yi (Adam) wrote:
 Hi Jan and Philippe,
 
 I have tested the adeos-ipipe-bf53x-CVS-20061008-1.5-00.patch in
 Xenomai-2.2.5 with latest Blackfin uclinux toolchain 06r2 release:
 http://blackfin.uclinux.org/frs/download.php/1136/blackfin-toolchain-06r2-5.i386.rpm.
  Since the toolchain changed a little for the mcount call, the ipipe-tracer 
 patch need to be updated a little.
 
 Also I add trace for IRQ entry and exit as Jan suggested. Here is the
 details of the patch (with my explanation) 
 
 diff -Nur linux-2.6.x-ipipe-orig/arch/blackfin/kernel/ipipe-mcount.S
 linux-2.6.x-ipipe/arch/blackfin/kernel/ipipe-mcount.S
 --- linux-2.6.x-ipipe-orig/arch/blackfin/kernel/ipipe-mcount.S
 2006-11-10 21:04:21.0 +0800
 +++ linux-2.6.x-ipipe/arch/blackfin/kernel/ipipe-mcount.S
 2006-11-10 16:41:11.0 +0800
 @@ -12,7 +12,7 @@
 
  .align 4   /* just in case */
 
 -ENTRY(_mcount)
 +ENTRY(__mcount)
 [--sp] = ( r7:0, p5:0 ); 
 [--sp] = ASTAT;
 p1.L = _ipipe_trace_enable;
 diff -Nur linux-2.6.x-ipipe-orig/arch/blackfin/kernel/ipipe-root.c
 linux-2.6.x-ipipe/arch/blackfin/kernel/ipipe-root.c
 --- linux-2.6.x-ipipe-orig/arch/blackfin/kernel/ipipe- root.c
 2006-11-10 21:04:21.0 +0800
 +++ linux-2.6.x-ipipe/arch/blackfin/kernel/ipipe-root.c 2006-11-10
 16:41:59.0 +0800
 @@ -281,6 +281,6 @@
  EXPORT_SYMBOL(show_stack);
 
  #ifdef CONFIG_IPIPE_TRACE_MCOUNT 
 -void notrace mcount(void);
 -EXPORT_SYMBOL(mcount);
 +void notrace _mcount(void);
 +EXPORT_SYMBOL(_mcount);
  #endif /* CONFIG_IPIPE_TRACE_MCOUNT */
 
 Yi's note: The  gcc  will add Call _ _mcount to each function
 entry when there is -pg option 

Ok.

 
 diff -Nur linux-2.6.x-ipipe-orig/arch/blackfin/mach-common/interrupt.S
 linux-2.6.x-ipipe/arch/blackfin/mach-common/interrupt.S
 --- linux-2.6.x-ipipe-orig/arch/blackfin/mach-common/interrupt.S
 2006-11-10 21:04: 21.0 +0800
 +++ linux-2.6.x-ipipe/arch/blackfin/mach-common/interrupt.S
 2006-11-10 16:43:55.0 +0800
 @@ -304,7 +304,10 @@
 p0.l = _irq_flags;
 p0.h = _irq_flags;
 r0 = [p0]; 
 -   sti r0
 +   sti r0;
 +   /* Reenable interrupts */
 +   [--sp] = reti;
 +   r0 = [sp++];
 rts;
 
  #endif /* CONFIG_IPIPE */
 
 
 Yi's Note: I used the ipipe-trace to trace the latency test case:
 latency -t2 -p200 -f. And found that __ipipe_call_irqtail() will
 disable global interrupts, putting the Blackfin to a state like: 
 IMASK: 0x, ILAT: 0x0040, IPEND: 0xc010 - that is,
 Core Timer irq latched, but since IPEND[4] is set, the irq handler
 cannot be invoked - thus longer latency.
 

Good catch, I forgot the fact that triggering an IRQ to run the
scheduling tail would raise the global disable bit. Applied, thanks.

[...]

-- 
Philippe.



___
Xenomai-core mailing list
Xenomai-core@gna.org
https://mail.gna.org/listinfo/xenomai-core


[Xenomai-core] Re: [Adeos-main] ipip tracer porting for blackfin

2006-11-10 Thread Jan Kiszka
Li Yi (Adam) wrote:
 Hi Jan and Philippe,
 

...

 
 Also attached the new ipiper-tracer log.

Damn, no fitting reference trace at hand, but something seems to be
fishy. See comments/questions below.

 
 
 root:~ ./latency -t2 -p200 -f
 
 root:~ cat /proc/ipipe/trace/frozen
 I-pipe frozen back-tracing service on 2.6.16.27-ADI-2006R2/ipipe-1.5-00
 
 Freeze: 144879102832 cycles, Trace Points: 200 (+50)
 
  +- Hard IRQs ('|': locked)
  |+ unused
  ||+--- unused
  |||+-- Xenomai
  +- Linux ('*': domain stalled, '+': current, '#': current+stalled)
  |+-- Delay flag ('+':  1 us, '!':  10 
 us)
  ||+- NMI noise ('N')
  |||
   TypeUser Val.   TimeDelay  Function (Parent)
...

 :+func -98+   1.550  _kthread_should_stop+0x10 
 (_gatekeeper_thread+0xec)
 :|   +begin   0x8001   -97+   2.898  _gatekeeper_thread+0x100 
 (__start+0xf000)
 :|  *+func -94+   1.432  _xnpod_resume_thread+0xa 
 (_gatekeeper_thread+0x186)
 :|  *+[   51] -?-0   -92+   5.450  _xnpod_resume_thread+0x4a 
 (__start+0xf000)

Here we go: harden the xeno thread related to pid 51 (likely some now
gone part of latency).

http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L1555

 :|  *+func -87+   1.100  _xnpod_schedule_runnable+0xc 
 (_gatekeeper_thread+0x1be)
 :|  *+[0] swapper -1   -86+   2.788  _xnpod_schedule_runnable+0x28 
 (__start+0xf000)

This correlates to
http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2529

xnpod_schedule_runnable returns without actually switching (off-topic:
seems to be the only use-case for this function right now...).

 :|  *+func -83+   2.852  _xnpod_schedule+0xa 
 (_gatekeeper_thread+0x1ce)
 :|  *+func -80+   2.970  _ipipe_trigger_irq+0x12 
 (_xnpod_schedule+0x2e6)
 :|  *+func -77+   2.120  ___ipipe_handle_irq+0x1e 
 (_ipipe_trigger_irq+0x86)
 :|  *+func -75+   2.058  ___ipipe_dispatch_wired+0x14 
 (___ipipe_handle_irq+0x190)
 :|  *+func -73+   1.722  ___ipipe_restore_pipeline_head+0xa 
 (_gatekeeper_thread+0x138)
 :|   +func -71+   2.130  ___ipipe_walk_pipeline+0x18 
 (___ipipe_restore_pipeline_head+0xd0)
 :|  + func -69+   2.410  _ipipe_suspend_domain+0xa 
 (___ipipe_walk_pipeline+0xac)
 :|  + func -67+   5.048  ___ipipe_sync_stage+0xe 
 (_ipipe_suspend_domain+0x4e)
 :|  # func -62+   2.452  _xnpod_schedule_handler+0xe 
 (___ipipe_sync_stage+0x186)
 :|  # func -59+   2.130  _xnpod_schedule+0xa 
 (_xnpod_schedule_handler+0x5c)
 :|  # [0] swapper -1   -57+   7.180  _xnpod_schedule+0x104 
 (__start+0xf000)

This must be
http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2337

saying root thread is about the be scheduled away. But then I'm
missing code here that one would normally see on x86:

http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2442

Likely inlined on bfin, but this *must* make some noise:

http://www.rts.uni-hannover.de/xenomai/lxr/source/ksrc/nucleus/pod.c#L2453

Instead we enter the pending timer interrupt. This currently makes no
sense to me, rather make me think that something is skewed. Maybe only
the tracer, maybe more...

 :|  # end 0x8000   -50+   2.278  ___sched_text_start+0x5ca 
 (__start+0xf000)
 :|  # func -480.922  ___ipipe_grab_irq+0x22 
 (__common_int_entry+0x72)
 :|  # begin   0x0006   -47+   1.820  ___ipipe_grab_irq+0x34 
 (__start+0xf000)
 :|  # func -45+   1.530  ___ipipe_handle_irq+0x1e 
 (___ipipe_grab_irq+0x3c)
 :|  # func -43+   1.168  _rthal_timer_ack+0x8 
 (___ipipe_handle_irq+0x178)
 :|  # func -42+   1.102  ___ipipe_dispatch_wired+0x14 
 (___ipipe_handle_irq+0x190)
 :|  # end 0x0006   -41+   2.010  ___ipipe_grab_irq+0x42 
 (__start+0xf000)
 :   # func -39+   1.090  _ipipe_unstall_pipeline_head+0x8 
 (_xnshadow_harden+0xce)
 :|  # begin   0x8001   -38+   2.308  _ipipe_unstall_pipeline_head+0x18 
 (__start+0xf000)

That's another weirdness, but now very likely of the tracer: both
tracepoints should contain the same parent entry, but the second one is
just nonsense. And there are such kind of parents all over the place -
hmm, actually any explicit trace point shows this problem. Is there no
way on bfin to get the caller from everywhere in a function? I guess
there is, likely a register, right?

Jan



signature.asc
Description: OpenPGP digital signature
___
Xenomai-core mailing list
Xenomai-core@gna.org

[Xenomai-core] Re: [Adeos-main] ipip tracer porting for blackfin

2006-10-01 Thread Jan Kiszka
Li Yi (Adam) wrote:
 Hi,
 
 Attached ipipe-tracer ported to blackfin. The patch is based on
 http://download.gna.org/adeos/patches/v2.6/blackfin/adeos-ipipe-bf53x-R06R1RC2-1.4-03.patch.

Great!

 
 But it requires a little hack to Blackfin GCC-R06R1 to  make the -pg
 option work.  The latest release of bfin-gcc (06r2) has supported this
 feature. And I will update the ipipe tracer patch to the latest kernel
 release (r06r2).
 
 Also attached the ipipe tracer log.

It looks like a few instrumentation issues are remaining, see comments
below.

 Hoping for your comments.
 
 Best Regards,
 
 -Yi
 
 
 
 
 root:~ ./latency -t0 -p 300 -f
 
 
 root:~ cat /proc/ipipe/trace/max
 I-pipe worst-case tracing service on 2.6.16.11.ADI-2006R1blackfin/ipipe-1.4-03
 
 Begin: 240373976502 cycles, Trace Points: 24 (-10/+1), Length: 270 us
 
  +- Hard IRQs ('|': locked)
  |+ unused
  ||+--- unused
  |||+-- Xenomai
  +- Linux ('*': domain stalled, '+': current, '#': current+stalled)
  |+-- Delay flag ('+':  1 us, '!':  10 
 us)
  ||+- NMI noise ('N')
  |||
   TypeUser Val.   TimeDelay  Function (Parent)
  |  + begin   0x8001   -200.910  ___ipipe_dispatch_event+0xb4 
 (__start+0xf000)
  |  + end 0x8001   -196.360  ___ipipe_dispatch_event+0x11a 
 (__start+0xf000)
 + func -131.440  ___ipipe_syscall_root+0xe 
 (system_call+0x2e)
 + func -110.890  ___ipipe_dispatch_event+0xa 
 (___ipipe_syscall_root+0x24)
  |  + begin   0x8001   -101.280  ___ipipe_dispatch_event+0x20 
 (__start+0xf000)
  |  + end 0x8001-91.530  ___ipipe_dispatch_event+0x88 
 (__start+0xf000)
 + func  -72.730  _hisyscall_event+0x10 
 (___ipipe_dispatch_event+0xa0)
 + func  -51.440  ___rt_task_wait_period+0xc 
 (_hisyscall_event+0x134)
 + func  -31.820  _rt_task_wait_period+0xc 
 (___rt_task_wait_period+0x4c)
 + func  -10.950  _xnpod_wait_thread_period+0xa 
 (_rt_task_wait_period+0x4c)
 |  + begin   0x8001 1+   1.900  _xnpod_wait_thread_period+0x30 
 (__start+0xf000)
 :|  # func   2+   1.640  _xnpod_suspend_thread+0xa 
 (_xnpod_wait_thread_period+0x78)
 :|  # func   40.892  _xnpod_schedule+0xa 
 (_xnpod_suspend_thread+0x168)
 :|  # [   50] -?-   99 5+   1.658  _xnpod_schedule+0x112 
 (__start+0xf000)
 :|  # [1] init-1 7+   2.350  _xnpod_schedule+0x270 
 (__start+0xf000)
 :+func   9! 235.540  ___ipipe_walk_pipeline+0x1e 
 (___ipipe_handle_irq+0x14c)

Looks like there are some inconsistencies in the IRQ state tracing: You
schedule from latency (PID 50, now of unknown name -?-, priority 99)
to the init process under Linux (PID 1, init, ROOT thread priority
-1). After that switch the IRQs are very likely earlier reenabled, e.g.
on interrupt return. Compare the instrumentation of x86 with your version.

Moreover, IRQ entry and exit should also be traced. This doesn't seem to
happen yet, otherwise we would see some begin entry with the IRQ
number as user value. Again, check the x86 code for
ipipe_trace_begin/end passages.

 :|   +func 244+   1.330  ___ipipe_grab_irq+0x10 
 (_evt_timer+0x7c)
 :|   +func 246+   1.560  ___ipipe_handle_irq+0x10 
 (___ipipe_grab_irq+0x32)
 :|   +func 247+   2.120  _rthal_timer_ack+0x8 
 (___ipipe_handle_irq+0x174)
 :|   +func 249+   1.680  ___ipipe_dispatch_wired+0x14 
 (___ipipe_handle_irq+0x74)
 :|  # func 251+   1.270  _xnintr_clock_handler+0x10 
 (___ipipe_dispatch_wired+0xa6)
 :|  # func 252+   1.090  _xnintr_irq_handler+0x18 
 (_xnintr_clock_handler+0x18)
 :|  # func 254+   1.380  _xnpod_announce_tick+0xc 
 (_xnintr_irq_handler+0x2e)
 :|  # func 255+   1.470  _xntimer_do_tick_aperiodic+0x14 
 (_xnpod_announce_tick+0x16)
 :|  # func 256+   1.400  _xnthread_periodic_handler+0xa 
 (_xntimer_do_tick_aperiodic+0x1d6)
 :|  # func 2580.790  _xnpod_resume_thread+0xa 
 (_xnthread_periodic_handler+0x1e)
 :|  # [   50] -?-   99   259+   2.510  _xnpod_resume_thread+0x4a 
 (__start+0xf000)
 :|  # func 261+   1.890  _xnpod_schedule+0xa 
 (_xnintr_irq_handler+0x82)
 :|  # func 263+   1.380  _xnpod_schedule_deferred+0xc 
 (___ipipe_call_irqtail+0x1e)
 :|  # func 2640.970  _xnpod_schedule+0xa 
 (_xnpod_schedule_deferred+0x28)
 :|  # [1] init-1   265+   1.950  _xnpod_schedule+0x112 
 (__start+0xf000)
 :|  # [   50] -?-   99   267+   1.560  _xnpod_schedule+0x270