Re: [Xenomai] usage of rtdm_task_sleep_abs

[Johann Obermayr <johann.obermayr@sigmatek.at>]

Am 13.07.2015 um 17:24 schrieb Gilles Chanteperdrix:
> Johann Obermayr wrote:
>> without your application, there are no large latencies.
>> with your application see frozen.txt (with latency -f)
> I am confused. You mean "our application", not "your application", right?
> lrtdrv_monitoring_irq is not part of the code delivered by the Xenomai
> project.
>
>> We see the problem only if one task (background) is accessing the SRAM
>> on your PCI-Card. if we stop this task, all is ok.
> Again: the Xenomai project does not make PCI-card. So, you probably mean
> "our PCI-Card"?
yes, our PCI-Card. (sorry for my bad english)
>> So we have a higher prior task (pci-locker), that interrupt the
>> background task, so that the pci bus get free.
> I am not sure I understand your explanations. But the trace is pretty clear:
>
> At time -658 the timer is programmed to tick at -561.
>
>> :|  # event   tick@-561   -658	  0.112  xntimer_next_local_shot+0xca
>
>> :|  + func                -651	  0.145  lrtdrv_monitoring_irq+0x4
>> [sigmatek_lrt] (irq_hook_handler+0x32 [sigmatek_lrt])
>> :|  + end     0x000000ef  -651! 641.640  apic_timer_interrupt+0x52
>> (<102d0254>)
> But at that point the tick is delayed for 600us. And according to the
> trace, the last traced function called before that delay is the function
>
> ltdrv_monitoring_irq.
>
> So, I do not know what this irq is doing, but I would suggest having a
> close look at it.
>
>
hello,

i have disable our lrtdrv_monitoring_irq.
Only have this callback
static void irq_hook_handler(unsigned int irq, unsigned int state)
{
     if (fpga_interrupt == irq && state == 0x01)
     {
         time_fpga_irq = rt_timer_tsc();
     }
}
same latency

regards
   Johann
-------------- next part --------------
I-pipe frozen back-tracing service on 3.10.0/ipipe release #1
------------------------------------------------------------
CPU: 0, Freeze: 897546816952 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.078 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                -700	  0.222  measureIdleTime+0x9 [sigmatek_lrt] (taskSwitchXenomai+0x9a [sigmatek_lrt])
:|  # func                -700	  0.163  xntimer_get_overruns+0x8 (xnpod_wait_thread_period+0x93)
:|  # func                -700	  0.136  __ipipe_restore_head+0x4 (ipipe_restore_pipeline_head+0x42)
:|  + end     0x80000000  -699	  0.188  hard_local_irq_enable+0x16 (__ipipe_restore_head+0x66)
:|  + begin   0x80000001  -699	  0.173  hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6b)
:|  + end     0x80000001  -699	  0.144  hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xad)
:|  + begin   0x80000000  -699	  0.161  hard_local_irq_disable+0x17 (__ipipe_syscall_root+0x38)
:|  + end     0x80000000  -699	  0.311  __ipipe_syscall_root+0x70 (sysenter_past_esp+0x5b)
:   + func                -698	  0.118  __ipipe_syscall_root+0x5 (sysenter_past_esp+0x5b)
:   + func                -698	  0.120  __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x31)
:|  + begin   0x80000001  -698	  0.188  hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
:|  + end     0x80000001  -698	  0.126  hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x59)
:   + func                -698	  0.120  ipipe_syscall_hook+0x7 (__ipipe_notify_syscall+0x64)
:|  + begin   0x80000001  -698	  0.145  hard_local_irq_save+0x16 (ipipe_syscall_hook+0x1b)
:|  + end     0x80000001  -698	  0.126  hard_local_irq_restore+0x15 (ipipe_syscall_hook+0x5b)
:   + func                -698	  0.127  hisyscall_event+0x9 (ipipe_syscall_hook+0x6b)
:   + func                -697	  0.114  __rt_task_wait_period+0x5 (hisyscall_event+0x129)
:   + func                -697	  0.118  rt_task_wait_period+0x4 (__rt_task_wait_period+0x14)
:   + func                -697	  0.123  xnpod_wait_thread_period+0x9 (rt_task_wait_period+0x44)
:|  + begin   0x80000000  -697	  0.166  hard_local_irq_disable+0x15 (__xnlock_get_irqsave.constprop.43+0x9)
:|  # func                -697	  0.145  xnpod_suspend_thread+0x9 (xnpod_wait_thread_period+0x6c)
:|  # func                -697	  0.167  __xnpod_schedule+0x9 (xnpod_schedule+0x32)
:|  # [  613] -<?>-   99  -697	  0.117  __xnpod_schedule+0x58 (xnpod_schedule+0x32)
:|  # func                -696	  0.291  xnsched_pick_next+0x5 (__xnpod_schedule+0xa5)
:|  # func                -696	  0.270  __switch_to+0x9 (__xnpod_schedule+0x3b8)
:|  # [  603] cyclic: 30  -696	  0.273  __xnpod_schedule+0x431 (xnpod_schedule+0x32)
:|  # func                -696	  0.118  xnpod_fire_callouts+0x7 (__xnpod_schedule+0x4b4)
:|  # func                -695	  0.117  taskSwitchXenomai+0x9 [sigmatek_lrt] (xnpod_fire_callouts+0x4c)
:|  # func                -695	  0.135  measureIdleTime+0x9 [sigmatek_lrt] (taskSwitchXenomai+0x9a [sigmatek_lrt])
:|  # func                -695	  0.279  xnarch_tsc_to_ns+0x6 (measureIdleTime+0xae [sigmatek_lrt])
:|   +func                -695	  0.200  __ipipe_do_sync_pipeline+0x4 (__ipipe_dispatch_irq+0x1c1)
:|   +func                -695	  0.163  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_handle_irq+0x10e)
:|   +end     0x000000ef  -695! 682.112  apic_timer_interrupt+0x52 (<102d0251>)
:|   +begin   0x000000ef   -12	  0.145  apic_timer_interrupt+0x3a (<10139c1a>)
:|   +func                 -12	  0.158  __ipipe_handle_irq+0x7 (apic_timer_interrupt+0x41)
:|   +func                 -12	  0.114  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_handle_irq+0xc4)
:|   +func                 -12	  0.117  __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xce)
:|   +func                 -12	  0.132  __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0xa9)
:|   +func                 -12	  0.145  lapic_itimer_ack+0x3 (__ipipe_ack_hrtimer_irq+0x59)
:|   +func                 -12	  0.170  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_dispatch_irq+0x118)
:|  # func                 -11	  0.114  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_dispatch_irq+0x172)
:|  # func                 -11	  0.216  xnintr_clock_handler+0x9 (__ipipe_dispatch_irq+0x182)
:|  # func                 -11	  0.149  xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0xb9)
:|  # func                 -11	  0.115  xnthread_periodic_handler+0x3 (xntimer_tick_aperiodic+0xa0)
:|  # func                 -11	  0.136  xnpod_resume_thread+0x9 (xnthread_periodic_handler+0x20)
:|  # [  613] -<?>-   99   -11	  0.273  xnpod_resume_thread+0x39 (xnthread_periodic_handler+0x20)
:|  # func                 -10	  0.135  xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x177)
:|  # event   tick@-5      -10	  0.112  xntimer_next_local_shot+0xca (xntimer_tick_aperiodic+0x177)
:|  # func                 -10	  0.133  ipipe_timer_set+0x5 (xntimer_next_local_shot+0xd1)
:|  # func                 -10	  0.253  lapic_next_deadline+0x5 (ipipe_timer_set+0x67)
:|  # func                 -10	  0.176  __xnpod_schedule+0x9 (xnpod_schedule+0x32)
:|  # [  603] cyclic: 30   -10	  0.120  __xnpod_schedule+0x58 (xnpod_schedule+0x32)
:|  # func                 -10	  0.135  xnsched_pick_next+0x5 (__xnpod_schedule+0xa5)
:|  # func                  -9	  0.366  __ipipe_notify_vm_preemption+0x4 (__xnpod_schedule+0x141)
:|  # func                  -9	  0.302  __switch_to+0x9 (__xnpod_schedule+0x3b8)
:|  # [  613] -<?>-   99    -9	  0.195  __xnpod_schedule+0x431 (xnpod_schedule+0x32)
:|  # func                  -9	  0.121  xnpod_fire_callouts+0x7 (__xnpod_schedule+0x4b4)
:|  # func                  -8	  0.144  taskSwitchXenomai+0x9 [sigmatek_lrt] (xnpod_fire_callouts+0x4c)
:|  # func                  -8	  0.221  measureIdleTime+0x9 [sigmatek_lrt] (taskSwitchXenomai+0x9a [sigmatek_lrt])
:|  # func                  -8	  0.237  xntimer_get_overruns+0x8 (xnpod_wait_thread_period+0x93)
:|  # func                  -8	  0.149  __ipipe_restore_head+0x4 (ipipe_restore_pipeline_head+0x42)
:|  + end     0x80000000    -8	  0.194  hard_local_irq_enable+0x16 (__ipipe_restore_head+0x66)
:|  + begin   0x80000001    -7	  0.182  hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6b)
:|  + end     0x80000001    -7	  0.158  hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xad)
:|  + begin   0x80000000    -7	  0.160  hard_local_irq_disable+0x17 (__ipipe_syscall_root+0x38)
:|  + end     0x80000000    -7+   1.064  __ipipe_syscall_root+0x70 (sysenter_past_esp+0x5b)
:   + func                  -6	  0.126  __ipipe_syscall_root+0x5 (sysenter_past_esp+0x5b)
:   + func                  -6	  0.130  __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x31)
:|  + begin   0x80000001    -6	  0.187  hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
:|  + end     0x80000001    -5	  0.127  hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x59)
:   + func                  -5	  0.120  ipipe_syscall_hook+0x7 (__ipipe_notify_syscall+0x64)
:|  + begin   0x80000001    -5	  0.145  hard_local_irq_save+0x16 (ipipe_syscall_hook+0x1b)
:|  + end     0x80000001    -5	  0.126  hard_local_irq_restore+0x15 (ipipe_syscall_hook+0x5b)
:   + func                  -5	  0.288  hisyscall_event+0x9 (ipipe_syscall_hook+0x6b)
:   + func                  -5	  0.242  xnshadow_sys_trace+0x6 (hisyscall_event+0x129)
:   + func                  -4	  0.368  ipipe_trace_frozen_reset+0x5 (xnshadow_sys_trace+0x5e)
:|  + begin   0x000000ef    -4	  0.155  apic_timer_interrupt+0x3a (__ipipe_global_path_lock+0x0)
:|  + func                  -4	  0.160  __ipipe_handle_irq+0x7 (apic_timer_interrupt+0x41)
:|  + func                  -4	  0.117  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_handle_irq+0xc4)
:|  + func                  -4	  0.117  __ipipe_dispatch_irq+0x9 (__ipipe_handle_irq+0xce)
:|  + func                  -3	  0.138  __ipipe_ack_hrtimer_irq+0x6 (__ipipe_dispatch_irq+0xa9)
:|  + func                  -3	  0.141  lapic_itimer_ack+0x3 (__ipipe_ack_hrtimer_irq+0x59)
:|  + func                  -3	  0.154  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_dispatch_irq+0x118)
:|  # func                  -3	  0.126  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_dispatch_irq+0x172)
:|  # func                  -3	  0.234  xnintr_clock_handler+0x9 (__ipipe_dispatch_irq+0x182)
:|  # func                  -3	  0.559  __xnlock_spin+0x4 (__xnlock_get+0x2b)
:|  # func                  -2	  0.136  xntimer_tick_aperiodic+0x9 (xnintr_clock_handler+0xb9)
:|  # func                  -2	  0.176  xnthread_periodic_handler+0x3 (xntimer_tick_aperiodic+0xa0)
:|  # func                  -2	  0.136  xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x177)
:|  # event   tick@94       -2	  0.112  xntimer_next_local_shot+0xca (xntimer_tick_aperiodic+0x177)
:|  # func                  -2	  0.133  ipipe_timer_set+0x5 (xntimer_next_local_shot+0xd1)
:|  # func                  -1	  0.356  lapic_next_deadline+0x5 (ipipe_timer_set+0x67)
:|  + func                  -1	  0.144  irq_hook_handler+0x3 [sigmatek_lrt] (__ipipe_handle_irq+0x10e)
:|  + end     0x000000ef    -1	  0.201  apic_timer_interrupt+0x52 (__ipipe_global_path_lock+0x0)
:   + func                  -1	  0.132  __ipipe_global_path_lock+0x7 (ipipe_trace_frozen_reset+0x14)
:   + func                  -1	  0.136  __ipipe_spin_lock_irqsave+0x6 (__ipipe_global_path_lock+0x16)
:|  + begin   0x80000001     0	  0.657  hard_local_irq_save+0x16 (__ipipe_spin_lock_irqsave+0x12)
:|  # func                   0	  0.148  __ipipe_spin_unlock_irqcomplete+0x4 (__ipipe_global_path_unlock+0x5f)
:|  + end     0x80000001     0	  0.166  hard_local_irq_restore+0x15 (__ipipe_spin_unlock_irqcomplete+0x25)
<   + freeze  0x00091117     0	  0.179  xnshadow_sys_trace+0x67 (hisyscall_event+0x129)
 |  + begin   0x80000001     0	  0.187  hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x6b)
 |  + end     0x80000001     0	  0.149  hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0xad)
 |  + begin   0x80000000     0	  0.170  hard_local_irq_disable+0x17 (__ipipe_syscall_root+0x38)
 |  + end     0x80000000     0	  0.218  __ipipe_syscall_root+0x70 (sysenter_past_esp+0x5b)
    + func                   0	  0.130  __ipipe_syscall_root+0x5 (sysenter_past_esp+0x5b)
    + func                   1	  0.132  __ipipe_notify_syscall+0x9 (__ipipe_syscall_root+0x31)
 |  + begin   0x80000001     1	  0.176  hard_local_irq_save+0x16 (__ipipe_notify_syscall+0x18)
 |  + end     0x80000001     1	  0.126  hard_local_irq_restore+0x15 (__ipipe_notify_syscall+0x59)
    + func                   1	  0.138  ipipe_syscall_hook+0x7 (__ipipe_notify_syscall+0x64)
 |  + begin   0x80000001     1	  0.000  hard_local_irq_save+0x16 (ipipe_syscall_hook+0x1b)