Teensy 4.1 timing inconsistencies with IntervalTimers

M

mnissov

Well-known member
Following
I am working on a sensor timing project, I'm nearing the end now however I still have a couple of minor problems I need to work through. The basic idea is that I use TeensyTimerTool and 3 interval timers to create the rising edge of the trigger signals at 200, 20, and 10Hz. I then use a PWM oneshot timer for scheduling the falling edge such that the widths are 10, 250, and 250 us.

These values aren't necessarily set in stone so a certain amount of flexibility is required

Overall this has been working fine but I am experiencing some unexpected deviation in the rising edges. I'm using a saleae logic pro 8 as oscilloscope and clock the following results after collecting data for 10 mins
  • run 1
    • 200 Hz => [f_max, f_mean, std_dev] = [200.006, 200.001 Hz, 66.801 ns]
    • 20 Hz => [f_max, f_mean, std_dev] = [20, 20.0 Hz, 69.55 ns]
    • 10 Hz => [f_max, f_mean, std_dev] = [10, 10.0 Hz, 80.643 ns]
  • run 2
    • 200 Hz => [f_max, f_mean, std_dev] = [990.805, 200.006 Hz, 19.808 us]
    • 20 Hz => [f_max, f_mean, std_dev] = [116.118, 20.005 Hz, 635.732 us]
    • 10 Hz => [f_max, f_mean, std_dev] = [115.529, 10.005 Hz, 1.836 ms]

I'm still analyzing but I think it seems pretty clear that the increase in std_dev comes from the standout f_max.

Note: I am working with interrupts so this definitely lends an element of complexity, but AFAIK, these interrupts are small and implemented "correctly". The interrupts are:
For keeping timing up to date
Code: 
void setupInterrupt(const uint8_t & pin)
{
  pinMode(pin, INPUT_PULLUP);
  attachInterrupt(digitalPinToInterrupt(pin), fallingISR, FALLING);
}

elapsedMicros micros_from_second;
volatile uint32_t unix_seconds;
void fallingISR()
{
  micros_from_second = 0;
  unix_seconds++;
}

and for responding to the periodic timer interrupts:
Code: 
inline void prepare_message(
  const uint8_t & type, const uint32_t & seconds, const uint32_t & micros, const uint32_t & count,
  uint8_t msg[])
{
  msg[0] = type;
  memcpy(&msg[1], &seconds, sizeof(seconds));  // 1->4
  memcpy(&msg[5], &micros, sizeof(micros));    // 5->8
  memcpy(&msg[9], &count, sizeof(count));      // 9->12
}

inline void TriggerGenerator::PeriodicCallback()
{
  digitalWriteFast(pin_, HIGH);
  // REVIEW: need no interrupt?
  micros_ = micros_from_second;
  seconds_ = unix_seconds;

  prepare_message(type_, seconds_, micros_, count_, msg);
  Serial.write(msg, msg_size); // msg_size const is 13

  ++count_;
  TriggerFallingEdge();
}
inline void TriggerGenerator::TriggerFallingEdge() { one_shot_timer_.trigger(width_); }

Is there some overhead associated with using teensytimertool which I can get around?






I have the data in csv, but I'm having trouble attaching this. I can attach the code as well, but it's grown relatively long at this point, so not sure how much people want to comb through its entirety.
 
I can attach the code as well, but it's grown relatively long at this point, so not sure how much people want to comb through its entirety.
Click to expand...

Best is to provide a minimal and complete example showing the effect.

Is there some overhead associated with using teensytimertool which I can get around?
Click to expand...

Starting/stopping/triggering the timers of course needs some time. But once a periodic (hardware) timer runs, it should be quite stable. As mentioned, if you provide a simple example, I can dive deeper into it.
 
I'll try and get back to you with a simple example, as I said it's not necessarily extremely regular.

For example, for the 10Hz timer I processed the data in python and the following is the first 10 entries of sampling time, where I've sorted from low to high.
Code: 
# row nr    sampling time [s]
1829    0.008656
1833    0.021013
211     0.041395
210     0.058604
1832    0.078986
1830    0.091343
5279    0.099999
4668    0.099999
4665    0.099999
4654    0.099999
so you can see the anomalies are grouped and not necessarily all together or all near the beginning.

Note, slightly unrelated but I had one uncertainty about the following part of this function
Code: 
  digitalWriteFast(pin_, HIGH);
  // REVIEW: need no interrupt?
  micros_ = micros_from_second;
  seconds_ = unix_seconds;

where micros_from_second and unix_seconds are volatile uint32_t and elapsedMicros. Would I need to call nointerrupt before and after? The values of both are set in the following pin-based interrupt function
Code: 
\
elapsedMicros micros_from_second;
volatile uint32_t unix_seconds;
void fallingISR()
{
  micros_from_second = 0;
  unix_seconds++;
}
Note I am intentionally copying values over to the class member variables micros_ and seconds_ because I figured this would be the surest way to access the volatiles for as little time as possible. I'm not sure if this could cause any problem though.
 
Here are some figures I made illustrating all sampling times > 1 std deviation from the mean
anomaly_10hz.jpganomaly_20hz.jpganomaly_200hz.jpg

Note these are all grouped, and many of them happen when all three triggers fire on the same timestamp (as observed by logic analyzer)

Edit: Correction to what I said. Actually every time the logic analyzer reports all three trigger rising edges at the same stamp, they also have frequency problems.
Code: 
             time  Channel 0  Channel 1  Channel 2  sig0_diff  sig1_diff  sig2_diff
9675    20.958463          1          1          1        1.0        1.0        1.0
84083  182.707362          1          1          1        1.0        1.0        1.0
84207  182.977691          1          1          1        1.0        1.0        1.0

I'm not sure if this condemns the logic analyzer or my implementation, I'll make a minimal test case asap.
 
Maybe it is one interrupt interfering with the other.

That is, if you have code like this:
Code: 
inline void TriggerGenerator::PeriodicCallback()
{
  digitalWriteFast(pin_, HIGH);
  // REVIEW: need no interrupt?
  micros_ = micros_from_second;
  seconds_ = unix_seconds;

 [COLOR="#FF0000"] prepare_message(type_, seconds_, micros_, count_, msg);
  Serial.write(msg, msg_size); // msg_size const is 13[COLOR="#FF0000"][/COLOR]
[/COLOR]
  ++count_;
  TriggerFallingEdge();
}
And they both run at default priority (probably the same), one won't be called when the code is in the other...

Now you do Serial output. The stuff is queued up into a Serial buffer, maybe something like up to 512 bytes and when the buffer is full, it maybe transfers the data to the USB port, and if it thinks there is not enough room in the USB serial queue, it will wait until there is room. So maybe you hit this and then the code has to wait until buffer is transferred over USB...

You might try raising the priority (lower number) for the interrupt that is giving you inconsistent timing.
 
It's one of three periodic callbacks (each associated with an intervaltimer) which has these delays. It happens in larger degree to the low frequency ones, but all three suffer (almost simultaneously) as you can see from the plots in my previous post. So I'm not sure if changing the priority will fix much, as all three are effected and they are the brunt of the interrupt time being used.

Each serial write is 13 bytes, should I not be doing this in the interrupt callback itself? Would raising the baud rate help? Or maybe I should just create the message here and write is elsewhere (like n the main loop for example


Edit: @KurtE one thought I just had. Looking at the plots it seems like all three signals hit the correct sampling time but with an occasional additional rising edge hidden between two correct rising edges. If interrupt were blocking one another I would expect one of the "correctly placed" rising edges to be missing and shifted right? This is looks like extra rising edges which shouldn't be there, at least from what I can see right now.

In addition, the delay on the 10Hz makes me more confident in this, as one of the incorrect signals is almost a full 0.1 second wrong. This feels like a very long time to me. But I don't know, curious to hear your thoughts.
 
Last edited:
luni said:
Best is to provide a minimal and complete example showing the effect.



Starting/stopping/triggering the timers of course needs some time. But once a periodic (hardware) timer runs, it should be quite stable. As mentioned, if you provide a simple example, I can dive deeper into it.
Click to expand...


Sorry for spamming this thread. I've managed to create a test case which fails the same way, first run was successful, second run resulted in 200Hz f_max over 1kHz and the 10Hz signal having a std deviation of >1ms


Here are the files for the test case, I hope it's simple enough. Tried to keep the essence without changing the structure too much, TriggerGeneratorTest.h is where the meat is
View attachment TriggerGeneratorTest.hView attachment configuration.hView attachment test_case.cpp
 
I had a look at your test case and, since I don't want to mess with python, I adapted the code to print the measured periods and pulsewidths directly into a serial monitor.

Code: 
#pragma once

#include <Arduino.h>
#include <TeensyTimerTool.h>

elapsedMicros micros_from_second;
volatile uint32_t unix_seconds;

namespace sensor_sync
{
    // const uint8_t msg_size = 9;
    const uint8_t msg_size = 13;
    uint8_t msg[msg_size];

    void prepare_message(const uint8_t& type, const uint32_t& stamp, const uint32_t& count, uint8_t msg[])
    {
        msg[0] = type;
        msg[1] = stamp;
        msg[2] = stamp >> 8;
        msg[3] = stamp >> 16;
        msg[4] = stamp >> 24;
        msg[5] = count;
        msg[6] = count >> 8;
        msg[7] = count >> 16;
        msg[8] = count >> 24;
    }

    inline void prepare_message(const uint8_t& type, const uint32_t& seconds, const uint32_t& micros, const uint32_t& count, uint8_t msg[])
    {
        msg[0] = type;
        memcpy(&msg[1], &seconds, sizeof(seconds)); // 1->4
        memcpy(&msg[5], &micros, sizeof(micros));   // 5->8
        memcpy(&msg[9], &count, sizeof(count));     // 9->12
    }

    class TriggerGenerator
    {
     public:
        TriggerGenerator();
        ~TriggerGenerator() {}

        void begin(
            const uint8_t& type, const uint8_t& pin, const unsigned long& interval,
            const unsigned long& width);
        void stop();
        void reset();

     private:
        void TriggerFallingEdge();
        void PeriodicCallback();
        void OneShotCallback();

        TeensyTimerTool::OneShotTimer one_shot_timer_;
        TeensyTimerTool::PeriodicTimer periodic_timer_;

        uint32_t count_;
        uint32_t seconds_;
        uint32_t micros_;

        // Parameters
        uint8_t type_;
        uint8_t pin_;
        unsigned long interval_;
        unsigned long width_;

        // timing determination <======================================================
        unsigned period      = 0;
        unsigned periodStart = 0;
        unsigned pulseStart  = 0;
    };

    TriggerGenerator::TriggerGenerator()
        : one_shot_timer_(TeensyTimerTool::TMR1), periodic_timer_(TeensyTimerTool::PIT)
    {
    }

    void TriggerGenerator::begin(const uint8_t& type, const uint8_t& pin, const unsigned long& interval, const unsigned long& width)
    {
        type_     = type;
        pin_      = pin;
        interval_ = interval;
        width_    = width;

        pinMode(pin_, OUTPUT);

        one_shot_timer_.begin([this]() { this->OneShotCallback(); });
        periodic_timer_.begin([this]() { this->PeriodicCallback(); }, interval_);
    }

    void TriggerGenerator::stop() { periodic_timer_.stop(); }

    void TriggerGenerator::reset() { count_ = 0; }

    inline void TriggerGenerator::TriggerFallingEdge() { one_shot_timer_.trigger(width_); }

    inline void TriggerGenerator::OneShotCallback()
    {
        digitalWriteFast(this->pin_, LOW);

        uint32_t pulseWidth = (ARM_DWT_CYCCNT - pulseStart) / 600;  // use the cycle counter (600 cnts per microsecond) to time the pulsewidth 

        // print results in colums for easy handling in a spreadsheet, assume pins 2,3,4 (hack) <=================================
        Serial.printf("pin: %d\t",pin_);
        for (int i = 0; i < (pin_ - 2) * 2; i++) Serial.print("\t");
        Serial.printf("%d\t%d\n", period, pulseWidth);
    }

    inline void TriggerGenerator::PeriodicCallback()
    {
        // use the cycle counter (600 cycles per microsecond) for timing  <==================================
        uint32_t now = ARM_DWT_CYCCNT;
        period       = (now - periodStart) / 600;
        periodStart  = now;

        digitalWriteFast(pin_, HIGH);
        pulseStart = ARM_DWT_CYCCNT;

        // // REVIEW: need no interrupt?
        // micros_  = micros_from_second;
        // seconds_ = unix_seconds;

        // // prepare_message(type_, stamp, count_, msg);
        // prepare_message(type_, seconds_, micros_, count_, msg);
        // Serial.write(msg, msg_size);

        ++count_;
        TriggerFallingEdge();
    }
} // namespace sensor_sync

This prints:
Code: 
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250
pin: 4					100000	250
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250
pin: 4					100000	250
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250
pin: 4					100000	250
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 2	5000	10
pin: 3			50000	250

I did some 10'000 lines and didn't find a single deviation from the expected values. It also does not change after restarting the sketch.

Maybe the strange behaviour has to do with your python script. If Python doesn't read values fast enough, the PC USB receive buffers might fill up which makes the USB Serial connection waiting until the PC buffers have space again. In this case, the Teensy side blocks sending for some time, waiting to get rid of the bytes in the Teensy transmitt buffer. After some time (~100ms ?) it stops waiting and ignores further attempts to print until the USB bus request data again.

This of course is a wild guess only. But since it works flawlessly when directly printing on the monitor it might be worth looking at your Python skript.
 
My reading side is typically a c++ program which, should, read everything as it comes. At least it looks that way. But when i was capturing the data which I used for the plots above and to check the minimal test case fails, I'm pretty sure I just let it go to monitor. I can verify this and try again tomorrow.

Is there any chance you can put an oscilloscope on yours? Somehow i get the feeling it's either a physical problem or one with my logic analyzer, note i don't have pulldowns or anything like that on any of pins (including I2C to RTC). Not sure if that's necessary, it definitely hasn't made any obvious problems as of yet.

I just think it's very hard to understand how it's creating more pulses than should be there, if that makes sense? I would've expected shifting a pulse could maybe be a problem, but extra just feels strange.
 
@luni - I was thinking the same thing in my earlier post.
KurtE said:
Maybe it is one interrupt interfering with the other.
...
Code: 
inline void TriggerGenerator::PeriodicCallback()
...
 [COLOR="#FF0000"] prepare_message(type_, seconds_, micros_, count_, msg);
  Serial.write(msg, msg_size); // msg_size const is 13[COLOR="#FF0000"][/COLOR]
[/COLOR]
}
...
Now you do Serial output. The stuff is queued up into a Serial buffer, maybe something like up to 512 bytes and when the buffer is full, it maybe transfers the data to the USB port, and if it thinks there is not enough room in the USB serial queue, it will wait until there is room. So maybe you hit this and then the code has to wait until buffer is transferred over USB...
...
/QUOTE]

luni said:
I had a look at your test case and, since I don't want to mess with python, I adapted the code to print the measured periods and pulsewidths directly into a serial monitor.
...
Maybe the strange behaviour has to do with your python script. If Python doesn't read values fast enough, the PC USB receive buffers might fill up which makes the USB Serial connection waiting until the PC buffers have space again. In this case, the Teensy side blocks sending for some time, waiting to get rid of the bytes in the Teensy transmitt buffer. After some time (~100ms ?) it stops waiting and ignores further attempts to print until the USB bus request data again.

This of course is a wild guess only. But since it works flawlessly when directly printing on the monitor it might be worth looking at your Python skript.
Click to expand...

I never had much luck with pyserial.... but that is a different story. But my assumption, is it filled the USB queue, and then the Serial.write() waited while still in the ISR until there was room to add the data to the output queue, and then returned. During that time the actual timer(s) probably would have gone off several times, but only after the one function returned was it able to process each of them. But Singular one on each timer ...

Wondering if you could simply add check for room... That is:
Code: 
inline void TriggerGenerator::PeriodicCallback()
{
  digitalWriteFast(pin_, HIGH);
  if (Serial.availableForWrite() > 13) {
    // REVIEW: need no interrupt?
    micros_ = micros_from_second;
    seconds_ = unix_seconds;

    prepare_message(type_, seconds_, micros_, count_, msg);
    Serial.write(msg, msg_size); // msg_size const is 13

    ++count_;
    TriggerFallingEdge();
  } else {
    // not sure what you want to do if no room on USB...
}
Click to expand...
 
Wondering if you could simply add check for room... That is:
Click to expand...

I personally would rather write the data in a ringbuffer in the ISR and do the serial writing in the foreground code. This would make handling connection losses, slow PCs etc much easier. One could also send larger chunks from the ringbuffer which would increase efficiency.

@mnissov I'm curious what this micros/unix_seconds thing is. In case you just need a timestamp it might be simpler to use the cycleCounter or the micros value. Here some information on how to extend it to 64bit if necessary https://github.com/TeensyUser/doc/wiki/Using-the-cycle-counter
 
I thought I posted a response to KurtE but I see it didn't go through.
The response was that I had tried commenting out the Serial.write line and that the error was still happening after approx 100s of capturing. Trying to progressively cut down on the minimal example to isolate the cause, sorry that the example I posted wasn't truly "minimal working".

@mnissov I'm curious what this micros/unix_seconds thing is. In case you just need a timestamp it might be simpler to use the cycleCounter or the micros value. Here some information on how to extend it to 64bit if necessary https://github.com/TeensyUser/doc/wi...-cycle-counter
Click to expand...
The reason for this is one objective of this system is to achieve very high precision timing, I'm trying to do this by using an external RTC (1ppm). So the (maybe poorly named) unix_seconds/micros are resulting from a 1Hz pulse from the RTC and an internal elapsedMicros for the in-between time to ensure the overall timekeeping. Maybe this isn't a perfect solution either.

@luni I'm still very curious how your test performs on oscilloscope, if this is possible.
 
@luni I'm still very curious how your test performs on oscilloscope, if this is possible.
Click to expand...
Actually I started using my logic analyzer. But since I didn't see anything and it is quite tedious to scan through the recording I switched to printing out the values. I can let it run for a time and see if something happens on the LA.
 
Fair enough, I'm lucky enough mine can take measurement over a range, so it calculates all of these metrics for me. I have a python script for the same, but I'm not sure how much use it will be if our data isn't of the same format.
 
Here a recording of about 200 seconds with the minmal / maximal positive and negative pulse widths.

Screenshot 2023-01-31 095901.jpg

Zoomed in for better reading:
Screenshot 2023-01-31 100129.jpg

This all looks perfectly normal to me

Here the csv of the data: View attachment untitled.zip
 
What's going on in line 463 of your csv? Formatting of the time becomes a bit interesting. Otherwise mine uses more or less the same format, so the python script should be usable.
Code: 
0.997303625000000,;0;0;0
1.002.293.875.000.000,00;1;0;0
1.002.304.375.000.000,00;0;0;0

I agree this looks promising, it's hard to reproduce for me as some runs (10 mins) have std deviation in the ns and then suddenly there comes one with std deviation in the ms. I think the most consistency I've achieved so far is 2 good runs in a row, with a failing third following. Or something to this degree.

Note this is without any serial communication as well.
 
What's going on in line 463 of your csv?
Click to expand...
Don't know, I just exported the csv from the LA app.

Zooming in at t=1s shows nothing unusual in the recording:

Screenshot 2023-01-31 102932.jpg

Note this is without any serial communication as well.
Click to expand...
Ok, I assume this is in your original program? So, anything else which generates some unexpected delay? If you manage to change your minimal program to provoke/show the effect reliably it shouldn't be too difficult to find the root cause of the issue.
 
Just seeing this ... not seeing all code where 'micros_from_second' is accessed.
Is this _isr on the same priority as the others? So they cannot interrupt each other and have the second change a volatile value? And using elapsedMicros value is run by code (takes time and subject to potential interrupt volatility):
Code: 
void fallingISR()
{
  micros_from_second = 0;
  unix_seconds++;
}

The T_4's 1062 timing runs millis on an _isr, and micros() tracks the cycles from the last millis tick update - and has 'atomic read' protection in place (see below).

This independent RTC clock will slip versus the Teensy clocking by 500 to perhaps 2,500 cycles per second - tested against GPS PPS. Every one tested here is short of 600M by that many ticks - and it shifts over time by temp or 'whatever' excites the crystal base. (it was the similar on T_3.6).

Not sure if that fills in anything useful? Suggesting a problem or solution?

Not sure how that would affect the timing running as seen good by @luni - unless that RTC PPS time slippage or interrupts are factoring in?

For cool interrupt safe code that gives microseconds offset based on last millis tick update (similar to what the RTC PPS is doing here ?)
With Paul's cleanup for 'rounding up frac' it looks like this and runs in 36-38 cpu cycles:
Code: 
// Returns the number of microseconds since your program started running.
// This 32 bit number will roll back to zero after about 71 minutes and
// 35 seconds.  For a simpler way to build delays or timeouts, consider
// using elapsedMicros.
uint32_t micros(void)
{
	uint32_t smc, scc;
	do {
		__LDREXW(&systick_safe_read);
		smc = systick_millis_count;
		scc = systick_cycle_count;
	} while ( __STREXW(1, &systick_safe_read));
	uint32_t cyccnt = ARM_DWT_CYCCNT;
	asm volatile("" : : : "memory");
	uint32_t ccdelta = cyccnt - scc;
	uint32_t frac = ((uint64_t)ccdelta * scale_cpu_cycles_to_microseconds) >> 32;
	if (frac > 1000) frac = 1000;
	uint32_t usec = 1000*smc + frac;
	return usec;
}

If the math were changed {in a local microsRTC()} to seconds from milliseconds for base units, the RTC PPS Tick value could be used for the timestamp for use? And even done with 64 bit math it wouldn't rollover every ~71 minutes (at the cost of a couple more cycles than ~36 ?).
Without 'correction' it would still have the 'slippage' of 1062's crystal missing those 500-2500'ish cycles each second.
There is 'toy'/WIP code here in my window with a GPS tracking true PPS seconds and updating an interval timer microseconds ticks to run in sync with the PPS.
It was unplugged the other day when IDE 2 failed to update the right Teensy when a T_4 was plugged in. It was just plugged back in and the Space Data will take a bit to get sync'd to show output again.
If interested I could post 'C:\T_Drive\tCode\TIME\GPS_iValTimer\GPS_iValTimer.ino' in its current state. It is a couple years old - last updated after T_4.0 shipped - and revisited a bit the other month.
There is a T_4.0 and now a T_4.1 with diff GPS's and one started already showing:
Code: 
 us 192093359 cyc diff        765 	err= 1.27 us	[3824 cyc diff Mn=3019 Mx=3824 P= 999993.88 ( 999993.69
 us 193093352 cyc diff        698 	err= 1.16 us	[3776 cyc diff Mn=3019 Mx=3824 P= 999993.88 ( 999993.69
 us 194093346 cyc diff        638 	err= 1.06 us	[3772 cyc diff Mn=3019 Mx=3824 P= 999993.88 ( 999993.69
 us 195093340 cyc diff        592 	err= 0.99 us	[3776 cyc diff Mn=3019 Mx=3824 P= 999993.88 ( 999993.75
 us 196093334 cyc diff        537 	err= 0.90 us	[3776 cyc diff Mn=3019 Mx=3824 P= 999993.88 ( 999993.75

That looks like the 'slower/erratic one/gps'. Both in a cold pocket by the window - above missing 3,776 cycles per second - and corrected to 0.90us.

Running another minute the slippage got worse and is still stabilizing - with some awful spikes of err over 0.22us (like 34us):
Code: 
 us 377092155 cyc diff 4294967162 	err=-0.22 us	[2624 cyc diff Mn=2124 Mx=2628 P= 999995.56 ( 999995.62
 us 378092151 cyc diff 4294967162 	err=-0.22 us	[2624 cyc diff Mn=2124 Mx=2628 P= 999995.56 ( 999995.62
 us 379092146 cyc diff 4294967162 	err=-0.22 us	[2628 cyc diff Mn=2124 Mx=2628 P= 999995.56 ( 999995.62
 us 380092142 cyc diff 4294967162 	err=-0.22 us	[2624 cyc diff Mn=2124 Mx=2628 P= 999995.56 ( 999995.62
 us 381092137 cyc diff 4294967162 	err=-0.22 us	[2624 cyc diff Mn=2124 Mx=2628 P= 999995.56 ( 999995.62
When they are warm and running they seemed to be staying corrected to some part of 1 us.
The output above shows intervalTimer set to 999993.88 to 999995.56 microseconds to stay in near sync with the GPS PPS.

The other one runs better - but it is still getting a Space Data Lock it seems. I got a new GPS still in wrapper - these units are 4-5 years old and have no battery being mostly unplugged.

There is something very Spastic about this unit - it was that way the other week running the same code the other one was well behaved the other week. The two share a hub and I never even bothered to figure out which of the two was which (T_4.1 is slow start and T_4.0 is the erratic one) and WHY.
I did add code to drop the MAX recorded cycle diff when it went full scale on the one - and the other doesn't do that. Maybe your RTC PPS would give good results. I ordered GPS from SparkFun and also an RTC - but in first connect it did not give a consistent PPS like a GPS does.
Code: 
 us 379522613 cyc diff 4294967162 	err=-0.22 us	[4294958368 cyc diff Mn=672 Mx=4294958368 P=1000014.75 (1000014.81
 us 380522628 cyc diff 4294967162 	err=-0.22 us	[4294958372 cyc diff Mn=672 Mx=4294958372 P=1000014.75 (1000014.81
 us 381522642 cyc diff 4294967162 	err=-0.22 us	[4294958372 cyc diff Mn=672 Mx=4294958372 P=1000014.75 (1000014.81
 us 382522657 cyc diff     831490 	err= 1385.82 us	[4294958372 cyc diff Mn=672 Mx=4294958372 P= 999987.06 ( 999779.19
 us 383522672 cyc diff     255247 	err= 425.41 us	[4294958368 cyc diff Mn=672 Mx=4294958368 P= 999978.56 ( 999914.75
 us 384522451 cyc diff     462300 	err= 770.50 us	[132476 cyc diff Mn=672 Mx=132476 P= 999963.12 ( 999847.56
 us 385522366 cyc diff      45964 	err= 76.61 us	[51124 cyc diff Mn=672 Mx=132476 P= 999961.56 ( 999950.06
 us 386522214 cyc diff 4294967162 	err=-0.22 us	[91476 cyc diff Mn=672 Mx=132476 P= 999961.56 ( 999961.62
 us 387522164 cyc diff 4294967162 	err=-0.22 us	[29976 cyc diff Mn=672 Mx=132476 P= 999961.56 ( 999961.62
 us 388522126 cyc diff     562386 	err= 937.31 us	[23024 cyc diff Mn=672 Mx=132476 P= 999942.81 ( 999802.19
 us 389522087 cyc diff      13516 	err= 22.53 us	[23024 cyc diff Mn=672 Mx=132476 P= 999942.38 ( 999939.00
 us 390521889 cyc diff     392419 	err= 654.03 us	[118676 cyc diff Mn=672 Mx=132476 P= 999929.31 ( 999831.19
 us 391521828 cyc diff     929446 	err= 1549.08 us	[36576 cyc diff Mn=672 Mx=132476 P= 999898.31 ( 999665.94
 us 392521660 cyc diff 4294967162 	err=-0.22 us	[101276 cyc diff Mn=672 Mx=132476 P= 999898.31 ( 999898.38
 us 393521326 cyc diff 4294967162 	err=-0.22 us	[200424 cyc diff Mn=672 Mx=200424 P= 999898.31 ( 999898.38
 us 394521224 cyc diff      28938 	err= 48.23 us	[60976 cyc diff Mn=672 Mx=200424 P= 999897.38 ( 999890.12
...
 us 554518512 cyc diff 4294966920 	err=-0.63 us	[4876 cyc diff Mn=672 Mx=7976 P= 999991.69 ( 999991.81
 us 555518504 cyc diff 4294966954 	err=-0.57 us	[4872 cyc diff Mn=672 Mx=7976 P= 999991.69 ( 999991.75
 us 556518495 cyc diff 4294966982 	err=-0.52 us	[4876 cyc diff Mn=672 Mx=7976 P= 999991.69 ( 999991.75
 us 557518487 cyc diff 4294966963 	err=-0.56 us	[4924 cyc diff Mn=672 Mx=7976 P= 999991.69 ( 999991.75
 us 558518479 cyc diff 4294966939 	err=-0.60 us	[4928 cyc diff Mn=672 Mx=7976 P= 999991.69 ( 999991.75

Not sure this could help as it would require scaling 1 sec to 99999? microseconds - or some other machinations to keep timing 'adjusted' toward a true value.

What RTC unit is used there?
 
Just in case it helps with time sync and analysis.
Code used above came from this 2 year old @PaulStoffregen post "Here's a little program to automatically adjust the IntervalTimer period.": pjrc.com/threads/65941-IntervalTimer-inaccuracy-Discipline-Scope-Video-included

No scope here so edited for SerMon 'visual'. Need to revisit Paul's original 'adjust' logic as used here.
Erratic GPS after overnight with bigger Max-Mn cycle swing:
Code: 
 us 3692416261 cyc diff        340 	err= 0.57 us	[4872 cyc diff Mn=176 Mx=5110 P= 999991.88 ( 999991.81
The other is also a T_4.0, but soldered to a FRDM4236 before T_4.1 was released:
Code: 
 us 2890336257 cyc diff        883 	err= 1.47 us	[1576 cyc diff Mn=596 Mx=1576 P= 999997.62 ( 999997.38
 us 2891336254 cyc diff        863 	err= 1.44 us	[1576 cyc diff Mn=596 Mx=1576 P= 999997.62 ( 999997.44
 us 2892336252 cyc diff        848 	err= 1.41 us	[1572 cyc diff Mn=596 Mx=1576 P= 999997.62 ( 999997.44
 
micros_from_second is only accessed in the callback and the ISR, but actually it's not so important because the described behavior happens when I comment it out as well, still working on the up-to-date minimal example to demonstrate the behavior.

All ISRs are on the default priority, both that for the timers and for the pin interrupt

This independent RTC clock will slip versus the Teensy clocking by 500 to perhaps 2,500 cycles per second - tested against GPS PPS. Every one tested here is short of 600M by that many ticks - and it shifts over time by temp or 'whatever' excites the crystal base. (it was the similar on T_3.6).
Click to expand...
I'm not entirely understanding, you're saying the RTC or the teensy clock is incorrect in this case?

For cool interrupt safe code that gives microseconds offset based on last millis tick update (similar to what the RTC PPS is doing here ?)
Click to expand...
Yeah this sounds more or less what I was trying to do, as the RTC resolution isn't great so I use the PPS to keep global tracking and elapsedMicros for the increased resolution

If the math were changed {in a local microsRTC()} to seconds from milliseconds for base units, the RTC PPS Tick value could be used for the timestamp for use? And even done with 64 bit math it wouldn't rollover every ~71 minutes (at the cost of a couple more cycles than ~36 ?).
Click to expand...
So this is the micros function definition? And it is more or less unaffected by other ISRs? Micros overflowing is not necessarily a huge problem due to the generally short operating time of the system.

If the math were changed {in a local microsRTC()} to seconds from milliseconds for base units, the RTC PPS Tick value could be used for the timestamp for use? And even done with 64 bit math it wouldn't rollover every ~71 minutes (at the cost of a couple more cycles than ~36 ?).
Without 'correction' it would still have the 'slippage' of 1062's crystal missing those 500-2500'ish cycles each second.
There is 'toy'/WIP code here in my window with a GPS tracking true PPS seconds and updating an interval timer microseconds ticks to run in sync with the PPS.
It was unplugged the other day when IDE 2 failed to update the right Teensy when a T_4 was plugged in. It was just plugged back in and the Space Data will take a bit to get sync'd to show output again.
If interested I could post 'C:\T_Drive\tCode\TIME\GPS_iValTimer\GPS_iValTimer .ino' in its current state. It is a couple years old - last updated after T_4.0 shipped - and revisited a bit the other month.
Click to expand...
this could actually be quite interesting if you're okay with sharing


What RTC unit is used there?
Click to expand...
RV3028
 
mnissov said:
micros_from_second is only accessed in the callback and the ISR, but actually it's not so important because the described behavior happens when I comment it out as well, still working on the up-to-date minimal example to demonstrate the behavior.

All ISRs are on the default priority, both that for the timers and for the pin interrupt


I'm not entirely understanding, you're saying the RTC or the teensy clock is incorrect in this case?


Yeah this sounds more or less what I was trying to do, as the RTC resolution isn't great so I use the PPS to keep global tracking and elapsedMicros for the increased resolution


So this is the micros function definition? And it is more or less unaffected by other ISRs? Micros overflowing is not necessarily a huge problem due to the generally short operating time of the system.

this could actually be quite interesting if you're okay with sharing



RV3028
Click to expand...

Interrupts are a mixed blessing with 'shared data/purpose'. Same PRI means one can delay the other - diff PRI means one can interrupt the other :)

Not questioning RTC accuracy/correctness - saw Digikey Eval board and that 'chip' says good things. Based on GPS PPS testing seen here 'real' seconds typically happen with the Teensy running about 500 to 8000 cycles behind the suggested 600 MHz clock speed.

Indeed one second PPS alone doesn't provide stellar resolution where onboard Teensy crystal drives the onboard sense of time, and it 'slips' each second as the Cycle counts run short. 1062 has onboard RTC that may be more accurate with its own crystal (?) - but again it only reports 1 second changes.

Yes, that is the code from PJRC CORES for Micros(). During T_4.0 Beta the clock on hand for MillisTick was driven by a 24 MHz clock (?) - limiting the precision of micros() to Tenths of 'us' IIRC. I put that micros() together to use the 1062's Cycle Counter to use the 600 MHz clock to time how long since the last Mills() tick arrived to get extended resolution to microseconds. And yes that [ Do {} while; ] loop will repeat if that enclosed code reading the two systick_millis reference values have ANY interrupt occur during their execution. The only one important is the 1K Hz millis tick update - but it does happen, as may others, and it will delay the loop() exit to make sure the 8 bytes of 'volatile' data {scc & smc} are read Atomically for a non-corrupted calculation.

That link in p#19 shows Paul's contribution and the initial version of the code here. Current code here needs some study - and maybe move to unpacking the NEW GPS to see if it gives better PPS signal. Something is really triggering the one in use and the Paul corection code may have been contaminated. I'll post hopefully in the next day, maybe with a version of microsPPS() that incorporates RTC/GPS PPS interrupt updates.

Thanks for the 'RV3028' name. Only eval board/shield I found quickly was the Digikey link above. SFun has a board for less, but doesn't expose the 'INT' pin that I assume is triggered on the PPS? Got two SFUN RV 1805's but quick test found the INT to trigger some inconsistent # of millis offset each second :(
 
Indeed one second PPS alone doesn't provide stellar resolution where onboard Teensy crystal drives the onboard sense of time, and it 'slips' each second as the Cycle counts run short. 1062 has onboard RTC that may be more accurate with its own crystal (?) - but again it only reports 1 second changes.
Click to expand...
From what I've read the teensy's inbuilt RTC crystal is rated worse (20ppm I think), though I've read of people demonstrating as low as 8ppm performance, think that was a post from you actually.


Yes, that is the code from PJRC CORES for Micros(). During T_4.0 Beta the clock on hand for MillisTick was driven by a 24 MHz clock (?) - limiting the precision of micros() to Tenths of 'us' IIRC. I put that micros() together to use the 1062's Cycle Counter to use the 600 MHz clock to time how long since the last Mills() tick arrived to get extended resolution to microseconds. And yes that [ Do {} while; ] loop will repeat if that enclosed code reading the two systick_millis reference values have ANY interrupt occur during their execution. The only one important is the 1K Hz millis tick update - but it does happen, as may others, and it will delay the loop() exit to make sure the 8 bytes of 'volatile' data {scc & smc} are read Atomically for a non-corrupted calculation.

That link in p#19 shows Paul's contribution and the initial version of the code here. Current code here needs some study - and maybe move to unpacking the NEW GPS to see if it gives better PPS signal. Something is really triggering the one in use and the Paul corection code may have been contaminated. I'll post hopefully in the next day, maybe with a version of microsPPS() that incorporates RTC/GPS PPS interrupt updates.
Click to expand...
Ok cool sounds, interesting. A little off-topic for the post but I'm interested to see how this progresses.

Thanks for the 'RV3028' name. Only eval board/shield I found quickly was the Digikey link above. SFun has a board for less, but doesn't expose the 'INT' pin that I assume is triggered on the PPS? Got two SFUN RV 1805's but quick test found the INT to trigger some inconsistent # of millis offset each second
Click to expand...
Yeah I've found several vendors with breakouts (for example), but it's really a mixed bag of lacking documentation and insufficient exposed pins.
 
@mnissov : Opened/soldered/wired the SparkFun GPS Logger Shield to a T_4.1. Got Space Data Fix in the window, saw UART strings and went to the indicated code and made what seem to be improvements. No time now to add PPS second counter and microsPPS() trial.

Output here now looks like:
Code: 
C:\T_Drive\tCode\TIME\SFunGPS_IO\SFunGPS_IO.ino Feb  1 2023 01:21:44
...
us  212754347 cyc diff    -3 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  213754344 cyc diff     1 	err= 0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  214754340 cyc diff    -3 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  215754337 cyc diff   -10 	err=-0.02 us	 Mn=  -17 Mx=    4 P= 999996.56
us  216754333 cyc diff    -2 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  217754330 cyc diff     1 	err= 0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  218754326 cyc diff    -3 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  219754323 cyc diff    -3 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  220754319 cyc diff    -4 	err=-0.01 us	 Mn=  -17 Mx=    4 P= 999996.56
us  221754316 cyc diff     2 	err= 0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  222754313 cyc diff    -3 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  223754309 cyc diff    -8 	err=-0.01 us	 Mn=  -17 Mx=    4 P= 999996.56
us  224754306 cyc diff    -3 	err=-0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
us  225754302 cyc diff     1 	err= 0.00 us	 Mn=  -17 Mx=    4 P= 999996.56
...
us 1438750107 cyc diff     8 	err= 0.01 us	 Mn=  -17 Mx=   15 P= 999996.56
us 1439750104 cyc diff    -4 	err=-0.01 us	 Mn=  -17 Mx=   15 P= 999996.56
us 1440750100 cyc diff     2 	err= 0.00 us	 Mn=  -17 Mx=   15 P= 999996.56
us 1441750097 cyc diff     5 	err= 0.01 us	 Mn=  -17 Mx=   15 P= 999996.56
us 1442750093 cyc diff     3 	err= 0.00 us	 Mn=  -17 Mx=   15 P= 999996.56
...
> so this Teensy has 999996.56 cycles per Space Data PPS second.

Changed from prior output:
- _isr's {gps() and pulse() } tweaked to expose the cycles DIFF in their firing, not just the ARM_DWT_CYCCNT itself
- one _isr does pin 16 ON for intervalTimer, then OFF on GPS PPS - no delay in _isr. No scope here but
- Seems the PID adjust values from linked Paul post are working now - though there is some variability between runs - maybe the distance in the _isr's?
- removed some goofy code not to be mentioned.
- didn't expose for easy change PIN 17 is PPS pin and PIN 16 is the _isr change output for a scope.
Code: 
IntervalTimer mytimer;
volatile uint32_t cyclesRisingEdge;
volatile uint32_t cyclesPulse;
volatile bool gotRisingEdge = false;
volatile bool gotPulse = false;
int firstAdjust = 0;
float period = 1000000.0;

void setup() {
  while (!Serial && millis() < 4000 );
  Serial.println("\n" __FILE__ " " __DATE__ " " __TIME__);
  pinMode(17, INPUT);
  pinMode(16, OUTPUT);
  if ( ARM_DWT_CYCCNT == ARM_DWT_CYCCNT ) { // start Cyc Cnt if IDLE, i.e. T_3.x's
    ARM_DEMCR |= ARM_DEMCR_TRCENA;
    ARM_DWT_CTRL |= ARM_DWT_CTRL_CYCCNTENA;
  }
  Serial.println("\n Waiting for PPS toggle ...\n");
  while (digitalReadFast(17) == HIGH);
  while (digitalReadFast(17) == LOW);
  mytimer.begin(pulse, period);
  mytimer.priority(192);
  attachInterrupt(17, gps, RISING);
}

void gps() {
  static uint32_t last = 0;
  uint32_t now = ARM_DWT_CYCCNT;
  cyclesRisingEdge = now - last;
  last = now;
  gotRisingEdge = true;
  digitalWriteFast(16, LOW);
}

void pulse() {
  static uint32_t last = 0;
  uint32_t now = ARM_DWT_CYCCNT;
  cyclesPulse = now - last;
  last = now;
  gotPulse = true;
  digitalWriteFast(16, HIGH);
}

int32_t cyclesPulseLast;
int32_t cyclesPulseMax = -1;
int32_t cyclesPulseMin = F_CPU;
void loop() {
  if (gotRisingEdge && gotPulse) {
    int32_t cDiff = cyclesPulse - cyclesRisingEdge;
    Serial.printf( "us %l10u cyc diff %5ld \t", micros(), cDiff );
    float err = cDiff * (1000000.0f / (float)F_CPU);
    if (0 == firstAdjust) period = period - err * 0.75;
    period = period - err * 0.02;         // integral control
    mytimer.update(period - err * 0.25);  // proportional control
    gotRisingEdge = false;
    gotPulse = false;
    if ( err < 0)
      Serial.print("err=");
    else
      Serial.print("err= ");
    Serial.print(err);
    Serial.print(" us");
    if ( firstAdjust > 8 ) {
      if ( cDiff < cyclesPulseMin ) cyclesPulseMin = cDiff;
      if ( cDiff > cyclesPulseMax ) cyclesPulseMax = cDiff;
      if ( cyclesPulseMax > (int32_t)(F_CPU_ACTUAL / 10) ) cyclesPulseMax = 0; // Reset MAX if signal loss corrupted
      Serial.printf( "\t Mn=%5ld Mx=%5ld P=%10.2f\n", cyclesPulseMin, cyclesPulseMax, period );
    }
    else {
      firstAdjust++;
      Serial.println();
    }
  }
}

Same code on the one prior T_4.0 looks good like below, and way wacky on the other:
Code: 
 Waiting for PPS toggle ...

us    1729519 cyc diff  2588 	err= 4.31 us
us    2729519 cyc diff  2010 	err= 3.35 us
us    3729515 cyc diff  -647 	err=-1.08 us
us    4729510 cyc diff  -491 	err=-0.82 us
us    5729507 cyc diff   104 	err= 0.17 us
us    6729504 cyc diff   104 	err= 0.17 us
us    7729501 cyc diff   -96 	err=-0.16 us
us    8729497 cyc diff   -94 	err=-0.16 us
us    9729494 cyc diff     1 	err= 0.00 us
us   10729491 cyc diff     3 	err= 0.00 us	 Mn=    3 Mx=    3 P= 999996.62
us   11729487 cyc diff   -45 	err=-0.08 us	 Mn=  -45 Mx=    3 P= 999996.62
us   12729484 cyc diff   -46 	err=-0.08 us	 Mn=  -46 Mx=    3 P= 999996.62
us   13729481 cyc diff   -52 	err=-0.09 us	 Mn=  -52 Mx=    3 P= 999996.62
us   14729477 cyc diff   -47 	err=-0.08 us	 Mn=  -52 Mx=    3 P= 999996.62
us   15729474 cyc diff   -46 	err=-0.08 us	 Mn=  -52 Mx=    3 P= 999996.62
us   16729470 cyc diff   -48 	err=-0.08 us	 Mn=  -52 Mx=    3 P= 999996.62
us   17729467 cyc diff   -52 	err=-0.09 us	 Mn=  -52 Mx=    3 P= 999996.62
...
us  858726691 cyc diff   -54 	err=-0.09 us	 Mn= -214 Mx=    6 P= 999996.62
us  859726688 cyc diff   -56 	err=-0.09 us	 Mn= -214 Mx=    6 P= 999996.62
us  860726684 cyc diff   -53 	err=-0.09 us	 Mn= -214 Mx=    6 P= 999996.62

...
 
Yeah I've found several vendors with breakouts (for example), but it's really a mixed bag of lacking documentation and insufficient exposed pins.
Click to expand...
Get one free from the chip manufacturer.
It is possible to get a sample.
When I filled out a form on their web site they sent me free samples and a free demo board.
 
You must log in or register to reply here.
Back
Top