From mboxrd@z Thu Jan 1 00:00:00 1970 MIME-Version: 1.0 References: In-Reply-To: From: Rajesh Venkataraman Date: Tue, 21 Sep 2021 13:28:11 -0700 Message-ID: Subject: Re: Execution time on Xenomai user thread is high Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable List-Id: Discussions about the Xenomai project List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Greg Gallagher Cc: xenomai@xenomai.org Hi, I added a dummy function like below and called this function from the highest priority xenomai user task. This task runs once every 500 microseconds triggered by a GPIO interrupt from an RTDM driver. Using rt_timer_read() I record the time before and after this dummy function. The duration of this function execution varies from 0 microseconds to 13 microseconds. Why does it vary so much and what is preempting this thread while running this dummy function? If I do the same test on an RTOS the duration varies marginally due to the tick interrupt. Is there a way to either disable this interrupt while running the xenomai thread or a way to reduce the variation? Rajesh void dummy_function(unsigned long dummy) { } On Mon, Sep 13, 2021 at 10:03 PM Rajesh Venkataraman < rajesh_venkataraman@trimble.com> wrote: > Hi Greg, > I added the pthread_setmode_np(0, PTHREAD_WARNSW, NULL); calls to the > real time threads to catch mode switches. I have not found any mode > switches yet. I will enable the debug options to find the latency. But th= e > bigger problem is the higher execution time. It is taking longer to execu= te > the same routine on Xenomai user thread (Highest priority) than on a > traditional RTOS ISR. Is this expected behaviour? Do xenomai threads get > preempted by other system interrupts like timer interrupts? Is there a wa= y > to debug this or prevent this issue? > > Rajesh > > > On Mon, Sep 13, 2021 at 8:43 PM Greg Gallagher > wrote: > >> >> >> On Mon, Sep 13, 2021 at 1:49 PM Rajesh Venkataraman via Xenomai < >> xenomai@xenomai.org> wrote: >> >>> ---------- Forwarded message --------- >>> From: Rajesh Venkataraman >>> Date: Mon, Sep 13, 2021 at 10:41 AM >>> Subject: Re: Execution time on Xenomai user thread is high >>> To: Greg Gallagher >>> >>> >>> Hi Greg, >>> Below are the results of the autotune and latency tests. I do not have >>> any >>> debug features enabled. >>> >>> Rajesh >>> >>> >>> =3D=3D auto-tuning started, period=3D10[Xenomai] autotune(irqhand) star= ted >>> >>> >>> 00000 ns (may take a while) >>> >>> >>> irq gravity... 1333 ns[Xenomai] autotune(kthread) started >>> >>> >>> >>> >>> >>> kernel gravity... 4666 ns >>> >>> >>> [Xenomai] autotune(uthread) started >>> >>> >>> user gravity... 6666 ns[Xenomai] autotune finished [1333i/4666k/6666u] >>> >>> >>> >>> >>> >>> =3D=3D auto-tuning completed after 43s >>> >>> =3D=3D Sampling period: 1000 us >>> >>> >>> =3D=3D Test mode: periodic user-mode task >>> >>> >>> =3D=3D All results in microseconds >>> >>> >>> warming up... >>> >>> >>> RTT| 00:00:01 (periodic user-mode task, 1000 us period, priority 99) >>> >>> >>> RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat best|--l= at >>> worst >>> >>> RTD| 2.333| 2.938| 7.000| 0| 0| 2.333| >>> 7.000 >>> >>> RTD| 2.333| 3.048| 6.666| 0| 0| 2.333| >>> 7.000 >>> >>> RTD| 2.333| 3.022| 7.000| 0| 0| 2.333| >>> 7.000 >>> >>> RTD| 2.333| 3.007| 7.333| 0| 0| 2.333| >>> 7.333 >>> >>> RTD| 2.332| 3.037| 8.999| 0| 0| 2.332| >>> 8.999 >>> >>> RTD| 2.332| 2.967| 6.666| 0| 0| 2.332| >>> 8.999 >>> >>> RTD| 2.332| 2.943| 6.665| 0| 0| 2.332| >>> 8.999 >>> >>> RTD| 2.332| 2.964| 6.665| 0| 0| 2.332| >>> 8.999 >>> >>> RTD| 2.331| 2.930| 6.665| 0| 0| 2.331| >>> 8.999 >>> >>> RTD| 2.331| 2.981| 11.665| 0| 0| 2.331| >>> 11.665 >>> >>> RTD| 2.331| 3.039| 6.998| 0| 0| 2.331| >>> 11.665 >>> >>> RTD| 2.331| 3.012| 7.664| 0| 0| 2.331| >>> 11.665 >>> >>> RTD| 2.330| 2.941| 6.997| 0| 0| 2.330| >>> 11.665 >>> >>> RTD| 2.330| 2.974| 6.664| 0| 0| 2.330| >>> 11.665 >>> >>> RTD| 2.330| 2.952| 6.330| 0| 0| 2.330| >>> 11.665 >>> >>> RTD| 2.330| 2.961| 6.330| 0| 0| 2.330| >>> 11.665 >>> >>> RTD| 2.330| 2.925| 5.996| 0| 0| 2.330| >>> 11.665 >>> >>> RTD| 2.329| 3.022| 7.996| 0| 0| 2.329| >>> 11.665 >>> >>> RTD| 2.329| 2.959| 6.996| 0| 0| 2.329| >>> 11.665 >>> >>> RTD| 2.329| 3.038| 7.662| 0| 0| 2.329| >>> 11.665 >>> >>> RTD| 2.329| 3.031| 8.662| 0| 0| 2.329| >>> 11.665 >>> >>> RTT| 00:00:22 (periodic user-mode task, 1000 us period, priority 99) >>> >>> >>> RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat best|--l= at >>> worst >>> >>> RTD| 2.328| 2.982| 7.662| 0| 0| 2.328| >>> 11.665 >>> >>> RTD| 2.328| 3.030| 6.662| 0| 0| 2.328| >>> 11.665 >>> >>> RTD| 2.328| 2.928| 6.328| 0| 0| 2.328| >>> 11.665 >>> >>> RTD| 2.328| 2.911| 5.994| 0| 0| 2.328| >>> 11.665 >>> >>> RTD| 2.327| 2.975| 7.661| 0| 0| 2.327| >>> 11.665 >>> >>> RTD| 2.327| 3.002| 7.327| 0| 0| 2.327| >>> 11.665 >>> >>> RTD| 2.327| 2.977| 7.327| 0| 0| 2.327| >>> 11.665 >>> >>> RTD| 2.327| 2.939| 6.993| 0| 0| 2.327| >>> 11.665 >>> >>> RTD| 2.326| 2.951| 6.660| 0| 0| 2.326| >>> 11.665 >>> >>> RTD| 2.326| 2.938| 7.326| 0| 0| 2.326| >>> 11.665 >>> >>> RTD| 1.993| 2.890| 6.659| 0| 0| 1.993| >>> 11.665 >>> >>> RTD| 0.659| 2.927| 7.659| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.325| 2.947| 6.992| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.325| 3.008| 7.992| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.325| 2.968| 8.325| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.325| 2.971| 6.325| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.324| 2.926| 5.991| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.324| 2.934| 6.991| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.324| 2.947| 6.324| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.324| 2.897| 6.657| 0| 0| 0.659| >>> 11.665 >>> >>> RTD| 2.324| 2.924| 7.657| 0| 0| 0.659| >>> 11.665 >>> >>> RTT| 00:00:43 (periodic user-mode task, 1000 us period, priority 99) >>> >>> >>> RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat best|--l= at >>> worst >>> >>> RTD| 2.323| 2.937| 6.990| 0| 0| 0.659| >>> 11.665 >>> >>> >>> ^C---|-----------|-----------|-----------|--------|------|-------------= ------------ >>> >>> >>> >>> >>> On Mon, Sep 13, 2021 at 10:11 AM Greg Gallagher >>> wrote: >>> >>> > >>> > >>> > On Mon, Sep 13, 2021 at 1:08 PM Rajesh Venkataraman via Xenomai < >>> > xenomai@xenomai.org> wrote: >>> > >>> >> Hi, >>> >> We recently ported our application to Linux(4.19.25)/Xenomai from >>> RTOS. >>> >> We have time critical routines in our application. This routine is >>> run in >>> >> Xenomai user threads with the highest priority. We run each routine >>> on a >>> >> core(Affinity to the CPU is set up for the threads). We have a RTDM >>> driver >>> >> which triggers these routines. We are seeing a maximum/mean latency = of >>> >> 100/25 microseconds respectively from the interrupt assertion to >>> running >>> >> the real time routine in Xenomai user thread. Our platform is i.MX6 >>> (ARM >>> >> Cortex-A9 Quad Core) running at 996 MHz. Is that latency reasonable >>> for >>> >> Xemonai? We are also seeing something strange. The execution time of >>> the >>> >> real time routines is twice as long as it took on the RTOS. We are n= ot >>> >> making any calls to the Linux inside these real time routines. The >>> >> execution time of the routine is 500 microseconds in Xenomai thread. >>> But >>> >> on >>> >> an RTOS running this routine in an interrupt context takes only 250 >>> >> microseconds. What is the reason for this higher execution time? Is >>> the >>> >> xenomai thread getting preempted by some timer irq? Is there a way t= o >>> >> avoid >>> >> this preemption? >>> >> >>> >> Rajesh >>> > >>> > >>> > Did you run autotune binary and the latency tests? What were your >>> results? >>> > How long did you run the latency test for? Do you have any debug >>> features >>> > enabled? >>> > >>> > Thanks >>> > >>> > Greg >>> > >>> >> >>> >> >> >> >> Usually what I=E2=80=99ll do to get latency numbers is to run the latenc= y test >> while the system is loaded (simulate a busy system) and let it run for a >> long period of time. If you don=E2=80=99t see the latency that you see i= n your >> program (IMHO) you should look for any mode switches in your program. Bo= th >> ipipe and xenomai have debug options to help find latency. >> I=E2=80=99m not too familiar with the i.mx6 so I can=E2=80=99t say wea= ther the latency >> you are seeing could possibly be caused by hardware. >> >> Thanks >> >> -Greg >> >>> >>>