[Xenomai-help] starnge latencies with native

[Xenomai-help] starnge latencies with native

[Daniel Simon]

[-- Attachment #1: Type: text/plain, Size: 1571 bytes --]

Hi all,

I'm doing some tests with the native skins. The attached program uses
an alarm to trigger a periodic task and measures the sampling latency. 

Initial latencies are in the range of tens of millisecs. and then
decrease slowly to the range of microsecs:

rt_timer_set_mode(TM_ONESHOT) started 
alarm started with period 1000000000 ns 
increment 1124642266 absjitter 124642266  
increment 937743828 absjitter 62256172  
increment 1031095424 absjitter 31095424  
increment 984466651 absjitter 15533349  
increment 1007758686 absjitter 7758686  
increment 996126407 absjitter 3873593  
increment 1001934707 absjitter 1934707  
increment 999039749 absjitter 960251  
increment 1000477139 absjitter 477139  
increment 999759707 absjitter 240293  
increment 1000119631 absjitter 119631  
increment 999938964 absjitter 61036  
increment 1000029816 absjitter 29816  
increment 999985508 absjitter 14492  
increment 1000004750 absjitter 4750  
increment 999998882 absjitter 1118  
increment 1000000946 absjitter 946  
increment 999998780 absjitter 1220  
increment 1000001951 absjitter 1951  
increment 999999514 absjitter 486  
increment 999998746 absjitter 1254  
[...]

 What may be wrong? 

I observe the same behaviour if the periodic sampling is given by a
rt_periodic task or by a rt_sleep_until in the clock loop...

	Daniel

-- 
      Daniel SIMON    Projet POP ART  INRIA Rhone-Alpes
ZIRST, 655 avenue de l'Europe, 38330 MONTBONNOT SAINT MARTIN, FRANCE 
 Daniel.Simon@domain.hid Phone:(33)476615328 Fax:(33)476615252
	 http://pop-art.inrialpes.fr/people/simon/



[-- Attachment #2: orcalarm.c --]
[-- Type: text/x-csrc, Size: 4787 bytes --]

//#include "orcnative.h"
#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#include <string.h>
#include <signal.h>
#include <sys/time.h>
#include <sys/io.h>
#include <sys/mman.h>
#include <native/types.h>
#include <native/task.h>
#include <native/queue.h>
#include <native/intr.h>
#include <native/timer.h>
#include <native/sem.h>
#include <native/alarm.h>
#include <native/heap.h>
#include <native/queue.h>
#include <native/syscall.h>
#define STACK_SIZE 8192
#define MIN_PRIO 1
#define MAX_PRIO 99

typedef void * (*FUNCPTR) (void *);
typedef void * (*SOSO) (void *); /**< Special type to be used for casting in pthread_create() */
//                     --s-ms-us-ns
RTIME task_period_ns = 1000000000llu;
#define NSEC_PER_SEC 1000000000
#define NBCLKS 3
#define BASECLK 0.001 //seconds !!!

#define OK 0
#define ERROR -1
#define STATUS int

#define FALSE 0
#define TRUE 1
#define POLICY 1

static int ji = 0;
//static int togparport = 0;
static RTIME startime, now, inittime, nexttime;
static long long hjitter, jinc, max, moy, drift, jitter;
struct timespec clock_resolution;

RT_SEM mainSem;
RT_SEM handSem;
RT_ALARM BaseClk;
int status, err, end = 0;
//pthread_t * tid;
char *dummy;
RT_TASK thr_clockit;


///Function that returns the cpu time in nanoseconds
inline long long GetCpuTime(void)
{
    return (long long)rt_timer_read();
}

// Trap Ctrl C Interruption
void clean_exit(int dummy)
{
    printf("Ctrl C Interrupt\n");
/*     printf("rt_sem_v(mainSem); \n"); */
/*     rt_sem_v(&mainSem); */
    end = 1;
    err = rt_task_join(&thr_clockit);
    if (err != 0)printf("rt_task_join() error %d \n", err);

    printf("deleting rt devices \n");
    rt_alarm_delete(&BaseClk);
    rt_task_delete(&thr_clockit);
    //rt_sem_delete(&mainSem);
    return ;
}

int orcTimerSigMask(void)
{
    sigset_t set;
    sigfillset(&set);
    if ((err = pthread_sigmask(SIG_BLOCK, &set, NULL)) != OK)
    {
        printf("pthread_sigmask Failed %d \n", err);
        return ERROR;
    }
    sigemptyset(&set);
    sigaddset(&set, SIGINT);
    sigaddset(&set, SIGTERM);
    if ((err = pthread_sigmask(SIG_UNBLOCK, &set, NULL)) != OK)
    {
        printf("pthread_sigmask Failed %d \n", err);
        return ERROR;
    }

    return OK;
}

void setTimer(void)
{
    /***starting timer ***/
    err = rt_timer_set_mode(TM_ONESHOT);
    if (err != 0)perror("rt_timer_set_mode()");
    else printf("rt_timer_set_mode(TM_ONESHOT) started \n");
    err = rt_alarm_create(&BaseClk, "BaseClock");
    if (err != 0)printf("rt_alarm_create() error %d \n", err);
    err = rt_alarm_start(&BaseClk,
                         task_period_ns,
                         task_period_ns);
    if (err != 0)printf("rt_alarm_start() error %d \n", err);

    else printf("alarm started with period %llu ns \n", task_period_ns);
    return ;

}

void clock_it(void *cookie)
{
  int ret;
    while (!end)
    {
        ret = rt_task_set_mode(0, T_PRIMARY, NULL);
        if (ret)
        {
            printf("error while rt_task_set_mode, code %d\n", ret);
            return ;
        }
/* #ifdef DEBUG */
/*         printf("before alarm_wait \n"); */
/* #endif */
        err = rt_alarm_wait(&BaseClk);
        now = GetCpuTime();
/* #ifdef DEBUG */
/*         printf("clock_it loop\n"); */
/* #endif */
        if (ji == 0)
        {
            max = moy = drift = 0;
            startime = now;
            ji++;
        }
        else if (ji == 1)
        {
            ji++;startime = now;
        }
        else
        {
            jinc = (long long)(now - startime);
            jitter = (jinc - (long long)task_period_ns );
            drift += jitter;
            hjitter = abs(jitter);
            moy += hjitter;
            ji++;
            if (hjitter > max) max = hjitter;
#ifdef DEBUG
            printf("increment %ld absjitter %ld  \n", (long)jinc, (long) hjitter);
#endif
            startime = now;
        }
    }
    printf ("jittermoy = %ld, jittermax = %ld \n", (long)moy / ji, (long)max);
    return ;
}

int main(void)
{

    orcTimerSigMask();

    mlockall(MCL_CURRENT | MCL_FUTURE);

    signal(SIGTERM, clean_exit);
    signal(SIGINT, clean_exit);

    setTimer();

    err = rt_task_spawn(&thr_clockit,
                        "MyAlarmServer",
                        0,
                        MAX_PRIO,
                        T_FPU|T_JOINABLE,
                        &clock_it,
                        NULL);

    if (err != 0) printf("rt_task_spawn error %d \n", err);

/*     err = rt_sem_create(&mainSem, "MainSem", 0, S_FIFO); */
/*     if (err != 0) printf("rt_sem_create error %d \n", err); */

/*     err = rt_sem_p(&mainSem, TM_INFINITE); */
/*     if (err != 0) printf("rt_sem_p error %d \n", err); */


    pause();
    fflush(NULL);

    return 0;
}

Re: [Xenomai-help] starnge latencies with native

[Philippe Gerum]

Daniel Simon wrote:
> Hi all,
> 
> I'm doing some tests with the native skins. The attached program uses
> an alarm to trigger a periodic task and measures the sampling latency. 
> 
> Initial latencies are in the range of tens of millisecs. and then
> decrease slowly to the range of microsecs:
> 
> rt_timer_set_mode(TM_ONESHOT) started 
> alarm started with period 1000000000 ns 
> increment 1124642266 absjitter 124642266  
> increment 937743828 absjitter 62256172  
> increment 1031095424 absjitter 31095424  
> increment 984466651 absjitter 15533349  
> increment 1007758686 absjitter 7758686  
> increment 996126407 absjitter 3873593  
> increment 1001934707 absjitter 1934707  
> increment 999039749 absjitter 960251  
> increment 1000477139 absjitter 477139  
> increment 999759707 absjitter 240293  
> increment 1000119631 absjitter 119631  
> increment 999938964 absjitter 61036  
> increment 1000029816 absjitter 29816  
> increment 999985508 absjitter 14492  
> increment 1000004750 absjitter 4750  
> increment 999998882 absjitter 1118  
> increment 1000000946 absjitter 946  
> increment 999998780 absjitter 1220  
> increment 1000001951 absjitter 1951  
> increment 999999514 absjitter 486  
> increment 999998746 absjitter 1254  
> [...]
> 
>  What may be wrong? 
> 
> I observe the same behaviour if the periodic sampling is given by a
> rt_periodic task or by a rt_sleep_until in the clock loop...
> 

This code works here, so there might be an issue with your environment.
Does some Xenomai message appear in the kernel log, such as SMI warning?
Or did you activate the ACPI+cpufreq support for your kernel?
Also, what does /proc/xenomai/timer and /proc/xenomai/sched say when 
your app is running?

Additionally, three remarks on your code:
- do NOT call rt_task_set_mode(0, T_PRIMARY, NULL); in your 
applications. It's utterly useless and at best a waste of cycles since
Xenomai will move your thread to the proper mode as needed to run the
syscalls. This call is here for the 0.00000001% of situations where 
eager control over the current mode is required by some internal Xenomai 
code, but normal applications should not need this unless they are doing 
something really weird.
- In the same vein, calling rt_timer_set_mode() is useless, unless you 
want to override the default timing mode you set up during the kernel 
configuration (CONFIG_XENO_OPT_TIMING_PERIODIC et al.) If you disabled
the previous option, then your system can only work in aperiodic mode
anyway, so you don't need to re-specify it by a call to rt_timer_set_mode().
- calling printf() in the middle of your measurement loop adds 
uncertainty to your results, since migrating from Xenomai to Linux for 
this purpose - and the other way around to get blocked on 
rt_alarm_wait() - has a cost wrt latency. A 1 second period should not 
be that much perturbated by a printf() though, but still, it's a wrong 
way of writing time predictable code.

{rpm@xenomai.org} sudo ./orcalarm
rt_timer_set_mode(TM_ONESHOT) started
alarm started with period 1000000000 ns
increment 999986989 absjitter 13011
increment 1000006146 absjitter 6146
increment 999989806 absjitter 10194
increment 1000022829 absjitter 22829
increment 999997693 absjitter 2307
increment 1000003468 absjitter 3468
increment 999997452 absjitter 2548
increment 999999961 absjitter 39
increment 1000001230 absjitter 1230
increment 1000025352 absjitter 25352
increment 999985543 absjitter 14457
increment 999998970 absjitter 1030
Ctrl C Interrupt
increment 1000012630 absjitter 12630
jittermoy = 7682, jittermax = 25352
deleting rt devices

-- 

Philippe.

Re: [Xenomai-help] starnge latencies with native

[Gilles Chanteperdrix]

Daniel Simon wrote:
 > Hi all,
 > 
 > I'm doing some tests with the native skins. The attached program uses
 > an alarm to trigger a periodic task and measures the sampling latency. 
 > 
 > Initial latencies are in the range of tens of millisecs. and then
 > decrease slowly to the range of microsecs:
 > 
 > rt_timer_set_mode(TM_ONESHOT) started 
 > alarm started with period 1000000000 ns 
 > increment 1124642266 absjitter 124642266  
 > increment 937743828 absjitter 62256172  
 > increment 1031095424 absjitter 31095424  
 > increment 984466651 absjitter 15533349  
 > increment 1007758686 absjitter 7758686  
 > increment 996126407 absjitter 3873593  
 > increment 1001934707 absjitter 1934707  
 > increment 999039749 absjitter 960251  
 > increment 1000477139 absjitter 477139  
 > increment 999759707 absjitter 240293  
 > increment 1000119631 absjitter 119631  
 > increment 999938964 absjitter 61036  
 > increment 1000029816 absjitter 29816  
 > increment 999985508 absjitter 14492  
 > increment 1000004750 absjitter 4750  
 > increment 999998882 absjitter 1118  
 > increment 1000000946 absjitter 946  
 > increment 999998780 absjitter 1220  
 > increment 1000001951 absjitter 1951  
 > increment 999999514 absjitter 486  
 > increment 999998746 absjitter 1254  
 > [...]
 > 
 >  What may be wrong? 

Are you still running a kernel with ACPI_PROCESSOR ? 

-- 


					    Gilles Chanteperdrix.

Re: [Xenomai-help] starnge latencies with native

[Gilles Chanteperdrix]

Daniel Simon wrote:
 > On Fri, 12 May 2006 18:25:25 +0200
 > Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> wrote:
 > 
 > > Are you still running a kernel with ACPI_PROCESSOR ?
 > 
 > yes, otherwise this laptop stops overheating in a few minutes, may
 > be its not a good platform for real-time ...
 > 
 > may be this behaviour was hidden in the testuite programs by the
 > "warming up" delay???

The warming up delay is only one second, whereas you experience high
latencies during several seconds. The latency test runs with a period of
100 us by default, this may make it less sensitive to the effect you
observe, did you try running the latency test with a period of 1s ?

-- 


					    Gilles Chanteperdrix.

Re: [Xenomai-help] starnge latencies with native

[Daniel Simon]

On Fri, 12 May 2006 19:47:22 +0200
Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org> wrote:

> The warming up delay is only one second, whereas you experience high
> latencies during several seconds. The latency test runs with a period
> of 100 us by default, this may make it less sensitive to the effect
> you observe, did you try running the latency test with a period of
> 1s ?

After freshly booting the laptop this morning, all works well,
latencies are in the range of 1-2 usecs from the first sample (whatever
the period between 100us and 1 sec.)

	Daniel

-- 
      Daniel SIMON    Projet POP ART  INRIA Rhone-Alpes
ZIRST, 655 avenue de l'Europe, 38330 MONTBONNOT SAINT MARTIN, FRANCE 
 Daniel.Simon@domain.hid Phone:(33)476615328 Fax:(33)476615252
	 http://pop-art.inrialpes.fr/people/simon/