was "chTimeNow() precision", now "RTC precision"

[russian]

What is the expected precision of chTimeNow() if used to measure time intervals? I am getting something around 9% error (against real time clock) on my stm32f4 with 2.4.2 code.

I have taken rtcGetTimeUnix function from 2.5 branch and my is rtcGetTimeUnixMs is "mktime(&timp) * 1000 + timp.__extra_1"

In a loop, I am saving chTimeNow() and rtcGetTimeUnixMs values, and sleep. With default CH_FREQUENCY I get
9779 tick interval = 10656 ms interval, 8.9% error
With CH_FREQUENCY=10000, it is 9930 ticks = 1084 ms, 9.1% error
I am driving some pins output based on these times to check intervals with external logic analyzer and seems like real time clock values are the real ones. So, is this 9% error something expected due to the nature of chTimeNow() implementation based on SysTick?

[Giovanni]

Hi,

Are you running with the internal oscillator or an external oscillator? the system time is supposed to be as accurate as the clock source used. Another possible cause is that you keep interrupts disabled for too long and some ticks are lost.

Giovanni

[russian]

I am running stm32f4discovery in it's default configuration, I believe it has a 8MHz external oscillator on the board.

In the same program, I am driving another output pin by a 62.5KHz PWM timer - this pin shows precise 62.5KHz frequency on my analyzer. So I guess the issue is on the software side? I am not doing anything explicit to disable interrupts, could interrupts be dropped behind the scene for any reason? Like too many pending SysTck interrupts which cannot be handled due to free cpu cycles/SysLock contention?

[Giovanni]

Hi,

Try running with debug options enabled, especially the state checker, it could catch an illegal usage of lock primitives. I am not sure about how to test this.

Is the RTC running from LSI or LSE?

Giovanni

[hazelnusse]

I use a for loop like so:

Code: Select all

systime_t time = chTimeNow();     // Initial time
for (uint32_t i = 0; !chThdShouldTerminate(); ++i) {
  time += MS2ST(5);  // Increment by 5ms

  // main work of my loop goes here

  chThdSleepUntil(time);
}


I also use a separate free-running timer counting up at 4MHz (0.25 microseconds per timer count) to record the time, so that I have high-resolution timing of my loop (and various things that occur during the loop). I get very good results with this. There is a little bit of jitter, but it very small (+/- 10.0 us) and doesn't occur frequently.

[russian]

Now I am even more confused: I was assuming RTC to be... real. Not really. My test shows systicks are precise but the RTC is 11% off, how is that possible? Do I need to calibrate the board somehow? how?

So, I am executing this on a STM32F4discovery board. First the output:

Code: Select all

+** ChibiOS/RT test suite
*** Kernel:       2.4.2
*** Compiled:     Nov 30 2012 - 20:48:57
timetest.2
CH_FREQUENCY=1000
Sleeping a bit...
Running 30 seconds test...
before 26:56 mm:ss
after  27:30 mm:ss
raw rtcDiff      = 33720 ms
raw chDiff       = 30000 ticks
raw pwmDiff      = 1874960 counts
pwmRatio = 29999
Sleeping a bit...
Running 100 seconds test...
before 27:33 mm:ss
after  29:25 mm:ss
raw rtcDiff      = 112332 ms
raw chDiff       = 100000 ticks
raw pwmDiff      = 6249945 counts
pwmRatio = 99999

Now some details: PWM frequency is set to 62.5KHz and I am counting callbacks, also I check how will chTimeNow() value change relative to number of callback events and the RTC value change. My external (physical) stop watch in my hands shows sys ticks are real time, but as you can see RTC values are not in sync with the systicks! Which also means they are not in sync with real timer, how is that possible?

Code: Select all

#include "main.h"
#include "board.h"
#include "rficonsole.h"
#include "rfirtc.h"
 #include <rtc.h>
#include <time.h>

#define TEST_PWMD PWMD4
#define TIM4_CH1_PB6_PIN 6
#define TIM4_CH4_PB9_PIN 9
#define FREQ 62500

int pwmCounter = 0;

/*
 * PWM cyclic callback.
 */
static void pwmpcb(PWMDriver *pwmp) {

  (void)pwmp;

  chSysLockFromIsr();
  pwmCounter++;

  if(pwmCounter % 2 == 0 ) {
     pwmEnableChannel(&TEST_PWMD, 3, PWM_FRACTION_TO_WIDTH(&TEST_PWMD, 1, 1));
  } else {
     pwmEnableChannel(&TEST_PWMD, 3, PWM_FRACTION_TO_WIDTH(&TEST_PWMD, 1, 0));
  }

  chSysUnlockFromIsr();
}

/*
 * PWM configuration structure.
 * Cyclic callback enabled, channels 1 and 4 enabled without callbacks,
 * the active state is a logic one.
 */
static PWMConfig pwmcfg = {
  2 * FREQ,                                    /* PWM clock frequency.   */
  2,                                    /* PWM period (in ticks).    */
  pwmpcb,
  {
    {PWM_OUTPUT_ACTIVE_HIGH, NULL},
    {PWM_OUTPUT_DISABLED, NULL},
    {PWM_OUTPUT_DISABLED, NULL},
    {PWM_OUTPUT_ACTIVE_HIGH, NULL}
  },
  /* HW dependent part.*/
  0
};


/**
 * blinking thread to show that we are alive
 */
static WORKING_AREA(blinkingThreadStack, 128);

void blinkingThread(void *arg) {
   while (TRUE) {
      palSetPad(GPIOD, GPIOD_LED5); // red - blinks via thread
      chThdSleepMilliseconds(100);
      palClearPad(GPIOD, GPIOD_LED5); // red - blinks via thread
      chThdSleepMilliseconds(100);
   }
}

struct TimesSnapshot {
   long pwmCounter;
   long tr;
   int tm_sec;
   int tm_min;
   long chTime;
   long rtcTime;
};
typedef struct TimesSnapshot TimesSnapshot;

static void stm32_rtc_bcd2tm(struct tm *timp, RTCTime *timespec) {
   uint32_t tv_time = timespec->tv_time;
   uint32_t tv_date = timespec->tv_date;
   uint32_t tv_msec = timespec->tv_msec;

#if CH_DBG_ENABLE_CHECKS
   timp->tm_isdst = 0;
   timp->tm_wday = 0;
   timp->tm_mday = 0;
   timp->tm_yday = 0;
   timp->tm_mon = 0;
   timp->tm_year = 0;
   timp->tm_sec = 0;
   timp->tm_min = 0;
   timp->tm_hour = 0;
#endif

   timp->__extra_1 = tv_msec;

   timp->tm_isdst = -1;

   timp->tm_wday = (tv_date & RTC_DR_WDU ) >> RTC_DR_WDU_OFFSET;
   if (timp->tm_wday == 7)
      timp->tm_wday = 0;

   timp->tm_mday = (tv_date & RTC_DR_DU ) >> RTC_DR_DU_OFFSET;
   timp->tm_mday += ((tv_date & RTC_DR_DT )>> RTC_DR_DT_OFFSET) * 10;

   timp->tm_mon = (tv_date & RTC_DR_MU ) >> RTC_DR_MU_OFFSET;
   timp->tm_mon += ((tv_date & RTC_DR_MT )>> RTC_DR_MT_OFFSET) * 10;
   timp->tm_mon -= 1;

   timp->tm_year = (tv_date & RTC_DR_YU ) >> RTC_DR_YU_OFFSET;
   timp->tm_year += ((tv_date & RTC_DR_YT )>> RTC_DR_YT_OFFSET) * 10;
   timp->tm_year += 2000 - 1900;

   timp->tm_sec = (tv_time & RTC_TR_SU ) >> RTC_TR_SU_OFFSET;
   timp->tm_sec += ((tv_time & RTC_TR_ST )>> RTC_TR_ST_OFFSET) * 10;

   timp->tm_min = (tv_time & RTC_TR_MNU ) >> RTC_TR_MNU_OFFSET;
   timp->tm_min += ((tv_time & RTC_TR_MNT )>> RTC_TR_MNT_OFFSET) * 10;

   timp->tm_hour = (tv_time & RTC_TR_HU ) >> RTC_TR_HU_OFFSET;
   timp->tm_hour += ((tv_time & RTC_TR_HT )>> RTC_TR_HT_OFFSET) * 10;
   timp->tm_hour += 12 * ((tv_time & RTC_TR_PM )>> RTC_TR_PM_OFFSET);
}

time_t rtcGetTimeUnixMs(RTCDriver *rtcp) {
#if STM32_RTC_HAS_SUBSECONDS
   RTCTime timespec = { 0, 0, FALSE, 0 };
#else
   RTCTime timespec = {0,0,FALSE};
#endif
   struct tm timp;

   rtcGetTime(rtcp, &timespec);
   stm32_rtc_bcd2tm(&timp, &timespec);

   return mktime(&timp) * 1000 + timp.__extra_1;
}

#define currentTimeMillis() rtcGetTimeUnixMs(&RTCD1)

void grabTimes(TimesSnapshot *sn) {
   chSysLock(); // trying to be as atomic as I can be
   sn->pwmCounter = pwmCounter;
   sn->tr = RTCD1.id_rtc->TR;
   sn->chTime = chTimeNow();
   sn->rtcTime = currentTimeMillis(); // actually this method unlock Sys but that's fine
   chSysUnlock();

   sn->tm_sec = (sn->tr & RTC_TR_SU ) >> RTC_TR_SU_OFFSET;
   sn->tm_sec += ((sn->tr & RTC_TR_ST )>> RTC_TR_ST_OFFSET) * 10;

   sn->tm_min = (sn->tr & RTC_TR_MNU ) >> RTC_TR_MNU_OFFSET;
   sn->tm_min += ((sn->tr & RTC_TR_MNT )>> RTC_TR_MNT_OFFSET) * 10;
}

void runTest(int len) {
    print("Sleeping a bit...\r\n");
    chThdSleepMilliseconds(3000); // couple of seconds for things to settle down

    print("Running %d seconds test...\r\n", len / 1000);
    TimesSnapshot before;
    grabTimes(&before);

    chThdSleepMilliseconds(len); // does not matter how precise sleep is - we measure relative values
    TimesSnapshot after;
    grabTimes(&after);

    print("before %d:%d mm:ss\r\n", before.tm_min, before.tm_sec);
    print("after  %d:%d mm:ss\r\n", after.tm_min,  after.tm_sec);

    long rtcDiff = after.rtcTime - before.rtcTime;
    long chDiff = after.chTime - before.chTime;
    long pwmDiff = after.pwmCounter - before.pwmCounter;

    print("raw rtcDiff      = %d ms\r\n", rtcDiff);
    print("raw chDiff       = %d ticks\r\n", chDiff);
    print("raw pwmDiff      = %d counts\r\n", pwmDiff);

    float pwmRatio = (1000.0 * pwmDiff) / FREQ; // number of ms if counted as PWM ticks

    // todo: need function to print float values
    print("pwmRatio = %d\r\n", (int)(pwmRatio));
}

int main(void) {
   halInit();
   chSysInit();

   palSetPad(GPIOD, GPIOD_LED3); // orange - constant ON

   chThdCreateStatic(blinkingThreadStack, sizeof(blinkingThreadStack),
         NORMALPRIO, blinkingThread, NULL);

   initConsole();

     /*
      * Initializes the PWM driver 4
      */
     pwmStart(&TEST_PWMD, &pwmcfg);
     palSetPadMode(GPIOB, TIM4_CH1_PB6_PIN, PAL_MODE_ALTERNATE(2));  /* PB6 */
     palSetPadMode(GPIOB, TIM4_CH4_PB9_PIN, PAL_MODE_ALTERNATE(2));  /* PB9 */

    pwmEnableChannel(&TEST_PWMD, 0, PWM_FRACTION_TO_WIDTH(&TEST_PWMD, 2, 1));

//    runTest(1000);
//    runTest(10000);
    runTest(30000);
    runTest(100000);

   while (TRUE) {
      palSetPad(GPIOD, GPIOD_LED6); // blue - blinks via main method
      chThdSleepMilliseconds(100);
      palClearPad(GPIOD, GPIOD_LED6); // blue - blinks via main method
      chThdSleepMilliseconds(100);
   }
   return 0;
}



[mabl]

Code: Select all

   chSysLock(); // trying to be as atomic as I can be
   sn->pwmCounter = pwmCounter;
   sn->tr = RTCD1.id_rtc->TR;
   sn->chTime = chTimeNow();
   sn->rtcTime = currentTimeMillis(); // actually this method unlock Sys but that's fine
   chSysUnlock();


chTimeNow and the call to rtcGetTime inside currentTimeMillis are surely "normal functions" and cannot be called from a lock zone.

Try running with debug options enabled, especially the state checker, it could catch an illegal usage of lock primitives. I am not sure about how to test this.

That is exactly what Giovanni meant. Please turn on the state checker and fix your api calls.

[Giovanni]

Is the RTC running from LSE or LSI? LSI is a loop oscillator and you should not expect precision.

Giovanni

[mabl]

I am running stm32f4discovery in it's default configuration, I believe it has a 8MHz external oscillator on the board.

Is the RTC running from LSE or LSI? LSI is a loop oscillator and you should not expect precision.

Probably it is running from LSI (see also mcuconf.h). LSE would be a 32.768kHz Oscillator, right? I don't think there is one on the f4discovery...

[Giovanni]

Yes, there isn't one mounted in normal boards so unless russian soldered the components himself probably this is the problem.

Giovanni