Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Alexander Herzog]

Hi Gilles,

I haven't replied to your email for a few months. I am sorry for that, we didn't have time to dig further into this problem. However, now we went back to the issue and installed Xenomai 2.6.3 with Linux kernel 3.8.13 . Now, if we do not run 'watch -n .1 cat /proc/xeno/stat', the latency test is running just fine without significant latencies. However, the moment we run the watch command in parallel, things break down and the latency goes up. Is this an issue that other people see as well and is there a fix for it? Thanks for your help.

best,
Alex 




> On 03/04/2014 08:55 PM, Alexander Herzog wrote:
> > Hi,
> > 
> > We have some real-time issues with our xenomai machine running Ubuntu
> > 12.04 with kernel version 3.5.7 patched with Xenomai 2.6.2.1 .
> 
> Hi,
> 
> do you get the same issues with the "latency" test and with Xenomai
> 2.6.3? On what hardware do you observe this?
> 
> Regards.
> 
> -- 
>                                                                 Gilles.
> 
>> Hi,
>> 
>> We have some real-time issues with our xenomai machine running Ubuntu 12.04 with kernel version 3.5.7 patched with Xenomai 2.6.2.1 . We run a simple program (see end of this email), where we shadow the main thread, then switch it into periodic mode and obtain the timestamp each time the process is released. One would expect that the time between two cycles should remain constant. This is roughly true, if we run the program. However, if we run the program and in parallel execute 'watch -n .1 cat /proc/xeno/stat' we see pretty high spikes. The same code runs on an older kernel+xenomai version (kernel 2.6.35.9 with xenomai 2.5.6 on Ubuntu 10.04) without spikes. I attached 3 plots. All of them show the duration between two consecutive cycles in blue. After the process is woken up it sleeps for a while and records the time it spent sleeping. This duration is plotted in green. You will also see spikes in sleep duration. The 3 plots are:
>> 
>> 2_5_with_watch.png shows the execution on an older xenomai system while we ran 'watch -n .1 cat /proc/xeno/stat' 
>> min cycle duration 989184.0 ns
>> max cycle duration 1010688.0 ns
>> 
>> 2_6_with_watch.png shows the execution on our xenomai system while we ran 'watch -n .1 cat /proc/xeno/stat' 
>> min cycle duration 400640.0 ns
>> max cycle duration 1911552.0 ns
>> 
>> 2_6_no_watch.png shows the execution on our xenomai without running the watch command in parallel. 
>> min cycle duration 989696.0 ns
>> max cycle duration 1010432.0 ns
>> 
>> We appreciate any hint on what might be the cause for this or how we could further diagnose the problem.
>> 
>> Thanks in advance,
>> Alex
>> 
>> PS: Here is the test program:
>> 
>> #include <native/task.h>
>> #include <native/timer.h>
>> #include <sys/mman.h>
>> #include <cstdio>
>> 
>> #define LOG_SIZE 100000
>> 
>> int main(int argc, char* argv[])
>> {
>>        long system_time[LOG_SIZE];
>>        long work_duration[LOG_SIZE];
>>        unsigned long overruns[LOG_SIZE];
>> 
>>        mlockall(MCL_CURRENT | MCL_FUTURE);
>> 
>>        rt_task_shadow(NULL, "periodic_thread", 50, 0);
>>        if(0 != rt_task_set_periodic(NULL, TM_NOW, 0.001 * 1e9))
>>        {
>>                printf ("Could not make task periodic\n");
>>            return -1;
>>        }
>>        rt_task_wait_period(NULL);
>> 
>>        for(int it=0; it<LOG_SIZE; ++it)
>>        {
>>          rt_task_wait_period(&(overruns[it]));
>>          system_time[it] = long(rt_timer_ticks2ns(rt_timer_read()));
>> 
>>          // do something
>>          long work_start = long(rt_timer_ticks2ns(rt_timer_read()));
>>          rt_task_sleep(400000);
>>          work_duration[it] = long(rt_timer_ticks2ns(rt_timer_read())) - work_start;
>>        }
>> 
>>        printf("writing log...\n");
>>        FILE *slog_file = fopen("periodic_task.log","w");
>>        for(int i=0; i<LOG_SIZE; ++i)
>>        {
>>          printf("writing log %d\n", i);
>>          fprintf(slog_file, "%ld ", system_time[i]);
>>          fprintf(slog_file, "%ld\n", work_duration[i]);
>>          fprintf(slog_file, "%lu\n", overruns[i]);
>>        }
>>        fclose(slog_file);
>> 
>>        return 0;
>> }
>> 
> 

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/07/2014 06:57 PM, Alexander Herzog wrote:
> Hi Gilles,
> 

Hi Alexander,

we do not use top-posting on xenomai mailing list.

> I haven't replied to your email for a few months. I am sorry for
> that, we didn't have time to dig further into this problem. However,
> now we went back to the issue and installed Xenomai 2.6.3 with Linux
> kernel 3.8.13 . Now, if we do not run 'watch -n .1 cat
> /proc/xeno/stat', the latency test is running just fine without

You mean /proc/xenomai/stat, right?

> significant latencies. However, the moment we run the watch command
> in parallel, things break down and the latency goes up. Is this an
> issue that other people see as well and is there a fix for it? Thanks
> for your help.

The problem is not watch, the problem is probably /proc/xenomai/stat,
which creates large latencies by holding the nucleus lock for too long.
The issue probably does not get the attention it deserves, because
/proc/xenomai/stat is something people usually use during debugging
phases, not really on a final system. And it also probably happens in
some conditions only (with a large number of Xenomai threads for
instance), because I never observed it on the systems where I run Xenomai.

Regards.

-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 07:22 PM, Gilles Chanteperdrix wrote:
> On 08/07/2014 06:57 PM, Alexander Herzog wrote:
>> Hi Gilles,
>>
> 
> Hi Alexander,
> 
> we do not use top-posting on xenomai mailing list.
> 
>> I haven't replied to your email for a few months. I am sorry for
>> that, we didn't have time to dig further into this problem. However,
>> now we went back to the issue and installed Xenomai 2.6.3 with Linux
>> kernel 3.8.13 . Now, if we do not run 'watch -n .1 cat
>> /proc/xeno/stat', the latency test is running just fine without
> 
> You mean /proc/xenomai/stat, right?
> 
>> significant latencies. However, the moment we run the watch command
>> in parallel, things break down and the latency goes up. Is this an
>> issue that other people see as well and is there a fix for it? Thanks
>> for your help.
> 
> The problem is not watch, the problem is probably /proc/xenomai/stat,
> which creates large latencies by holding the nucleus lock for too long.
> The issue probably does not get the attention it deserves, because
> /proc/xenomai/stat is something people usually use during debugging
> phases, not really on a final system. And it also probably happens in
> some conditions only (with a large number of Xenomai threads for
> instance), because I never observed it on the systems where I run Xenomai.
> 

That is unlikely, reading /proc/xenomai/stat is done through a snapshot
vfile, which has been introduced to fix that issue precisely.

-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/07/2014 08:25 PM, Philippe Gerum wrote:
> On 08/07/2014 07:22 PM, Gilles Chanteperdrix wrote:
>> On 08/07/2014 06:57 PM, Alexander Herzog wrote:
>>> Hi Gilles,
>>>
>>
>> Hi Alexander,
>>
>> we do not use top-posting on xenomai mailing list.
>>
>>> I haven't replied to your email for a few months. I am sorry for
>>> that, we didn't have time to dig further into this problem. However,
>>> now we went back to the issue and installed Xenomai 2.6.3 with Linux
>>> kernel 3.8.13 . Now, if we do not run 'watch -n .1 cat
>>> /proc/xeno/stat', the latency test is running just fine without
>>
>> You mean /proc/xenomai/stat, right?
>>
>>> significant latencies. However, the moment we run the watch command
>>> in parallel, things break down and the latency goes up. Is this an
>>> issue that other people see as well and is there a fix for it? Thanks
>>> for your help.
>>
>> The problem is not watch, the problem is probably /proc/xenomai/stat,
>> which creates large latencies by holding the nucleus lock for too long.
>> The issue probably does not get the attention it deserves, because
>> /proc/xenomai/stat is something people usually use during debugging
>> phases, not really on a final system. And it also probably happens in
>> some conditions only (with a large number of Xenomai threads for
>> instance), because I never observed it on the systems where I run Xenomai.
>>
> 
> That is unlikely, reading /proc/xenomai/stat is done through a snapshot
> vfile, which has been introduced to fix that issue precisely.
> 

Maybe I misunderstand the code completely, but it seems to me that
taking the snapshot is done irqs off, and is proportional to the number
of xenomai threads, so is bound to take a large time for a large number
of xenomai threads.

-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 08:28 PM, Gilles Chanteperdrix wrote:
> On 08/07/2014 08:25 PM, Philippe Gerum wrote:
>> On 08/07/2014 07:22 PM, Gilles Chanteperdrix wrote:
>>> On 08/07/2014 06:57 PM, Alexander Herzog wrote:
>>>> Hi Gilles,
>>>>
>>>
>>> Hi Alexander,
>>>
>>> we do not use top-posting on xenomai mailing list.
>>>
>>>> I haven't replied to your email for a few months. I am sorry for
>>>> that, we didn't have time to dig further into this problem. However,
>>>> now we went back to the issue and installed Xenomai 2.6.3 with Linux
>>>> kernel 3.8.13 . Now, if we do not run 'watch -n .1 cat
>>>> /proc/xeno/stat', the latency test is running just fine without
>>>
>>> You mean /proc/xenomai/stat, right?
>>>
>>>> significant latencies. However, the moment we run the watch command
>>>> in parallel, things break down and the latency goes up. Is this an
>>>> issue that other people see as well and is there a fix for it? Thanks
>>>> for your help.
>>>
>>> The problem is not watch, the problem is probably /proc/xenomai/stat,
>>> which creates large latencies by holding the nucleus lock for too long.
>>> The issue probably does not get the attention it deserves, because
>>> /proc/xenomai/stat is something people usually use during debugging
>>> phases, not really on a final system. And it also probably happens in
>>> some conditions only (with a large number of Xenomai threads for
>>> instance), because I never observed it on the systems where I run Xenomai.
>>>
>>
>> That is unlikely, reading /proc/xenomai/stat is done through a snapshot
>> vfile, which has been introduced to fix that issue precisely.
>>
> 
> Maybe I misunderstand the code completely, but it seems to me that
> taking the snapshot is done irqs off, and is proportional to the number
> of xenomai threads, so is bound to take a large time for a large number
> of xenomai threads.
> 

No, the lock is dropped between two consecutive calls to the ->next()
iterator on purpose, i.e. we don't mask for longer than what it takes to
pull the information for a single thread, regardless of how many threads
are present. The snapshot is taken again each time a change in the
thread list is detected, which might have happened while we did not hold
the nklock.

So it all depends on how much more latency is too much in the observed
case, but currently I'm seeing not more than 7 us on average, and 2 us
in the worst case, on a 52xx low end platform running a cat loop on
/proc/xenomai/stat.

-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Paul Janzen]

Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:

> And it also probably happens in some conditions only (with a large
> number of Xenomai threads for instance)

This is not quite correct. I experience large latencies (~1ms) during
"watch cat /proc/xenomai/stat", just running xeno-test (stat lists two
application tasks, two ROOTs and two IRQ-timers.)

x64, SMP, Linux 3.4.6, ipipe-core-3.4.6-x86-4.patch, xenomai 242a6e4. 

-- Paul

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 08:47 PM, Paul Janzen wrote:
> Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:
> 
>> And it also probably happens in some conditions only (with a large
>> number of Xenomai threads for instance)
> 
> This is not quite correct. I experience large latencies (~1ms) during
> "watch cat /proc/xenomai/stat", just running xeno-test (stat lists two
> application tasks, two ROOTs and two IRQ-timers.)
> 
> x64, SMP, Linux 3.4.6, ipipe-core-3.4.6-x86-4.patch, xenomai 242a6e4. 
> 

1 ms is definitely pathological. This cannot be related to
/proc/xenomai/stat or whatever vfile under /proc/xenomai, we would have
noticed.

This is more likely a I-pipe issue (3.4.6/x86 is outdated, although 1 ms
is really above usual issues), a kernel configuration issue (e.g.
CONFIG_CPU_FREQ, or other latency killer), or maybe a SMI problem. Or
maybe an issue induced by a graphic card driver if you happen to run
with a GUI.

-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Ludovic Righetti]

> This is more likely a I-pipe issue (3.4.6/x86 is outdated, although 1 ms
> is really above usual issues), a kernel configuration issue (e.g.
> CONFIG_CPU_FREQ, or other latency killer), or maybe a SMI problem. Or
> maybe an issue induced by a graphic card driver if you happen to run
> with a GUI.
>
we have the same issue (same machine Alexander described - xeno 2.6.3 /
kernel 3.8.13 ipipe patch from the xenomai tar)
below the xeno latency output when I run with a watch -n .1 cat
/proc/xenomai/stat and no X-windows server. I do not have the problem
without the watch command and with running a x-window (ubuntu 12.04
desktop) although I get latency spikes when opening open gl windows
(which I know is normal).

CONFIG_CPU_FREQ, CPU_IDLE, ACPI_PROCESSOR, INPUT_PCSPKR are disabled in
my kernel config. Not sure if there could be other latency killers I
should disable.

RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat
best|--lat worst
RTD|     -2.413|     -0.799|    141.488|       1|     0|     -2.413|   
141.488
RTD|     -2.423|     -0.494|    477.758|      15|     0|     -2.423|   
477.758
RTD|     -2.440|     -0.564|    286.563|      23|     0|     -2.440|   
477.758
RTD|     -2.389|     -0.858|    118.116|      24|     0|     -2.440|   
477.758
RTD|     -2.376|     -0.980|     71.960|      24|     0|     -2.440|   
477.758
RTD|     -2.375|     -0.671|    100.248|      24|     0|     -2.440|   
477.758
RTD|     -2.382|     -0.872|    184.203|      26|     0|     -2.440|   
477.758
RTD|     -2.383|     -0.739|    260.341|      33|     0|     -2.440|   
477.758
RTD|     -2.380|     -0.760|    711.203|      41|     0|     -2.440|   
711.203
RTD|     -2.314|     -0.658|   1664.493|      63|     0|     -2.440|  
1664.493
RTD|     -2.413|     -0.838|    134.240|      65|     0|     -2.440|  
1664.493
RTD|     -2.435|     -0.661|    381.385|      68|     0|     -2.440|  
1664.493
RTD|     -2.317|     -0.872|     93.973|      68|     0|     -2.440|  
1664.493
RTD|     -2.316|     -0.568|   2756.048|     100|     0|     -2.440|  
2756.048
RTD|     -2.387|     -0.870|    117.891|     102|     0|     -2.440|  
2756.048
RTD|     -2.319|     -0.950|     66.645|     102|     0|     -2.440|  
2756.048
RTD|     -2.384|     -0.864|     86.956|     102|     0|     -2.440|  
2756.048
RTD|     -2.385|     -0.878|     73.840|     102|     0|     -2.440|  
2756.048
RTD|     -2.380|     -1.000|     42.325|     102|     0|     -2.440|  
2756.048

best wishes
ludovic

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/07/2014 08:47 PM, Paul Janzen wrote:
> Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:
> 
>> And it also probably happens in some conditions only (with a large
>> number of Xenomai threads for instance)
> 
> This is not quite correct. I experience large latencies (~1ms) during
> "watch cat /proc/xenomai/stat", just running xeno-test (stat lists two
> application tasks, two ROOTs and two IRQ-timers.)

This does not disprove the fact that it probably happens in some
conditions only. As I said, I never saw it on the systems where I run
xenomai.

-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 09:16 PM, Ludovic Righetti wrote:
> 
>> This is more likely a I-pipe issue (3.4.6/x86 is outdated, although 1 ms
>> is really above usual issues), a kernel configuration issue (e.g.
>> CONFIG_CPU_FREQ, or other latency killer), or maybe a SMI problem. Or
>> maybe an issue induced by a graphic card driver if you happen to run
>> with a GUI.
>>
> we have the same issue (same machine Alexander described - xeno 2.6.3 /
> kernel 3.8.13 ipipe patch from the xenomai tar)
> below the xeno latency output when I run with a watch -n .1 cat
> /proc/xenomai/stat and no X-windows server. I do not have the problem
> without the watch command and with running a x-window (ubuntu 12.04
> desktop) although I get latency spikes when opening open gl windows
> (which I know is normal).

I suspect you could run any loop, like cat /proc/interrupts, and see the
same issue. Are you running with a frame buffer in the no-x mode?

> 
> CONFIG_CPU_FREQ, CPU_IDLE, ACPI_PROCESSOR, INPUT_PCSPKR are disabled in
> my kernel config. Not sure if there could be other latency killers I
> should disable.
> 
> RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat
> best|--lat worst
> RTD|     -2.413|     -0.799|    141.488|       1|     0|     -2.413|   
> 141.488
> RTD|     -2.423|     -0.494|    477.758|      15|     0|     -2.423|   
> 477.758
> RTD|     -2.440|     -0.564|    286.563|      23|     0|     -2.440|   
> 477.758
> RTD|     -2.389|     -0.858|    118.116|      24|     0|     -2.440|   
> 477.758
> RTD|     -2.376|     -0.980|     71.960|      24|     0|     -2.440|   
> 477.758
> RTD|     -2.375|     -0.671|    100.248|      24|     0|     -2.440|   
> 477.758
> RTD|     -2.382|     -0.872|    184.203|      26|     0|     -2.440|   
> 477.758
> RTD|     -2.383|     -0.739|    260.341|      33|     0|     -2.440|   
> 477.758
> RTD|     -2.380|     -0.760|    711.203|      41|     0|     -2.440|   
> 711.203
> RTD|     -2.314|     -0.658|   1664.493|      63|     0|     -2.440|  
> 1664.493
> RTD|     -2.413|     -0.838|    134.240|      65|     0|     -2.440|  
> 1664.493
> RTD|     -2.435|     -0.661|    381.385|      68|     0|     -2.440|  
> 1664.493
> RTD|     -2.317|     -0.872|     93.973|      68|     0|     -2.440|  
> 1664.493
> RTD|     -2.316|     -0.568|   2756.048|     100|     0|     -2.440|  
> 2756.048
> RTD|     -2.387|     -0.870|    117.891|     102|     0|     -2.440|  
> 2756.048
> RTD|     -2.319|     -0.950|     66.645|     102|     0|     -2.440|  
> 2756.048
> RTD|     -2.384|     -0.864|     86.956|     102|     0|     -2.440|  
> 2756.048
> RTD|     -2.385|     -0.878|     73.840|     102|     0|     -2.440|  
> 2756.048
> RTD|     -2.380|     -1.000|     42.325|     102|     0|     -2.440|  
> 2756.048
> 
> best wishes
> ludovic


-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Ludovic Righetti]

> I suspect you could run any loop, like cat /proc/interrupts, and see the
> same issue. Are you running with a frame buffer in the no-x mode?
>
that's what I thought too, but /proc/interrupts or /proc/xenomai/sched
(or others) do not seem to create any issue (below the output for
interrupts, watching other /proc/ files give similar results).

Let me check about the fb.

ludovic



RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat
best|--lat worst
RTD|     -2.322|     -1.053|      7.677|       0|     0|    
-2.322|      7.677
RTD|     -2.321|     -1.062|      8.224|       0|     0|    
-2.322|      8.224
RTD|     -2.322|     -1.058|      7.195|       0|     0|    
-2.322|      8.224
RTD|     -2.320|     -1.050|      7.070|       0|     0|    
-2.322|      8.224
RTD|     -2.321|     -1.056|      7.389|       0|     0|    
-2.322|      8.224
RTD|     -2.323|     -1.060|      6.365|       0|     0|    
-2.323|      8.224
RTD|     -2.320|     -1.050|      8.547|       0|     0|    
-2.323|      8.547
RTD|     -2.320|     -1.051|      8.097|       0|     0|    
-2.323|      8.547
RTD|     -2.320|     -1.062|      7.406|       0|     0|    
-2.323|      8.547
RTD|     -2.321|     -1.054|      9.558|       0|     0|    
-2.323|      9.558
RTD|     -2.321|     -1.061|      6.994|       0|     0|    
-2.323|      9.558
RTD|     -2.321|     -1.064|      5.545|       0|     0|    
-2.323|      9.558

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 09:35 PM, Ludovic Righetti wrote:
> 
>> I suspect you could run any loop, like cat /proc/interrupts, and see the
>> same issue. Are you running with a frame buffer in the no-x mode?
>>
> that's what I thought too, but /proc/interrupts or /proc/xenomai/sched
> (or others) do not seem to create any issue (below the output for
> interrupts, watching other /proc/ files give similar results).
> 
> Let me check about the fb.
> 

Just for kicks, could you try this patch ? it does NOT fix anything,
only maybe papering over an issue we don't know about yet:

diff --git a/ksrc/nucleus/sched.c b/ksrc/nucleus/sched.c
index 3391f4a..16d96d3 100644
--- a/ksrc/nucleus/sched.c
+++ b/ksrc/nucleus/sched.c
@@ -877,7 +877,7 @@ static int vfile_stat_next(struct
xnvfile_snapshot_iterator *it, void *data)
 		 * We are done with actual threads, scan interrupt
 		 * descriptors.
 		 */
-		goto scan_irqs;
+		return 0;

 	thread = link2thread(priv->curr, glink);
 	priv->curr = nextq(&nkpod->threadq, priv->curr);

> ludovic
> 
> 
> 
> 
> RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat
> best|--lat worst
> RTD|     -2.322|     -1.053|      7.677|       0|     0|    
> -2.322|      7.677
> RTD|     -2.321|     -1.062|      8.224|       0|     0|    
> -2.322|      8.224
> RTD|     -2.322|     -1.058|      7.195|       0|     0|    
> -2.322|      8.224
> RTD|     -2.320|     -1.050|      7.070|       0|     0|    
> -2.322|      8.224
> RTD|     -2.321|     -1.056|      7.389|       0|     0|    
> -2.322|      8.224
> RTD|     -2.323|     -1.060|      6.365|       0|     0|    
> -2.323|      8.224
> RTD|     -2.320|     -1.050|      8.547|       0|     0|    
> -2.323|      8.547
> RTD|     -2.320|     -1.051|      8.097|       0|     0|    
> -2.323|      8.547
> RTD|     -2.320|     -1.062|      7.406|       0|     0|    
> -2.323|      8.547
> RTD|     -2.321|     -1.054|      9.558|       0|     0|    
> -2.323|      9.558
> RTD|     -2.321|     -1.061|      6.994|       0|     0|    
> -2.323|      9.558
> RTD|     -2.321|     -1.064|      5.545|       0|     0|    
> -2.323|      9.558
> 


-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/07/2014 09:44 PM, Philippe Gerum wrote:
> On 08/07/2014 09:35 PM, Ludovic Righetti wrote:
>>
>>> I suspect you could run any loop, like cat /proc/interrupts, and see the
>>> same issue. Are you running with a frame buffer in the no-x mode?
>>>
>> that's what I thought too, but /proc/interrupts or /proc/xenomai/sched
>> (or others) do not seem to create any issue (below the output for
>> interrupts, watching other /proc/ files give similar results).
>>
>> Let me check about the fb.
>>
> 
> Just for kicks, could you try this patch ? it does NOT fix anything,
> only maybe papering over an issue we don't know about yet:

Note that there has already been a thread about this issue in april.

-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Ludovic Righetti]

 
> Just for kicks, could you try this patch ? it does NOT fix anything,
> only maybe papering over an issue we don't know about yet:
> 

I just tried it. the issue is not visible anymore.

ludovic

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 09:56 PM, Gilles Chanteperdrix wrote:
> On 08/07/2014 09:44 PM, Philippe Gerum wrote:
>> On 08/07/2014 09:35 PM, Ludovic Righetti wrote:
>>>
>>>> I suspect you could run any loop, like cat /proc/interrupts, and see the
>>>> same issue. Are you running with a frame buffer in the no-x mode?
>>>>
>>> that's what I thought too, but /proc/interrupts or /proc/xenomai/sched
>>> (or others) do not seem to create any issue (below the output for
>>> interrupts, watching other /proc/ files give similar results).
>>>
>>> Let me check about the fb.
>>>
>>
>> Just for kicks, could you try this patch ? it does NOT fix anything,
>> only maybe papering over an issue we don't know about yet:
> 
> Note that there has already been a thread about this issue in april.
> 

So it looks like nobody cared.

-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/07/2014 10:47 PM, Ludovic Righetti wrote:
>  
>> Just for kicks, could you try this patch ? it does NOT fix anything,
>> only maybe papering over an issue we don't know about yet:
>>
> 
> I just tried it. the issue is not visible anymore.
> 

Ok, instead of this patch, please disable CONFIG_CONTEXT_TRACKING_FORCE
from your Kconfig, the issue should go away. Since 3.14 we switch this
option off automatically, as it is incompatible with interrupt
pipelining in many cases, and solely useful for debugging a very
specific portion of the kernel itself.

-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/08/2014 08:59 AM, Philippe Gerum wrote:
> On 08/07/2014 09:56 PM, Gilles Chanteperdrix wrote:
>> On 08/07/2014 09:44 PM, Philippe Gerum wrote:
>>> On 08/07/2014 09:35 PM, Ludovic Righetti wrote:
>>>>
>>>>> I suspect you could run any loop, like cat /proc/interrupts, and see the
>>>>> same issue. Are you running with a frame buffer in the no-x mode?
>>>>>
>>>> that's what I thought too, but /proc/interrupts or /proc/xenomai/sched
>>>> (or others) do not seem to create any issue (below the output for
>>>> interrupts, watching other /proc/ files give similar results).
>>>>
>>>> Let me check about the fb.
>>>>
>>>
>>> Just for kicks, could you try this patch ? it does NOT fix anything,
>>> only maybe papering over an issue we don't know about yet:
>>
>> Note that there has already been a thread about this issue in april.
>>
> 
> So it looks like nobody cared.
> 
I tried and help Jeroen, but since I could not reproduce the issue,
could not investigate it much further.

-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Paul Janzen]

Philippe Gerum <rpm@xenomai.org> writes:

> Ok, instead of this patch, please disable CONFIG_CONTEXT_TRACKING_FORCE
> from your Kconfig, the issue should go away. Since 3.14 we switch this
> option off automatically, as it is incompatible with interrupt
> pipelining in many cases, and solely useful for debugging a very
> specific portion of the kernel itself.

This option does not exist in 3.4.x, where I see the problem.

-- Paul

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Philippe Gerum]

On 08/08/2014 07:21 PM, Paul Janzen wrote:
> Philippe Gerum <rpm@xenomai.org> writes:
> 
>> Ok, instead of this patch, please disable CONFIG_CONTEXT_TRACKING_FORCE
>> from your Kconfig, the issue should go away. Since 3.14 we switch this
>> option off automatically, as it is incompatible with interrupt
>> pipelining in many cases, and solely useful for debugging a very
>> specific portion of the kernel itself.
> 
> This option does not exist in 3.4.x, where I see the problem.
> 

This option is for 3.8 which Ludovic runs. Do you still see the issue
with the one-liner patch I sent lately?

-- 
Philippe.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Paul Janzen]

Philippe Gerum <rpm@xenomai.org> writes:

> This option is for 3.8 which Ludovic runs. Do you still see the issue
> with the one-liner patch I sent lately?

No, the one-liner successfully suppresses the problem on 3.4.

-- Paul

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/08/2014 08:27 PM, Paul Janzen wrote:
> Philippe Gerum <rpm@xenomai.org> writes:
> 
>> This option is for 3.8 which Ludovic runs. Do you still see the issue
>> with the one-liner patch I sent lately?
> 
> No, the one-liner successfully suppresses the problem on 3.4.

Without this one-liner, does one of the following patches help?

diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
index c8e0363..ff99536 100644
--- a/ksrc/nucleus/vfile.c
+++ b/ksrc/nucleus/vfile.c
@@ -278,7 +278,8 @@ redo:
 		if (ret != VFILE_SEQ_SKIP) {
 			data += vfile->datasz;
 			it->nrdata++;
-		}
+		} else
+			cpu_relax();
 	}

 	if (ret < 0) {


diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
index c8e0363..1702f08 100644
--- a/ksrc/nucleus/vfile.c
+++ b/ksrc/nucleus/vfile.c
@@ -278,7 +278,8 @@ redo:
 		if (ret != VFILE_SEQ_SKIP) {
 			data += vfile->datasz;
 			it->nrdata++;
-		}
+		} else
+			xnarch_memory_barrier();
 	}

 	if (ret < 0) {


-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Paul Janzen]

Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:

> Without this one-liner, does one of the following patches help?
>
> diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
> index c8e0363..ff99536 100644
> --- a/ksrc/nucleus/vfile.c
> +++ b/ksrc/nucleus/vfile.c
> @@ -278,7 +278,8 @@ redo:
>  		if (ret != VFILE_SEQ_SKIP) {
>  			data += vfile->datasz;
>  			it->nrdata++;
> -		}
> +		} else
> +			cpu_relax();
>  	}
>
>  	if (ret < 0) {
>
>
> diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
> index c8e0363..1702f08 100644
> --- a/ksrc/nucleus/vfile.c
> +++ b/ksrc/nucleus/vfile.c
> @@ -278,7 +278,8 @@ redo:
>  		if (ret != VFILE_SEQ_SKIP) {
>  			data += vfile->datasz;
>  			it->nrdata++;
> -		}
> +		} else
> +			xnarch_memory_barrier();
>  	}
>
>  	if (ret < 0) {


No.  Neither one of these two patches helps.

-- Paul

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/11/2014 06:54 PM, Paul Janzen wrote:
> Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:
> 
>> Without this one-liner, does one of the following patches help?
>>
>> diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
>> index c8e0363..ff99536 100644
>> --- a/ksrc/nucleus/vfile.c
>> +++ b/ksrc/nucleus/vfile.c
>> @@ -278,7 +278,8 @@ redo:
>>  		if (ret != VFILE_SEQ_SKIP) {
>>  			data += vfile->datasz;
>>  			it->nrdata++;
>> -		}
>> +		} else
>> +			cpu_relax();
>>  	}
>>
>>  	if (ret < 0) {
>>
>>
>> diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
>> index c8e0363..1702f08 100644
>> --- a/ksrc/nucleus/vfile.c
>> +++ b/ksrc/nucleus/vfile.c
>> @@ -278,7 +278,8 @@ redo:
>>  		if (ret != VFILE_SEQ_SKIP) {
>>  			data += vfile->datasz;
>>  			it->nrdata++;
>> -		}
>> +		} else
>> +			xnarch_memory_barrier();
>>  	}
>>
>>  	if (ret < 0) {
> 
> 
> No.  Neither one of these two patches helps.

What about combining the 2, like:

	} else {
		xnarch_memory_barrier();
		cpu_relax();
	}


-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Paul Janzen]

Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:

> What about combining the 2, like:
>
> 	} else {
> 		xnarch_memory_barrier();
> 		cpu_relax();
> 	}

No, this does not help either.

-- Paul

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Ludovic Righetti]

> Ok, instead of this patch, please disable CONFIG_CONTEXT_TRACKING_FORCE
> from your Kconfig, the issue should go away. Since 3.14 we switch this
> option off automatically, as it is incompatible with interrupt
> pipelining in many cases, and solely useful for debugging a very
> specific portion of the kernel itself.
>
this option was already disabled in my kernel config. So it does not fix
the issue.

best wishes,
ludovic

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 08/11/2014 07:43 PM, Paul Janzen wrote:
> Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:
> 
>> What about combining the 2, like:
>>
>> 	} else {
>> 		xnarch_memory_barrier();
>> 		cpu_relax();
>> 	}
> 
> No, this does not help either.


Could you try the following patch?

diff --git a/include/asm-generic/bits/pod.h b/include/asm-generic/bits/pod.h
index a6be0dc..cfb0c71 100644
--- a/include/asm-generic/bits/pod.h
+++ b/include/asm-generic/bits/pod.h
@@ -248,6 +248,7 @@ void __xnlock_spin(xnlock_t *lock /*, */ XNLOCK_DBG_CONTEXT_ARGS)
 			cpu_relax();
 			xnlock_dbg_spinning(lock, cpu, &spin_limit /*, */
 					    XNLOCK_DBG_PASS_CONTEXT);
+			xnarch_memory_barrier();
 		} while(atomic_read(&lock->owner) != ~0);
 }
 EXPORT_SYMBOL_GPL(__xnlock_spin);
diff --git a/include/asm-generic/system.h b/include/asm-generic/system.h
index 25bd83f..7a8c4d0 100644
--- a/include/asm-generic/system.h
+++ b/include/asm-generic/system.h
@@ -378,6 +378,8 @@ static inline void xnlock_put(xnlock_t *lock)
 	xnarch_memory_barrier();
 
 	atomic_set(&lock->owner, ~0);
+
+	xnarch_memory_barrier();
 }
 
 static inline spl_t
diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
index c8e0363..066c12f 100644
--- a/ksrc/nucleus/vfile.c
+++ b/ksrc/nucleus/vfile.c
@@ -279,6 +279,15 @@ redo:
 			data += vfile->datasz;
 			it->nrdata++;
 		}
+#ifdef CONFIG_SMP
+		{
+			/* Leave some time for other cpus to get the lock */
+			xnticks_t wakeup = xnarch_get_cpu_tsc();
+			wakeup += xnarch_ns_to_tsc(1000);
+			while ((xnsticks_t)(xnarch_get_cpu_tsc() - wakeup) < 0)
+				cpu_relax();
+		}
+#endif
 	}
 
 	if (ret < 0) {


-- 
                                                                Gilles.

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Nicholas Rotella]

Hi Gilles,

I work with Alexander Herzog (who started this thread originally) and
Ludovic Righetti.  I just tested this patch on our Xenomai system
(Ubuntu 12.04, linux kernel 3.8.13, Xenomai 2.6.3) and it fixes all of
our problems.  We can now watch in parallel to running the xeno
latency test without observing high latencies.

Thanks!

- Nick

On Tue, Sep 9, 2014 at 2:05 PM, Gilles Chanteperdrix
<gilles.chanteperdrix@xenomai.org> wrote:
> On 08/11/2014 07:43 PM, Paul Janzen wrote:
>> Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> writes:
>>
>>> What about combining the 2, like:
>>>
>>>      } else {
>>>              xnarch_memory_barrier();
>>>              cpu_relax();
>>>      }
>>
>> No, this does not help either.
>
>
> Could you try the following patch?
>
> diff --git a/include/asm-generic/bits/pod.h b/include/asm-generic/bits/pod.h
> index a6be0dc..cfb0c71 100644
> --- a/include/asm-generic/bits/pod.h
> +++ b/include/asm-generic/bits/pod.h
> @@ -248,6 +248,7 @@ void __xnlock_spin(xnlock_t *lock /*, */ XNLOCK_DBG_CONTEXT_ARGS)
>                         cpu_relax();
>                         xnlock_dbg_spinning(lock, cpu, &spin_limit /*, */
>                                             XNLOCK_DBG_PASS_CONTEXT);
> +                       xnarch_memory_barrier();
>                 } while(atomic_read(&lock->owner) != ~0);
>  }
>  EXPORT_SYMBOL_GPL(__xnlock_spin);
> diff --git a/include/asm-generic/system.h b/include/asm-generic/system.h
> index 25bd83f..7a8c4d0 100644
> --- a/include/asm-generic/system.h
> +++ b/include/asm-generic/system.h
> @@ -378,6 +378,8 @@ static inline void xnlock_put(xnlock_t *lock)
>         xnarch_memory_barrier();
>
>         atomic_set(&lock->owner, ~0);
> +
> +       xnarch_memory_barrier();
>  }
>
>  static inline spl_t
> diff --git a/ksrc/nucleus/vfile.c b/ksrc/nucleus/vfile.c
> index c8e0363..066c12f 100644
> --- a/ksrc/nucleus/vfile.c
> +++ b/ksrc/nucleus/vfile.c
> @@ -279,6 +279,15 @@ redo:
>                         data += vfile->datasz;
>                         it->nrdata++;
>                 }
> +#ifdef CONFIG_SMP
> +               {
> +                       /* Leave some time for other cpus to get the lock */
> +                       xnticks_t wakeup = xnarch_get_cpu_tsc();
> +                       wakeup += xnarch_ns_to_tsc(1000);
> +                       while ((xnsticks_t)(xnarch_get_cpu_tsc() - wakeup) < 0)
> +                               cpu_relax();
> +               }
> +#endif
>         }
>
>         if (ret < 0) {
>
>
> --
>                                                                 Gilles.
>
> _______________________________________________
> Xenomai mailing list
> Xenomai@xenomai.org
> http://www.xenomai.org/mailman/listinfo/xenomai

Re: [Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Gilles Chanteperdrix]

On 03/04/2014 08:55 PM, Alexander Herzog wrote:
> Hi,
> 
> We have some real-time issues with our xenomai machine running Ubuntu
> 12.04 with kernel version 3.5.7 patched with Xenomai 2.6.2.1 .

Hi,

do you get the same issues with the "latency" test and with Xenomai
2.6.3? On what hardware do you observe this?

Regards.

-- 
                                                                Gilles.

[Xenomai] real-time guarantee issues on xenomai 2.6.2.1

[Alexander Herzog]

Hi,

We have some real-time issues with our xenomai machine running Ubuntu 12.04 with kernel version 3.5.7 patched with Xenomai 2.6.2.1 . We run a simple program (see end of this email), where we shadow the main thread, then switch it into periodic mode and obtain the timestamp each time the process is released. One would expect that the time between two cycles should remain constant. This is roughly true, if we run the program. However, if we run the program and in parallel execute 'watch -n .1 cat /proc/xeno/stat' we see pretty high spikes. The same code runs on an older kernel+xenomai version (kernel 2.6.35.9 with xenomai 2.5.6 on Ubuntu 10.04) without spikes. I attached 3 plots. All of them show the duration between two consecutive cycles in blue. After the process is woken up it sleeps for a while and records the time it spent sleeping. This duration is plotted in green. You will also see spikes in sleep duration. The 3 plots are:

2_5_with_watch.png shows the execution on an older xenomai system while we ran 'watch -n .1 cat /proc/xeno/stat' 
min cycle duration 989184.0 ns
max cycle duration 1010688.0 ns

2_6_with_watch.png shows the execution on our xenomai system while we ran 'watch -n .1 cat /proc/xeno/stat' 
min cycle duration 400640.0 ns
max cycle duration 1911552.0 ns

2_6_no_watch.png shows the execution on our xenomai without running the watch command in parallel. 
min cycle duration 989696.0 ns
max cycle duration 1010432.0 ns

We appreciate any hint on what might be the cause for this or how we could further diagnose the problem.

Thanks in advance,
Alex

PS: Here is the test program:

#include <native/task.h>
#include <native/timer.h>
#include <sys/mman.h>
#include <cstdio>

#define LOG_SIZE 100000

int main(int argc, char* argv[])
{
        long system_time[LOG_SIZE];
        long work_duration[LOG_SIZE];
        unsigned long overruns[LOG_SIZE];

        mlockall(MCL_CURRENT | MCL_FUTURE);

        rt_task_shadow(NULL, "periodic_thread", 50, 0);
        if(0 != rt_task_set_periodic(NULL, TM_NOW, 0.001 * 1e9))
        {
                printf ("Could not make task periodic\n");
            return -1;
        }
        rt_task_wait_period(NULL);

        for(int it=0; it<LOG_SIZE; ++it)
        {
          rt_task_wait_period(&(overruns[it]));
          system_time[it] = long(rt_timer_ticks2ns(rt_timer_read()));

          // do something
          long work_start = long(rt_timer_ticks2ns(rt_timer_read()));
          rt_task_sleep(400000);
          work_duration[it] = long(rt_timer_ticks2ns(rt_timer_read())) - work_start;
        }

        printf("writing log...\n");
        FILE *slog_file = fopen("periodic_task.log","w");
        for(int i=0; i<LOG_SIZE; ++i)
        {
          printf("writing log %d\n", i);
          fprintf(slog_file, "%ld ", system_time[i]);
          fprintf(slog_file, "%ld\n", work_duration[i]);
          fprintf(slog_file, "%lu\n", overruns[i]);
        }
        fclose(slog_file);

        return 0;
}