Re: Posix Execution time clock

Re: Posix Execution time clock

[Uwe Kleine-König]

Hi Hector,

On Tue, Dec 01, 2009 at 07:14:45AM -0500, Hector Perez Tijero wrote:
> My system is running Linux 2.6.24-25-rt #1 SMP PREEMPT RT  (Ubuntu  
> package) and I run my tests using the affinity parameter to bind all the  
> threads included in the test to the same CPU.
I'm not the expert here, but the experts might ask you to reproduce on a
vanilla rt kernel.  (I'm sure the question will contain the word "crap"
:-)

Best regards
Uwe

-- 
Pengutronix e.K.                              | Uwe Kleine-König            |
Industrial Linux Solutions                    | http://www.pengutronix.de/  |
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Posix Execution time clock

[Hector Perez Tijero]

Hi,

My question might be a little basic for this list... Maybe someone could 
point me out to another forum :)

I'm trying to get some measures using the execution time clock in my 
system and I found some slight differences in the use of the 
CLOCK_THREAD_CPUTIME_ID and CLOCK_MONOTONIC clocks. The measures are 
between the same points of code. My concern is that, sometimes, the 
measure obtained with CLOCK_MONOTONIC is lower than using 
CLOCK_THREAD_CPUTIME_ID. Find below a dummy example to test this strange 
behavior.

It doesn't happen very often but the error could be around hundreds of 
microseconds.

So my question is: are both POSIX clocks based on different physical 
clocks? I always though they use the TSC...

My previous guess was that such behavior could be caused by the CPU 
frequency scaling but the same happened when I disabled it.

My system is running Linux 2.6.24-25-rt #1 SMP PREEMPT RT  (Ubuntu 
package) and I run my tests using the affinity parameter to bind all the 
threads included in the test to the same CPU.

Thanks so much and great work

Hector

---

#include <time.h>
#include <pthread.h>
#include <float.h>

#include <string.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/mman.h>

#define THREAD_CLOCK CLOCK_THREAD_CPUTIME_ID
#define COMMON_CLOCK CLOCK_MONOTONIC

#define LAST_JOB   10000
#define PRIO_HIGH    90

#define MAX_SAFE_STACK (8*1024) /* The maximum stack size which is
                       guaranteed safe to access without
                       faulting */

#define CHK(p) { int ret;                                      \
                 if ((ret = p)) {                   \
                   printf ("Error:"#p":%s\n", strerror (ret)); \
                   exit (-1);                                  \
}                                             \
}

static int error_count = 0;

double timespec_to_double(const struct timespec *time)
{
  return time->tv_nsec*1E-9 + (double)time->tv_sec;
}

void double_to_timespec(double time, struct timespec *ts)
{
  ts->tv_sec = (long) time;
  ts->tv_nsec = (long)((time - (double)ts->tv_sec) * 1E9);
}

void  add_timespec (struct timespec *s,
                    const struct timespec *t1,
                    const struct timespec *t2)
{
  s->tv_sec  = t1->tv_sec  + t2->tv_sec;
  s->tv_nsec = t1->tv_nsec + t2->tv_nsec;
  if (s->tv_nsec >= 1E9) {
    s->tv_sec ++;
    s->tv_nsec -= 1E9;
  }
}

void incr_timespec (struct timespec *t1, const struct timespec *t2)
{
  t1->tv_sec += t2->tv_sec;
  t1->tv_nsec += t2->tv_nsec;
  if (t1->tv_nsec >= 1E9) {
    t1->tv_sec ++;
    t1->tv_nsec -= 1E9;
  }
}

int smaller_or_equal_timespec (const struct timespec *t1,
                                             const struct timespec *t2)
{
  return t1->tv_sec < t2->tv_sec || (t1->tv_sec == t2->tv_sec &&
      t1->tv_nsec <= t2->tv_nsec);
}

int compare_times (float time, struct timespec* start, struct timespec* 
stop)
{
  double diff, start_time, stop_time = 0.0;
 
  start_time = timespec_to_double (start);
  stop_time = timespec_to_double (stop);
 
  diff = stop_time - start_time;
 
  if (time > diff)
  {
    ++error_count;
    printf ("\tError number %d: %7.6f microseconds\n", error_count, 
(time-diff)*1E6);
  }
  return 0;
}

void stack_prefault(void) {

  unsigned char dummy[MAX_SAFE_STACK];

  memset(&dummy, 0, MAX_SAFE_STACK);
  return;
}

int posix_linux_requirements (void) {
  /* Lock memory */
  if(mlockall(MCL_CURRENT|MCL_FUTURE) == -1) {
    perror("mlockall failed");
    return (-1);
  }
 
  /* Pre-fault our stack */
  stack_prefault ();
 
  return 0;
}

void eat (float for_seconds)
{
  struct timespec now, temp, end;
 
  clock_gettime (THREAD_CLOCK, &now);
 
  double_to_timespec (for_seconds, &temp);
  add_timespec (&end, &now, &temp);
 
  do {
    clock_gettime(THREAD_CLOCK, &now);
  }
  while ( smaller_or_equal_timespec (&now, &end) );
}

int main (int argc, char *argv[])
{
  //  Execution Time
  float time = 9E-4;                 //900 microseconds
  struct timespec period = {0, 1.8E6}; //  1.8 milliseconds
  struct sched_param param_rt;
  struct timespec next_activation, start_time, stop_time;
  int count = 0;
 
    
  //  Change policy to SCHED_FIFO and priority to main thread
  param_rt.sched_priority = PRIO_HIGH;
  //CHK ( pthread_setschedparam (pthread_self(), SCHED_FIFO, &param_rt) );
  CHK ( sched_setscheduler (0, SCHED_FIFO, &param_rt) );
 
  //  Set Linux RT-PREEMPT requirements
  CHK ( posix_linux_requirements () );
 
  CHK ( clock_gettime(COMMON_CLOCK, &next_activation) );
 
  for (count = 0; count < LAST_JOB; count++)
  {
 
    CHK (clock_nanosleep(COMMON_CLOCK, TIMER_ABSTIME,
                       &next_activation, NULL));
   
    CHK ( clock_gettime(COMMON_CLOCK, &start_time) );
    //  Do job: execution time clock
    eat (time);
    CHK ( clock_gettime(COMMON_CLOCK, &stop_time) );
    CHK ( compare_times (time, &start_time, &stop_time) );
    //  Compute next activation
    incr_timespec (&next_activation, &period);
  }
  printf ("\nEnd of test\n");
  return 0;
}

Re: Posix Execution time clock

[Luis Claudio R. Goncalves]

On Tue, Dec 01, 2009 at 07:14:45AM -0500, Hector Perez Tijero wrote:
> Hi,
>
> My question might be a little basic for this list... Maybe someone could  
> point me out to another forum :)
>
> I'm trying to get some measures using the execution time clock in my  
> system and I found some slight differences in the use of the  
> CLOCK_THREAD_CPUTIME_ID and CLOCK_MONOTONIC clocks. The measures are  
> between the same points of code. My concern is that, sometimes, the  
> measure obtained with CLOCK_MONOTONIC is lower than using  
> CLOCK_THREAD_CPUTIME_ID. Find below a dummy example to test this strange  
> behavior.
>
> It doesn't happen very often but the error could be around hundreds of  
> microseconds.
>
> So my question is: are both POSIX clocks based on different physical  
> clocks? I always though they use the TSC...

Check the dmesg logs for hints on TSC. There are some TSCs that are not
used as clocksources because they are out-of-sync between CPUs, because
they halt on idle, because they halt on inner C-states and so on...

> My previous guess was that such behavior could be caused by the CPU  
> frequency scaling but the same happened when I disabled it.

How many CPUs?

>From http://www.tin.org/bin/man.cgi?section=3&topic=clock_gettime :

  NOTE for SMP systems
       The CLOCK_PROCESS_CPUTIME_ID and CLOCK_THREAD_CPUTIME_ID clocks are
       realized on many platforms using timers from the CPUs (TSC on i386,
       AR.ITC on Itanium). These registers may differ between CPUs and as a
       consequence these clocks may return bogus results if a process is
       migrated to another CPU.

By definition, CLOCK_MONOTONIC seems to be what you want.

Another interesting detail is that you have to check what is the value of
/proc/sys/kernel/vsyscall64 for it constrols the behavior and resolution of
clock reads (enabling or disabling VDSO clock enhancements). Try setting it
to zero and repeating your tests.

Along with that, the latest version for 2.6.24, IIRC, was 2.6.24.7-rt27.
So, it sounds like you are using older versions of old software.

Regards,
Luis
-- 
[ Luis Claudio R. Goncalves                    Bass - Gospel - RT ]
[ Fingerprint: 4FDD B8C4 3C59 34BD 8BE9  2696 7203 D980 A448 C8F8 ]

Re: Posix Execution time clock

[Hector Perez Tijero]

Hi again,

Thanks for your really quick replies and your contributions!  I have 
found some interesting info:


Luis Claudio R. Goncalves escribió:
> On Tue, Dec 01, 2009 at 07:14:45AM -0500, Hector Perez Tijero wrote:
>   
>> Hi,
>>
>> My question might be a little basic for this list... Maybe someone could  
>> point me out to another forum :)
>>
>> I'm trying to get some measures using the execution time clock in my  
>> system and I found some slight differences in the use of the  
>> CLOCK_THREAD_CPUTIME_ID and CLOCK_MONOTONIC clocks. The measures are  
>> between the same points of code. My concern is that, sometimes, the  
>> measure obtained with CLOCK_MONOTONIC is lower than using  
>> CLOCK_THREAD_CPUTIME_ID. Find below a dummy example to test this strange  
>> behavior.
>>
>> It doesn't happen very often but the error could be around hundreds of  
>> microseconds.
>>
>> So my question is: are both POSIX clocks based on different physical  
>> clocks? I always though they use the TSC...
>>     
>
> Check the dmesg logs for hints on TSC. There are some TSCs that are not
> used as clocksources because they are out-of-sync between CPUs, because
> they halt on idle, because they halt on inner C-states and so on...
>
>   
My dmesg output:
    [    8.333748] checking TSC synchronization [CPU#0 -> CPU#1]:
    [    8.353732] Measured 3359526540 cycles TSC warp between CPUs, 
turning off TSC clock.
    [    8.353737] Marking TSC unstable due to: check_tsc_sync_source 
failed.

So my system is not using the TSC...

>   
>> My previous guess was that such behavior could be caused by the CPU  
>> frequency scaling but the same happened when I disabled it.
>>     
>
> How many CPUs?
>   
A DualCore.

> >From http://www.tin.org/bin/man.cgi?section=3&topic=clock_gettime :
>
>   NOTE for SMP systems
>        The CLOCK_PROCESS_CPUTIME_ID and CLOCK_THREAD_CPUTIME_ID clocks are
>        realized on many platforms using timers from the CPUs (TSC on i386,
>        AR.ITC on Itanium). These registers may differ between CPUs and as a
>        consequence these clocks may return bogus results if a process is
>        migrated to another CPU.
>   
Yeah, I have check the available clocks in 
/sys/devices/system/clocksource/clocksource0/available_clocksource
    >>hpet acpi_pm jiffies tsc

and the clock used according to cat 
/sys/devices/system/clocksource/clocksource0/current_clocksource
    >>hpet

I have switched to acpi_pm but the same issue exists. I have also 
disabled one CPU in the BIOS to use the TSC... I though it could be good 
try but... useless

> By definition, CLOCK_MONOTONIC seems to be what you want.
>
>   
No, I actually need the CLOCK_THREAD_CPUTIME_ID. Basically I have to get 
some execution times measures to perform the schedulability analysis. 
But I have found this strange behavior and I just wonder why.
> Another interesting detail is that you have to check what is the value of
> /proc/sys/kernel/vsyscall64 for it constrols the behavior and resolution of
> clock reads (enabling or disabling VDSO clock enhancements). Try setting it
> to zero and repeating your tests.
>
>   
That functionality is only for 64bits, isn't it? My computer is still 32 
bits... :)

Please let me know any new suggestion...

Regards,

Hector

--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Posix Execution time clock

[Uwe Kleine-König]

On Tue, Dec 01, 2009 at 10:32:28AM -0200, Luis Claudio R. Goncalves wrote:
> Along with that, the latest version for 2.6.24, IIRC, was 2.6.24.7-rt27.
> So, it sounds like you are using older versions of old software.
The version scheme of Ubuntu doesn't allow to read the used rt patch
from the kernel version.  The Ubuntu version used is 2.6.24-25-rt.  This
only means something like:  The 25th Ubuntu revision of the 2.6.24
kernel in the rt feature set.

Best regards
Uwe

-- 
Pengutronix e.K.                              | Uwe Kleine-König            |
Industrial Linux Solutions                    | http://www.pengutronix.de/  |
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Posix Execution time clock

[Hector Perez Tijero]

Hi all,

Just to complete the info. I have repeated a similar test (SMP and 
scaling frequency disabled in the BIOS, TSC clock) with another function:

If I measure the attached function with CLOCK_THREAD_CPUTIME_ID, I keep 
getting variable timing results. The execution of this function takes 
about 400 usecs in my system. Having called it more than 10_000 times, 
most of the measures are within 100 usecs from this value. This range 
makes sense to me. But I have found a few measures (less than 10 out of 
10_000) which are over 1100 usecs, which it's a bit suspicious. Since 
this clock just takes the execution time associated to a single thread 
(no preemption time should be included) and the function's execution 
time could be considered as "constant", it seems that something is going 
wrong with this kind of clock.

Any idea?

Thanks

Hector

PS: Ubuntu 2.6.24.-25-rt is based on 2.6.24.7-rt27 patch (link 
<http://packages.ubuntu.com/hardy-updates/linux-restricted-modules-2.6.24-25-rt>)

void make_job ()
{
  long temp = 0;
  int index, index2 = 0;
  for (index = 0; index < 5000; index ++) {
     temp += index;
     if (index%97 == 0) {
       for (index2 = 0; index2 < 1000; index2 ++) {
          temp +=index;
       }
     }
  }
}

Uwe Kleine-König escribió:
> On Tue, Dec 01, 2009 at 10:32:28AM -0200, Luis Claudio R. Goncalves wrote:
>   
>> Along with that, the latest version for 2.6.24, IIRC, was 2.6.24.7-rt27.
>> So, it sounds like you are using older versions of old software.
>>     
> The version scheme of Ubuntu doesn't allow to read the used rt patch
> from the kernel version.  The Ubuntu version used is 2.6.24-25-rt.  This
> only means something like:  The 25th Ubuntu revision of the 2.6.24
> kernel in the rt feature set.
>
> Best regards
> Uwe
>
>   
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html