Re: [Xenomai] rtdm_nrtsig_pend FAQ

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

Am 14.11.2014 um 11:20 schrieb Gilles Chanteperdrix:
> On Fri, Nov 14, 2014 at 10:53:31AM +0100, Johann Obermayr wrote:
>> Am 13.11.2014 um 17:33 schrieb Gilles Chanteperdrix:
>>> On Thu, Nov 13, 2014 at 05:30:34PM +0100, Johann Obermayr wrote:
>>>> Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
>>>>> On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
>>>>>> Hello,
>>>>>>
>>>>>> we use rtdm_nrtsig_pend follow.
>>>>>>
>>>>>> static rtdm_nrtsig_t wait_domain_nrt;
>>>>>> static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
>>>>>>
>>>>>> void period_update()
>>>>>> {
>>>>>>          wait_domain_pend_count++;
>>>>>>          rtdm_nrtsig_pend(&wait_domain_nrt);
>>>>>> }
>>>>>>
>>>>>> static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
>>>>>> {
>>>>>>      wait_domain_call_count++;
>>>>>>      //wakeup wait_domain
>>>>>>      wait_domain_wakeup = 1;
>>>>>>      wake_up_interruptible(&wait_domain_wq);
>>>>>> }
>>>>>>
>>>>>>
>>>>>> period_update is called every millisecond.
>>>>>> this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
>>>>> >From what Thierry said, I suspect the patch for this kernel has a
>>>>> missing call to irq_exit. So, I would ask you to do the same as
>>>>> Thierry, please enable the I-pipe tracer, set a sufficient number of
>>>>> back trace points such as 10000, and trigger a trace when you detect
>>>>> that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
>>>>>
>>>>> Then send the trace to the mailing list.
>>>>>
>>>> Hi,
>>>>
>>>> witch function i must use to make a i-pipe trace ?
>>>> here i am in a xenomai irq handle
>>>>
>>>> void period_update()
>>>> {
>>>>      ......
>>>>      else if (wait_domain_pend_count > 100000 &&
>>>> wait_domain_pend_count != wait_domain_call_count) {
>>>>              // dotrace
>>>>
>>>>       }
>>>> }
>>> ipipe_trace_freeze. Requires a numeric argument, which has no
>>> particular meaning, it just gets printed in the trace.
>>>
>>> The I-pipe tracer is documented here:
>>> http://xenomai.org/2014/06/using-the-i-pipe-tracer/
>>>
>> Hello,
>>
>> here is the trace
> Your trace show several things:
> - period_update in your program does not correspond to the sources
> you showed:
>
> :   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> :   +*func                -759    1.000  lrtdrv_monitoring_start_timed+0x10 [sigmatek_lrt] (period_update+0x34 [sigmatek_lrt])
> :   +*func                -758    0.750  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
> :|  #*func                -757    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
> :|  #*func                -756    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
> :   +*func                -756    0.500  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
> :|  #*func                -755    0.500  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
> :|  #*func                -755    0.750  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
> :   +*func                -754    0.500  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
> :|  #*func                -754    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
> :|  #*func                -753    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
> :   +*func                -753    0.250  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
> :|  #*func                -752    1.000  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
> :|  #*func                -751    0.250  xnpod_resume_thread+0x10 (xnsynch_flush+0xa4)
> :|  #*[ 1065] WD-Trigg 1  -751    0.750  xnpod_resume_thread+0x54 (xnsynch_flush+0xa4)
> :|  #*func                -750    0.500  __xnpod_schedule+0x14 (__rtdm_synch_flush+0x84)
> :|  #*[   -1] -<?>-   99  -750    0.250  __xnpod_schedule+0x50 (__rtdm_synch_flush+0x84)
> :|  #*func                -750    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> :|  #*func                -749    0.500  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
> :   +*func                -748    0.750  ipipe_trigger_irq+0x10 (period_update+0x224 [sigmatek_lrt])
> :|  +*func                -748    0.500  __ipipe_handle_irq+0x14 (ipipe_trigger_irq+0x64)
>
>
> Before calling nrt_pend, period_update calls rtdm_event_signal,
> which could reschedule and cause the nrt_pend to be delayed (but
> that does not happen in that case).
Yes, it starts some RT tasks. This tasks need 30-100 us.

> - period update is called more often than every millisecond:
>
> :   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
>
> :   +*func                 -16    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> <   +*freeze  0x00023b12     0    0.750  period_update+0x1f4 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])

which can not be, because it is triggerd by a FPGA hardware IRQ every 
millisecond.

> - you have a massive latency, which is causing your real-time job to
> occupy the CPU all the time, and never let Linux run.
It looks as if a mmcqd task (micro SD card) will stop calling software irq.

> :|  #*[ 1065] WD-Trigg 1  -722    0.500  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
> :|  #*func                -722    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> :|  #*func                -721    0.250  ipipe_unmute_pic+0x10 (__xnpod_schedule+0x1e4)
> :|  #*func                -721    1.000  gic_unmute+0x10 (ipipe_unmute_pic+0x18)
> :|  #*func                -720+   1.250  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
> :   +*func                -719    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
> :|  #*[  700] mmcqd/0 -1  -718    0.750  __xnpod_schedule+0x3b0 (xnintr_clock_handler+0x118)
> :|  #*func                -717    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
> :|  #*func                -717    0.750  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
> :|  #*func                -716    0.750  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
> :|  #*func                -715    1.000  xnarch_tsc_to_ns+0x10 (measureIdleTime+0xac [sigmatek_lrt])
> :|   #func                -714    0.750  __ipipe_walk_pipeline+0x10 (__ipipe_dispatch_wired_nocheck+0xa4)
> :|   #func                -714! 674.750  __ipipe_exit_irq+0x10 (__ipipe_grab_irq+0x60)
> :|   #func                 -39    0.500  __ipipe_grab_irq+0x10 (__irq_svc+0x40)
>
> I believe this latency issue is due to the L2 cache write-allocate
> bit that was fixed in the latest I-pipe patch. Please upgrade the
> I-pipe patch, check/fix the issues above, and post another trace if
> you still have the issue.
>

i test it with the new patches.



Here is the period_update function

void period_update(unsigned long ovr)
{
     struct list_head *lh;

     timer_overruns += ovr;
     timer_ticks++;

     lrtdrv_monitoring_start_timed(timer_ticks);

     /* we don't need to lock the list, we are the highest priority task
      * and if other ctx are added to/removed from the list, the list is 
locked there
      */
     list_for_each(lh, &lrtdrv_opendev_list) {
         lrtdrv_context_t *ctx = list_entry(lh, lrtdrv_context_t, 
opendev_entry);

         if (WATCHDOG_CHECK(ctx, 0) || WATCHDOG_CHECK(ctx, 1)) {
             // Watch DOG aufgetretten, also brauch ich nichts mehr machen
         } else {
             rtdm_event_signal(&ctx->rtt_timer_wait);
             rtdm_event_pulse(&ctx->timer_wait);
         }
     }
     if (wait_domain_pend_count == 100000)
         wait_domain_call_count = wait_domain_pend_count;
     else if (wait_domain_pend_count > 100000 && wait_domain_pend_count 
!= wait_domain_call_count) {
static int trace_count = 0;
         if (trace_count == 0) {
             trace_count++;
             // dotrace
             printk(KERN_INFO "IPIPE-Trace");
             ipipe_trace_freeze(wait_domain_pend_count);
         }
     }
     // NRT IRQ - start background
     if(wait_domain_nrt_setup) {
         wait_domain_pend_count++;
         rtdm_nrtsig_pend(&wait_domain_nrt);
     } else {
         wait_domain_nopend_count++;
     }
}

best regards
  Johann