i-pipe tracer - how to view traced data

Laurentiu-Cristian Duca laurentiu.duca at gmail.com
Fri Aug 30 14:01:57 CEST 2019


Hello and thank you for the answer. It worked.

Here is a test of rtt-responder on qemu. I also attached it to this email.
I use the ipipe-trace api to freeze tracing from C code.
I see that rtdm_fd_recvmsg and rtdm_fd_sendmsg are called
(and I wanted to see that).

I have some questions (I have some ideas but just want to be sure).
Please answer to those that are important.

1. On Hard IRQs column, I see only ':' and space; what do they mean?
What does mean ('|': locked) from Hard IRQs?
2. On Xenomai column I see only '|' and space; what do they mean?
3. What does the following column mean:
Linux ('*': domain stalled, '+': current, '#': current+stalled)
4. Type 'func' I think it means a function is called; correct?
What do 'begin' and 'end' mean on the Type column? Are they important?
5. NMI noise 'N' ?

I-pipe frozen back-tracing service on 4.14.71/ipipe release #2112
------------------------------------------------------------
CPU: 0, Freeze: 1176197529135 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.074 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                 -27	  0.574  xnsynch_wakeup_one_sleeper+0x0
(rtdm_sem_up+0xed)
:|# func                 -26	  0.406  xnthread_resume+0x0
(xnsynch_wakeup_one_sleeper+0x14a)
:|# [  121] rtt-res 81   -26	  0.184  xnthread_resume+0x113 (<00000000>)
:|# func                 -26	  0.149  xnsched_rt_enqueue+0x0
(xnthread_resume+0x14f)
:|# func                 -26	  0.335  xnsched_addq_tail+0x0
(xnthread_resume+0x14f)
:|# func                 -25	  0.185  ___xnsched_run+0x0 (rtdm_sem_up+0x18d)
:|# func                 -25	  0.202  ___xnsched_run.part.63+0x0
(rtdm_sem_up+0x18d)
:|# [  100] rtnet-s 98   -25	  0.165  ___xnsched_run.part.63+0x102 (<00000000>)
:|# func                 -25	  0.207  xnsched_pick_next+0x0
(___xnsched_run.part.63+0x137)
:|# func                 -25	  0.160  xnsched_rt_requeue+0x0
(xnsched_pick_next+0x56)
:|# func                 -24	  0.193  xnsched_addq+0x0 (xnsched_pick_next+0x56)
:|# func                 -24	  0.165  xnsched_rt_pick+0x0
(xnsched_pick_next+0x8b)
:|# func                 -24	  0.200  del_q+0x0 (xnsched_rt_pick+0x5a)
:|# func                 -24	  0.198  xnlock_dbg_release+0x0 (rtdm_sem_up+0x1b2)
:|# func                 -24	  0.156  __ipipe_restore_head+0x0
(rtdm_sem_up+0x14c)
:|+ end     0x80000000   -23	  0.142  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -23	  0.193  rt_udp_rcv+0xe4 [rtudp] (<00000000>)
:|# func                 -23	  0.156  xnsched_lock+0x0
(rt_udp_rcv+0x11c [rtudp])
:|# func                 -23	  0.185  xnsched_unlock+0x0
(rt_udp_rcv+0x136 [rtudp])
:|# func                 -23	  0.156  __ipipe_restore_head+0x0
(rt_udp_rcv+0x15a [rtudp])
:|+ end     0x80000000   -23	  0.209  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -22	  0.153  rtdm_fd_unlock+0x0
(rt_ip_rcv+0x15a [rtipv4])
:|+ begin   0x80000000   -22	  0.189  rtdm_fd_unlock+0x22 (<00000000>)
:|# func                 -22	  0.160  xnlock_dbg_prepare_acquire+0x0
(rtdm_fd_unlock+0x54)
:|# func                 -22	  0.193  xnlock_dbg_acquired+0x0
(rtdm_fd_unlock+0x92)
:|# func                 -22	  0.169  __put_fd+0x0 (rtdm_fd_unlock+0xa4)
:|# func                 -22	  0.180  xnlock_dbg_release+0x0 (__put_fd+0xa8)
:|# func                 -21	  0.158  __ipipe_restore_head+0x0 (__put_fd+0x6f)
:|+ end     0x80000000   -21	  0.169  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -21	  0.191  rt_stack_deliver+0x293 [rtnet]
(<00000000>)
:|# func                 -21	  0.267  xnsched_lock+0x0
(rt_stack_deliver+0x2c8 [rtnet])
:|# func                 -21	  0.313  module_put+0x0
(rt_stack_deliver+0x2d4 [rtnet])
:|# func                 -20	  0.225  xnsched_unlock+0x0
(rt_stack_deliver+0x2e8 [rtnet])
:|# func                 -20	  0.153  __ipipe_restore_head+0x0
(rt_stack_mgr_task+0x6b [rtnet])
:|+ end     0x80000000   -20	  0.184  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -20	  0.162  rtdm_event_wait+0x0
(rt_stack_mgr_task+0x2c [rtnet])
: + func                 -20	  0.236  rtdm_event_timedwait+0x0
(rt_stack_mgr_task+0x2c [rtnet])
:|+ begin   0x80000000   -19	  0.194  rtdm_event_timedwait+0xb1 (<00000000>)
:|# func                 -19	  0.154  xnlock_dbg_prepare_acquire+0x0
(rtdm_event_timedwait+0xed)
:|# func                 -19	  0.200  xnlock_dbg_acquired+0x0
(rtdm_event_timedwait+0x131)
:|# func                 -19	  0.344  xnsynch_sleep_on+0x0
(rtdm_event_timedwait+0x316)
:|# func                 -18	  0.315  xnthread_suspend+0x0
(xnsynch_sleep_on+0x221)
:|# func                 -18	  0.185  ___xnsched_run+0x0
(xnthread_suspend+0x4cc)
:|# func                 -18	  0.169  ___xnsched_run.part.63+0x0
(xnthread_suspend+0x4cc)
:|# [  100] rtnet-s 98   -18	  0.154  ___xnsched_run.part.63+0x102 (<00000000>)
:|# func                 -18	  0.184  xnsched_pick_next+0x0
(___xnsched_run.part.63+0x137)
:|# func                 -17	  0.156  xnsched_rt_pick+0x0
(xnsched_pick_next+0x8b)
:|# func                 -17	  0.300  del_q+0x0 (xnsched_rt_pick+0x5a)
:|# func                 -17	  0.153  xnarch_switch_to+0x0
(___xnsched_run.part.63+0x22b)
:|# func                 -17	  0.395  switch_mm_irqs_off+0x0
(xnarch_switch_to+0x2a)
:|# func                 -16+   1.268  __phys_addr+0x0
(switch_mm_irqs_off+0x1c7)
:|# func                 -15	  0.149  xnthread_switch_fpu+0x0
(___xnsched_run.part.63+0x290)
:|# func                 -15	  0.209  xnarch_switch_fpu+0x0
(xnthread_switch_fpu+0x26)
:|# [  121] rtt-res 81   -15	  0.517  ___xnsched_run.part.63+0x2ad (<00000000>)
:|# func                 -14	  0.182  xnlock_dbg_release+0x0
(rtdm_sem_timeddown+0x239)
:|# func                 -14	  0.154  __ipipe_restore_head+0x0
(rtdm_sem_timeddown+0x1ab)
:|+ end     0x80000000   -14	  0.242  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -14	  0.193  rt_udp_recvmsg+0x105 [rtudp] (<00000000>)
:|# func                 -14	  0.165  xnsched_lock+0x0
(rt_udp_recvmsg+0x14b [rtudp])
:|# func                 -13	  0.222  xnsched_unlock+0x0
(rt_udp_recvmsg+0x178 [rtudp])
:|# func                 -13	  0.164  __ipipe_restore_head+0x0
(rt_udp_recvmsg+0x1ad [rtudp])
:|+ end     0x80000000   -13	  0.151  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -13	  0.874  rtnet_put_arg+0x0 [rtnet]
(rt_udp_recvmsg+0x200 [rtudp])
: + func                 -12	  0.278  rtnet_put_arg+0x0 [rtnet]
(rt_udp_recvmsg+0x330 [rtudp])
: + func                 -12	  0.291  rtdm_get_iov_flatlen+0x0
(rt_udp_recvmsg+0x37e [rtudp])
: + func                 -11	  0.171  rtnet_write_to_iov+0x0 [rtnet]
(rt_udp_recvmsg+0x414 [rtudp])
: + func                 -11	  0.335  rtnet_put_arg+0x0 [rtnet]
(rtnet_write_to_iov+0x86 [rtnet])
: + func                 -11	  0.147  kfree_rtskb+0x0 [rtnet]
(rt_udp_recvmsg+0x21e [rtudp])
:|+ begin   0x80000000   -11	  0.193  kfree_rtskb+0xb2 [rtnet] (<00000000>)
:|# func                 -11	  0.180  xnsched_lock+0x0
(kfree_rtskb+0xe2 [rtnet])
:|# func                 -10	  0.196  xnsched_unlock+0x0
(kfree_rtskb+0xfc [rtnet])
:|# func                 -10	  0.169  __ipipe_restore_head+0x0
(kfree_rtskb+0x12f [rtnet])
:|+ end     0x80000000   -10	  0.162  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -10	  0.153  rtskb_pool_queue_tail+0x0
[rtnet] (kfree_rtskb+0x13f [rtnet])
:|+ begin   0x80000000   -10	  0.191  rtskb_pool_queue_tail+0x23
[rtnet] (<00000000>)
:|# func                  -9	  0.209  xnsched_lock+0x0
(rtskb_pool_queue_tail+0x5c [rtnet])
:|# func                  -9	  0.149  rtskb_nop_pool_unlock+0x0
[rtnet] (rtskb_pool_queue_tail+0x89 [rtnet])
:|# func                  -9	  0.209  xnsched_unlock+0x0
(rtskb_pool_queue_tail+0x92 [rtnet])
:|# func                  -9	  0.154  __ipipe_restore_head+0x0
(kfree_rtskb+0x13f [rtnet])
:|+ end     0x80000000    -9	  0.278  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000001    -8	  0.184  rtdm_fd_recvmsg+0x174 (<00000000>)
:|+ end     0x80000001    -8	  0.174  rtdm_fd_recvmsg+0x18d (<00000000>)
: + func                  -8	  0.164  rtdm_fd_put+0x0 (rtdm_fd_recvmsg+0x147)
:|+ begin   0x80000000    -8	  0.184  rtdm_fd_put+0x22 (<00000000>)
:|# func                  -8	  0.154  xnlock_dbg_prepare_acquire+0x0
(rtdm_fd_put+0x54)
:|# func                  -8	  0.153  xnlock_dbg_acquired+0x0 (rtdm_fd_put+0x92)
:|# func                  -7	  0.154  __put_fd+0x0 (rtdm_fd_put+0x9d)
:|# func                  -7	  0.180  xnlock_dbg_release+0x0 (__put_fd+0xa8)
:|# func                  -7	  0.156  __ipipe_restore_head+0x0 (__put_fd+0x6f)
:|+ end     0x80000000    -7	  0.284  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000001    -7	  0.173  CoBaLt_recvmsg+0x172 (<00000000>)
:|+ end     0x80000001    -6+   1.188  CoBaLt_recvmsg+0x18d (<00000000>)
:|+ begin   0x80000000    -5+   3.917  do_syscall_64+0x57 (<00000000>)
:|+ func                  -1	  0.471  do_syscall_64+0x0
(entry_SYSCALL_64_after_hwframe+0x42)
:|+ end     0x80000000    -1	  0.171  do_syscall_64+0x14f (<00000000>)
: + func                  -1	  0.238  ipipe_handle_syscall+0x0
(do_syscall_64+0x37)
: + func                  -1	  0.194  ipipe_fastcall_hook+0x0
(ipipe_handle_syscall+0x5a)
: + func                   0	  0.553  handle_head_syscall+0x0
(ipipe_fastcall_hook+0x14)
: + func                   0	  0.258  CoBaLt_trace+0x0
(handle_head_syscall+0x100)
< + freeze  0x0000000f     0	  0.404  CoBaLt_trace+0xdd (<00000000>)
 |+ begin   0x80000000     0	  1.275  do_syscall_64+0x57 (<00000000>)
 |+ func                   1	  0.377  do_syscall_64+0x0
(entry_SYSCALL_64_after_hwframe+0x42)
 |+ end     0x80000000     2	  0.162  do_syscall_64+0x14f (<00000000>)
  + func                   2	  0.158  ipipe_handle_syscall+0x0
(do_syscall_64+0x37)
  + func                   2	  0.151  ipipe_fastcall_hook+0x0
(ipipe_handle_syscall+0x5a)
  + func                   2	  0.240  handle_head_syscall+0x0
(ipipe_fastcall_hook+0x14)
  + func                   2	  0.156  CoBaLt_sendmsg+0x0
(handle_head_syscall+0x100)
 |+ begin   0x80000001     2	  0.162  CoBaLt_sendmsg+0x9b (<00000000>)
 |+ end     0x80000001     3	  0.293  CoBaLt_sendmsg+0xb5 (<00000000>)
  + func                   3	  0.000  rtdm_fd_sendmsg+0x0 (CoBaLt_sendmsg+0x7c)

On 8/28/19, Jan Kiszka <jan.kiszka at siemens.com> wrote:
> On 28.08.19 10:11, Laurentiu-Cristian Duca via Xenomai wrote:
>> Hello there,
>>
>>    I want to use ipipe tracer for tracing RTNet drivers.
>>    In the tutorial
>> https://gitlab.denx.de/Xenomai/xenomai/wikis/Using_The_I_Pipe_Tracer
>> it does not specify which file to "cat" in order to view the function
>> traces
>> so if anybody used it please provide this info.
>>    How to view the traced data?
>>
>
> cat .../frozen or .../max
>
> Jan
>
> --
> Siemens AG, Corporate Technology, CT RDA IOT SES-DE
> Corporate Competence Center Embedded Linux
>
-------------- next part --------------
Here is a test of rtt-responder on qemu.
I use the ipipe-trace api to freeze trancing from C code.
I see that rtdm_fd_recvmsg and rtdm_fd_sendmsg are called
(and I wanted to see that).

I have some questions (I have some ideas but just want to be sure). 
Please answer to those that have relevance.

1. On Hard IRQs column, I see only ':' and space; what do they mean?
What does mean Hard IRQs ('|': locked) ?
2. On Xenomai column I see only '|' and space; what do they mean?
3. What does the following column mean:
Linux ('*': domain stalled, '+': current, '#': current+stalled)
4. Type 'func' I think it means a function is called; correct?
What do 'begin' and 'end' mean on the Type column? Are they important?
5. NMI noise 'N' ?


I-pipe frozen back-tracing service on 4.14.71/ipipe release #2112
------------------------------------------------------------
CPU: 0, Freeze: 1176197529135 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.074 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                 -27	  0.574  xnsynch_wakeup_one_sleeper+0x0 (rtdm_sem_up+0xed)
:|# func                 -26	  0.406  xnthread_resume+0x0 (xnsynch_wakeup_one_sleeper+0x14a)
:|# [  121] rtt-res 81   -26	  0.184  xnthread_resume+0x113 (<00000000>)
:|# func                 -26	  0.149  xnsched_rt_enqueue+0x0 (xnthread_resume+0x14f)
:|# func                 -26	  0.335  xnsched_addq_tail+0x0 (xnthread_resume+0x14f)
:|# func                 -25	  0.185  ___xnsched_run+0x0 (rtdm_sem_up+0x18d)
:|# func                 -25	  0.202  ___xnsched_run.part.63+0x0 (rtdm_sem_up+0x18d)
:|# [  100] rtnet-s 98   -25	  0.165  ___xnsched_run.part.63+0x102 (<00000000>)
:|# func                 -25	  0.207  xnsched_pick_next+0x0 (___xnsched_run.part.63+0x137)
:|# func                 -25	  0.160  xnsched_rt_requeue+0x0 (xnsched_pick_next+0x56)
:|# func                 -24	  0.193  xnsched_addq+0x0 (xnsched_pick_next+0x56)
:|# func                 -24	  0.165  xnsched_rt_pick+0x0 (xnsched_pick_next+0x8b)
:|# func                 -24	  0.200  del_q+0x0 (xnsched_rt_pick+0x5a)
:|# func                 -24	  0.198  xnlock_dbg_release+0x0 (rtdm_sem_up+0x1b2)
:|# func                 -24	  0.156  __ipipe_restore_head+0x0 (rtdm_sem_up+0x14c)
:|+ end     0x80000000   -23	  0.142  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -23	  0.193  rt_udp_rcv+0xe4 [rtudp] (<00000000>)
:|# func                 -23	  0.156  xnsched_lock+0x0 (rt_udp_rcv+0x11c [rtudp])
:|# func                 -23	  0.185  xnsched_unlock+0x0 (rt_udp_rcv+0x136 [rtudp])
:|# func                 -23	  0.156  __ipipe_restore_head+0x0 (rt_udp_rcv+0x15a [rtudp])
:|+ end     0x80000000   -23	  0.209  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -22	  0.153  rtdm_fd_unlock+0x0 (rt_ip_rcv+0x15a [rtipv4])
:|+ begin   0x80000000   -22	  0.189  rtdm_fd_unlock+0x22 (<00000000>)
:|# func                 -22	  0.160  xnlock_dbg_prepare_acquire+0x0 (rtdm_fd_unlock+0x54)
:|# func                 -22	  0.193  xnlock_dbg_acquired+0x0 (rtdm_fd_unlock+0x92)
:|# func                 -22	  0.169  __put_fd+0x0 (rtdm_fd_unlock+0xa4)
:|# func                 -22	  0.180  xnlock_dbg_release+0x0 (__put_fd+0xa8)
:|# func                 -21	  0.158  __ipipe_restore_head+0x0 (__put_fd+0x6f)
:|+ end     0x80000000   -21	  0.169  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -21	  0.191  rt_stack_deliver+0x293 [rtnet] (<00000000>)
:|# func                 -21	  0.267  xnsched_lock+0x0 (rt_stack_deliver+0x2c8 [rtnet])
:|# func                 -21	  0.313  module_put+0x0 (rt_stack_deliver+0x2d4 [rtnet])
:|# func                 -20	  0.225  xnsched_unlock+0x0 (rt_stack_deliver+0x2e8 [rtnet])
:|# func                 -20	  0.153  __ipipe_restore_head+0x0 (rt_stack_mgr_task+0x6b [rtnet])
:|+ end     0x80000000   -20	  0.184  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -20	  0.162  rtdm_event_wait+0x0 (rt_stack_mgr_task+0x2c [rtnet])
: + func                 -20	  0.236  rtdm_event_timedwait+0x0 (rt_stack_mgr_task+0x2c [rtnet])
:|+ begin   0x80000000   -19	  0.194  rtdm_event_timedwait+0xb1 (<00000000>)
:|# func                 -19	  0.154  xnlock_dbg_prepare_acquire+0x0 (rtdm_event_timedwait+0xed)
:|# func                 -19	  0.200  xnlock_dbg_acquired+0x0 (rtdm_event_timedwait+0x131)
:|# func                 -19	  0.344  xnsynch_sleep_on+0x0 (rtdm_event_timedwait+0x316)
:|# func                 -18	  0.315  xnthread_suspend+0x0 (xnsynch_sleep_on+0x221)
:|# func                 -18	  0.185  ___xnsched_run+0x0 (xnthread_suspend+0x4cc)
:|# func                 -18	  0.169  ___xnsched_run.part.63+0x0 (xnthread_suspend+0x4cc)
:|# [  100] rtnet-s 98   -18	  0.154  ___xnsched_run.part.63+0x102 (<00000000>)
:|# func                 -18	  0.184  xnsched_pick_next+0x0 (___xnsched_run.part.63+0x137)
:|# func                 -17	  0.156  xnsched_rt_pick+0x0 (xnsched_pick_next+0x8b)
:|# func                 -17	  0.300  del_q+0x0 (xnsched_rt_pick+0x5a)
:|# func                 -17	  0.153  xnarch_switch_to+0x0 (___xnsched_run.part.63+0x22b)
:|# func                 -17	  0.395  switch_mm_irqs_off+0x0 (xnarch_switch_to+0x2a)
:|# func                 -16+   1.268  __phys_addr+0x0 (switch_mm_irqs_off+0x1c7)
:|# func                 -15	  0.149  xnthread_switch_fpu+0x0 (___xnsched_run.part.63+0x290)
:|# func                 -15	  0.209  xnarch_switch_fpu+0x0 (xnthread_switch_fpu+0x26)
:|# [  121] rtt-res 81   -15	  0.517  ___xnsched_run.part.63+0x2ad (<00000000>)
:|# func                 -14	  0.182  xnlock_dbg_release+0x0 (rtdm_sem_timeddown+0x239)
:|# func                 -14	  0.154  __ipipe_restore_head+0x0 (rtdm_sem_timeddown+0x1ab)
:|+ end     0x80000000   -14	  0.242  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -14	  0.193  rt_udp_recvmsg+0x105 [rtudp] (<00000000>)
:|# func                 -14	  0.165  xnsched_lock+0x0 (rt_udp_recvmsg+0x14b [rtudp])
:|# func                 -13	  0.222  xnsched_unlock+0x0 (rt_udp_recvmsg+0x178 [rtudp])
:|# func                 -13	  0.164  __ipipe_restore_head+0x0 (rt_udp_recvmsg+0x1ad [rtudp])
:|+ end     0x80000000   -13	  0.151  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -13	  0.874  rtnet_put_arg+0x0 [rtnet] (rt_udp_recvmsg+0x200 [rtudp])
: + func                 -12	  0.278  rtnet_put_arg+0x0 [rtnet] (rt_udp_recvmsg+0x330 [rtudp])
: + func                 -12	  0.291  rtdm_get_iov_flatlen+0x0 (rt_udp_recvmsg+0x37e [rtudp])
: + func                 -11	  0.171  rtnet_write_to_iov+0x0 [rtnet] (rt_udp_recvmsg+0x414 [rtudp])
: + func                 -11	  0.335  rtnet_put_arg+0x0 [rtnet] (rtnet_write_to_iov+0x86 [rtnet])
: + func                 -11	  0.147  kfree_rtskb+0x0 [rtnet] (rt_udp_recvmsg+0x21e [rtudp])
:|+ begin   0x80000000   -11	  0.193  kfree_rtskb+0xb2 [rtnet] (<00000000>)
:|# func                 -11	  0.180  xnsched_lock+0x0 (kfree_rtskb+0xe2 [rtnet])
:|# func                 -10	  0.196  xnsched_unlock+0x0 (kfree_rtskb+0xfc [rtnet])
:|# func                 -10	  0.169  __ipipe_restore_head+0x0 (kfree_rtskb+0x12f [rtnet])
:|+ end     0x80000000   -10	  0.162  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -10	  0.153  rtskb_pool_queue_tail+0x0 [rtnet] (kfree_rtskb+0x13f [rtnet])
:|+ begin   0x80000000   -10	  0.191  rtskb_pool_queue_tail+0x23 [rtnet] (<00000000>)
:|# func                  -9	  0.209  xnsched_lock+0x0 (rtskb_pool_queue_tail+0x5c [rtnet])
:|# func                  -9	  0.149  rtskb_nop_pool_unlock+0x0 [rtnet] (rtskb_pool_queue_tail+0x89 [rtnet])
:|# func                  -9	  0.209  xnsched_unlock+0x0 (rtskb_pool_queue_tail+0x92 [rtnet])
:|# func                  -9	  0.154  __ipipe_restore_head+0x0 (kfree_rtskb+0x13f [rtnet])
:|+ end     0x80000000    -9	  0.278  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000001    -8	  0.184  rtdm_fd_recvmsg+0x174 (<00000000>)
:|+ end     0x80000001    -8	  0.174  rtdm_fd_recvmsg+0x18d (<00000000>)
: + func                  -8	  0.164  rtdm_fd_put+0x0 (rtdm_fd_recvmsg+0x147)
:|+ begin   0x80000000    -8	  0.184  rtdm_fd_put+0x22 (<00000000>)
:|# func                  -8	  0.154  xnlock_dbg_prepare_acquire+0x0 (rtdm_fd_put+0x54)
:|# func                  -8	  0.153  xnlock_dbg_acquired+0x0 (rtdm_fd_put+0x92)
:|# func                  -7	  0.154  __put_fd+0x0 (rtdm_fd_put+0x9d)
:|# func                  -7	  0.180  xnlock_dbg_release+0x0 (__put_fd+0xa8)
:|# func                  -7	  0.156  __ipipe_restore_head+0x0 (__put_fd+0x6f)
:|+ end     0x80000000    -7	  0.284  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000001    -7	  0.173  CoBaLt_recvmsg+0x172 (<00000000>)
:|+ end     0x80000001    -6+   1.188  CoBaLt_recvmsg+0x18d (<00000000>)
:|+ begin   0x80000000    -5+   3.917  do_syscall_64+0x57 (<00000000>)
:|+ func                  -1	  0.471  do_syscall_64+0x0 (entry_SYSCALL_64_after_hwframe+0x42)
:|+ end     0x80000000    -1	  0.171  do_syscall_64+0x14f (<00000000>)
: + func                  -1	  0.238  ipipe_handle_syscall+0x0 (do_syscall_64+0x37)
: + func                  -1	  0.194  ipipe_fastcall_hook+0x0 (ipipe_handle_syscall+0x5a)
: + func                   0	  0.553  handle_head_syscall+0x0 (ipipe_fastcall_hook+0x14)
: + func                   0	  0.258  CoBaLt_trace+0x0 (handle_head_syscall+0x100)
< + freeze  0x0000000f     0	  0.404  CoBaLt_trace+0xdd (<00000000>)
 |+ begin   0x80000000     0	  1.275  do_syscall_64+0x57 (<00000000>)
 |+ func                   1	  0.377  do_syscall_64+0x0 (entry_SYSCALL_64_after_hwframe+0x42)
 |+ end     0x80000000     2	  0.162  do_syscall_64+0x14f (<00000000>)
  + func                   2	  0.158  ipipe_handle_syscall+0x0 (do_syscall_64+0x37)
  + func                   2	  0.151  ipipe_fastcall_hook+0x0 (ipipe_handle_syscall+0x5a)
  + func                   2	  0.240  handle_head_syscall+0x0 (ipipe_fastcall_hook+0x14)
  + func                   2	  0.156  CoBaLt_sendmsg+0x0 (handle_head_syscall+0x100)
 |+ begin   0x80000001     2	  0.162  CoBaLt_sendmsg+0x9b (<00000000>)
 |+ end     0x80000001     3	  0.293  CoBaLt_sendmsg+0xb5 (<00000000>)
  + func                   3	  0.000  rtdm_fd_sendmsg+0x0 (CoBaLt_sendmsg+0x7c)
-------------- next part --------------
Here is a test of rtt-responder on qemu.
I use the ipipe-trace api to freeze trancing from C code.
I see that rtdm_fd_recvmsg and rtdm_fd_sendmsg are called
(and I wanted to see that).

I have some questions (I have some ideas but just want to be sure). 
Please answer to those that have relevance.

1. On Hard IRQs column, I see only ':' and space; what do they mean?
What does mean ('|': locked) from Hard IRQs?
2. On Xenomai column I see only '|' and space; what do they mean?
3. What does the following column mean:
Linux ('*': domain stalled, '+': current, '#': current+stalled)
4. Type 'func' I think it means a function is called; correct?
What do 'begin' and 'end' mean on the Type column? Are they important?
5. NMI noise 'N' ?


I-pipe frozen back-tracing service on 4.14.71/ipipe release #2112
------------------------------------------------------------
CPU: 0, Freeze: 1176197529135 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.074 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                 -27	  0.574  xnsynch_wakeup_one_sleeper+0x0 (rtdm_sem_up+0xed)
:|# func                 -26	  0.406  xnthread_resume+0x0 (xnsynch_wakeup_one_sleeper+0x14a)
:|# [  121] rtt-res 81   -26	  0.184  xnthread_resume+0x113 (<00000000>)
:|# func                 -26	  0.149  xnsched_rt_enqueue+0x0 (xnthread_resume+0x14f)
:|# func                 -26	  0.335  xnsched_addq_tail+0x0 (xnthread_resume+0x14f)
:|# func                 -25	  0.185  ___xnsched_run+0x0 (rtdm_sem_up+0x18d)
:|# func                 -25	  0.202  ___xnsched_run.part.63+0x0 (rtdm_sem_up+0x18d)
:|# [  100] rtnet-s 98   -25	  0.165  ___xnsched_run.part.63+0x102 (<00000000>)
:|# func                 -25	  0.207  xnsched_pick_next+0x0 (___xnsched_run.part.63+0x137)
:|# func                 -25	  0.160  xnsched_rt_requeue+0x0 (xnsched_pick_next+0x56)
:|# func                 -24	  0.193  xnsched_addq+0x0 (xnsched_pick_next+0x56)
:|# func                 -24	  0.165  xnsched_rt_pick+0x0 (xnsched_pick_next+0x8b)
:|# func                 -24	  0.200  del_q+0x0 (xnsched_rt_pick+0x5a)
:|# func                 -24	  0.198  xnlock_dbg_release+0x0 (rtdm_sem_up+0x1b2)
:|# func                 -24	  0.156  __ipipe_restore_head+0x0 (rtdm_sem_up+0x14c)
:|+ end     0x80000000   -23	  0.142  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -23	  0.193  rt_udp_rcv+0xe4 [rtudp] (<00000000>)
:|# func                 -23	  0.156  xnsched_lock+0x0 (rt_udp_rcv+0x11c [rtudp])
:|# func                 -23	  0.185  xnsched_unlock+0x0 (rt_udp_rcv+0x136 [rtudp])
:|# func                 -23	  0.156  __ipipe_restore_head+0x0 (rt_udp_rcv+0x15a [rtudp])
:|+ end     0x80000000   -23	  0.209  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -22	  0.153  rtdm_fd_unlock+0x0 (rt_ip_rcv+0x15a [rtipv4])
:|+ begin   0x80000000   -22	  0.189  rtdm_fd_unlock+0x22 (<00000000>)
:|# func                 -22	  0.160  xnlock_dbg_prepare_acquire+0x0 (rtdm_fd_unlock+0x54)
:|# func                 -22	  0.193  xnlock_dbg_acquired+0x0 (rtdm_fd_unlock+0x92)
:|# func                 -22	  0.169  __put_fd+0x0 (rtdm_fd_unlock+0xa4)
:|# func                 -22	  0.180  xnlock_dbg_release+0x0 (__put_fd+0xa8)
:|# func                 -21	  0.158  __ipipe_restore_head+0x0 (__put_fd+0x6f)
:|+ end     0x80000000   -21	  0.169  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -21	  0.191  rt_stack_deliver+0x293 [rtnet] (<00000000>)
:|# func                 -21	  0.267  xnsched_lock+0x0 (rt_stack_deliver+0x2c8 [rtnet])
:|# func                 -21	  0.313  module_put+0x0 (rt_stack_deliver+0x2d4 [rtnet])
:|# func                 -20	  0.225  xnsched_unlock+0x0 (rt_stack_deliver+0x2e8 [rtnet])
:|# func                 -20	  0.153  __ipipe_restore_head+0x0 (rt_stack_mgr_task+0x6b [rtnet])
:|+ end     0x80000000   -20	  0.184  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -20	  0.162  rtdm_event_wait+0x0 (rt_stack_mgr_task+0x2c [rtnet])
: + func                 -20	  0.236  rtdm_event_timedwait+0x0 (rt_stack_mgr_task+0x2c [rtnet])
:|+ begin   0x80000000   -19	  0.194  rtdm_event_timedwait+0xb1 (<00000000>)
:|# func                 -19	  0.154  xnlock_dbg_prepare_acquire+0x0 (rtdm_event_timedwait+0xed)
:|# func                 -19	  0.200  xnlock_dbg_acquired+0x0 (rtdm_event_timedwait+0x131)
:|# func                 -19	  0.344  xnsynch_sleep_on+0x0 (rtdm_event_timedwait+0x316)
:|# func                 -18	  0.315  xnthread_suspend+0x0 (xnsynch_sleep_on+0x221)
:|# func                 -18	  0.185  ___xnsched_run+0x0 (xnthread_suspend+0x4cc)
:|# func                 -18	  0.169  ___xnsched_run.part.63+0x0 (xnthread_suspend+0x4cc)
:|# [  100] rtnet-s 98   -18	  0.154  ___xnsched_run.part.63+0x102 (<00000000>)
:|# func                 -18	  0.184  xnsched_pick_next+0x0 (___xnsched_run.part.63+0x137)
:|# func                 -17	  0.156  xnsched_rt_pick+0x0 (xnsched_pick_next+0x8b)
:|# func                 -17	  0.300  del_q+0x0 (xnsched_rt_pick+0x5a)
:|# func                 -17	  0.153  xnarch_switch_to+0x0 (___xnsched_run.part.63+0x22b)
:|# func                 -17	  0.395  switch_mm_irqs_off+0x0 (xnarch_switch_to+0x2a)
:|# func                 -16+   1.268  __phys_addr+0x0 (switch_mm_irqs_off+0x1c7)
:|# func                 -15	  0.149  xnthread_switch_fpu+0x0 (___xnsched_run.part.63+0x290)
:|# func                 -15	  0.209  xnarch_switch_fpu+0x0 (xnthread_switch_fpu+0x26)
:|# [  121] rtt-res 81   -15	  0.517  ___xnsched_run.part.63+0x2ad (<00000000>)
:|# func                 -14	  0.182  xnlock_dbg_release+0x0 (rtdm_sem_timeddown+0x239)
:|# func                 -14	  0.154  __ipipe_restore_head+0x0 (rtdm_sem_timeddown+0x1ab)
:|+ end     0x80000000   -14	  0.242  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000000   -14	  0.193  rt_udp_recvmsg+0x105 [rtudp] (<00000000>)
:|# func                 -14	  0.165  xnsched_lock+0x0 (rt_udp_recvmsg+0x14b [rtudp])
:|# func                 -13	  0.222  xnsched_unlock+0x0 (rt_udp_recvmsg+0x178 [rtudp])
:|# func                 -13	  0.164  __ipipe_restore_head+0x0 (rt_udp_recvmsg+0x1ad [rtudp])
:|+ end     0x80000000   -13	  0.151  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -13	  0.874  rtnet_put_arg+0x0 [rtnet] (rt_udp_recvmsg+0x200 [rtudp])
: + func                 -12	  0.278  rtnet_put_arg+0x0 [rtnet] (rt_udp_recvmsg+0x330 [rtudp])
: + func                 -12	  0.291  rtdm_get_iov_flatlen+0x0 (rt_udp_recvmsg+0x37e [rtudp])
: + func                 -11	  0.171  rtnet_write_to_iov+0x0 [rtnet] (rt_udp_recvmsg+0x414 [rtudp])
: + func                 -11	  0.335  rtnet_put_arg+0x0 [rtnet] (rtnet_write_to_iov+0x86 [rtnet])
: + func                 -11	  0.147  kfree_rtskb+0x0 [rtnet] (rt_udp_recvmsg+0x21e [rtudp])
:|+ begin   0x80000000   -11	  0.193  kfree_rtskb+0xb2 [rtnet] (<00000000>)
:|# func                 -11	  0.180  xnsched_lock+0x0 (kfree_rtskb+0xe2 [rtnet])
:|# func                 -10	  0.196  xnsched_unlock+0x0 (kfree_rtskb+0xfc [rtnet])
:|# func                 -10	  0.169  __ipipe_restore_head+0x0 (kfree_rtskb+0x12f [rtnet])
:|+ end     0x80000000   -10	  0.162  __ipipe_restore_head+0x4d (<00000000>)
: + func                 -10	  0.153  rtskb_pool_queue_tail+0x0 [rtnet] (kfree_rtskb+0x13f [rtnet])
:|+ begin   0x80000000   -10	  0.191  rtskb_pool_queue_tail+0x23 [rtnet] (<00000000>)
:|# func                  -9	  0.209  xnsched_lock+0x0 (rtskb_pool_queue_tail+0x5c [rtnet])
:|# func                  -9	  0.149  rtskb_nop_pool_unlock+0x0 [rtnet] (rtskb_pool_queue_tail+0x89 [rtnet])
:|# func                  -9	  0.209  xnsched_unlock+0x0 (rtskb_pool_queue_tail+0x92 [rtnet])
:|# func                  -9	  0.154  __ipipe_restore_head+0x0 (kfree_rtskb+0x13f [rtnet])
:|+ end     0x80000000    -9	  0.278  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000001    -8	  0.184  rtdm_fd_recvmsg+0x174 (<00000000>)
:|+ end     0x80000001    -8	  0.174  rtdm_fd_recvmsg+0x18d (<00000000>)
: + func                  -8	  0.164  rtdm_fd_put+0x0 (rtdm_fd_recvmsg+0x147)
:|+ begin   0x80000000    -8	  0.184  rtdm_fd_put+0x22 (<00000000>)
:|# func                  -8	  0.154  xnlock_dbg_prepare_acquire+0x0 (rtdm_fd_put+0x54)
:|# func                  -8	  0.153  xnlock_dbg_acquired+0x0 (rtdm_fd_put+0x92)
:|# func                  -7	  0.154  __put_fd+0x0 (rtdm_fd_put+0x9d)
:|# func                  -7	  0.180  xnlock_dbg_release+0x0 (__put_fd+0xa8)
:|# func                  -7	  0.156  __ipipe_restore_head+0x0 (__put_fd+0x6f)
:|+ end     0x80000000    -7	  0.284  __ipipe_restore_head+0x4d (<00000000>)
:|+ begin   0x80000001    -7	  0.173  CoBaLt_recvmsg+0x172 (<00000000>)
:|+ end     0x80000001    -6+   1.188  CoBaLt_recvmsg+0x18d (<00000000>)
:|+ begin   0x80000000    -5+   3.917  do_syscall_64+0x57 (<00000000>)
:|+ func                  -1	  0.471  do_syscall_64+0x0 (entry_SYSCALL_64_after_hwframe+0x42)
:|+ end     0x80000000    -1	  0.171  do_syscall_64+0x14f (<00000000>)
: + func                  -1	  0.238  ipipe_handle_syscall+0x0 (do_syscall_64+0x37)
: + func                  -1	  0.194  ipipe_fastcall_hook+0x0 (ipipe_handle_syscall+0x5a)
: + func                   0	  0.553  handle_head_syscall+0x0 (ipipe_fastcall_hook+0x14)
: + func                   0	  0.258  CoBaLt_trace+0x0 (handle_head_syscall+0x100)
< + freeze  0x0000000f     0	  0.404  CoBaLt_trace+0xdd (<00000000>)
 |+ begin   0x80000000     0	  1.275  do_syscall_64+0x57 (<00000000>)
 |+ func                   1	  0.377  do_syscall_64+0x0 (entry_SYSCALL_64_after_hwframe+0x42)
 |+ end     0x80000000     2	  0.162  do_syscall_64+0x14f (<00000000>)
  + func                   2	  0.158  ipipe_handle_syscall+0x0 (do_syscall_64+0x37)
  + func                   2	  0.151  ipipe_fastcall_hook+0x0 (ipipe_handle_syscall+0x5a)
  + func                   2	  0.240  handle_head_syscall+0x0 (ipipe_fastcall_hook+0x14)
  + func                   2	  0.156  CoBaLt_sendmsg+0x0 (handle_head_syscall+0x100)
 |+ begin   0x80000001     2	  0.162  CoBaLt_sendmsg+0x9b (<00000000>)
 |+ end     0x80000001     3	  0.293  CoBaLt_sendmsg+0xb5 (<00000000>)
  + func                   3	  0.000  rtdm_fd_sendmsg+0x0 (CoBaLt_sendmsg+0x7c)


More information about the Xenomai mailing list