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: signature.asc
Description: OpenPGP digital signature

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

Reply via email to