Difference between elapsed real time and elapsed time with TimeLib's now()

I've been using TimeLib to track elapsed seconds with my Arduino Micro.

My goal is to send a Sigfox message (using a serial port and another card) every 12 minutes. I store data from the softwareSerial port every 2 minutes. Once I stored data 6 times, I print a timestamp and send a Sigfox message.

My problem is that the messages are received [Edit: by Sigfox] around every 13 minutes, so they must be sent at the same rate.

My usage of the serial ports are Serial1 for the Sigfox card, and SoftwareSerial for the device that gives me the data I need to send. The softwareSerial port is used very often (about 70 characters per second).

Relevant code:

#include <SoftwareSerial.h>
#include <TimeLib.h>

//USB Serial commands and messages
#define DEBUG
#ifdef DEBUG
  //send sigfox-related debug on USB Serial
  #define DEBUG_SIGFOX

  //send datagiver-related debug on USB Serial
  //#define DEBUG_DATAGIVER

  //RAM usage debug on USB serial
  //#define DEBUG_VERBOSE
#endif

#define DATAGIVER_RX 10
#define DATAGIVER_TX 11
SoftwareSerial datagiverSerial(DATAGIVER_RX , DATAGIVER_TX);

uint8_t data[12];
int8_t lastSaveId;
time_t nextSaveDate;

void setup()
{
  // initialize digital pin LED_BUILTIN as an output.
  pinMode(LED_BUILTIN, OUTPUT);

#ifdef DEBUG
  Serial.begin(9600);
  while(!Serial)
    blinkForUSBSerial();

  timestamp();
  Serial.println();
#endif

  Serial1.begin(9600);
  delay(100);

  datagiverSerial.begin(4800);
  delay(100);
  
  for (int i = 0; i < 12; i++)
    data[i] = 0;
  lastSaveId = -1;
  nextSaveDate = 0;
  
#ifdef DEBUG
  Serial.println("-- SETUP DONE --");
#endif
}

void loop()
{
  [... Debug stuff ...]

  if (datagiverSerial.available())
    parseDatagiver(readDatagiver());

  if (lastSaveId == 6)
  {
    sendRadioMessage(data, 12); //lasts 6 seconds
    lastSaveId = 0;
    for (int i = 0; i < 12; i++)
      data[i] = 0;
  }

  [... Debug stuff ...]
}

#ifdef DEBUG
void timestamp()
{
  time_t t = now();
  
  String hh = String(hour(t));
  if (hh.length() == 1)
    hh = "0" + String(hour(t));
  
  String mm = String(minute(t));
  if (mm.length() == 1)
    mm = "0" + String(minute(t));
  
  String ss = String(second(t));
  if (ss.length() == 1)
    ss = "0" + String(second(t));
  
  Serial.print("[" + hh + ":" + mm + ":" + ss + "] ");
}
#endif

String readDatagiver()
{
  String result = "";
    
  while (aeroSerial.available())
  {
    result += (char)datagiverSerial.read();
    delay(10);
  }
  
  return result;
}

void parseDatagiver(String message)
{
  float value1 = 0;
  float value2 = 0;

  [... String treatment ...]

  writeData(value1, value2);
}

void writeData(int value1, int value2)
{
  if (lastSaveId == 6)
    return; //no space to save
    
  time_t t = now();
  if (t >= nextSaveDate)
  {
    lastSaveId++;
#ifdef DEBUG
    timestamp();
    Serial.println("DATA GOT TO NEXT ID: " + String(lastSaveId));
#endif
    //nextSaveDate = t + 120;
    nextSaveDate += 120;
  }
  
  if (254 < value1)
  {
    data[2 * lastSaveId] = 254;
    data[2 * lastSaveId + 1] = value2;
  }
  else if (data[2 * lastSaveId] < value1) // < 254
  {
    data[2 * lastSaveId] = value1;
    data[2 * lastSaveId + 1] = value2;
  }
}

//Send Sigfox Radio Message
void sendRadioMessage(uint8_t msg[], int size)
{
  String message = "AT$SF=";
  for (int i = 0; i < size; i++)
  {
    message += String(msg[i] << 4, HEX);
    message += String((msg[i] << 4) >> 4, HEX);
  }
  sendSigfox(message);
}

void sendSigfox(String message)
{
  Serial1.print(message + '\n');
}

It's obviously not optimised, but the goal for now is to get something functional. Thanks for the read, and for the help!

You are trying to synchronise messages which you send from your Arduino with messages which are sent from Sigfox. Is that right ?
You are sending messages at the rate of 1 message every 12 minutes and receiving messages at the rate of 1 message every 13 minutes. You want to now adjust the schedule of activities on the Arduino so you can match the rate at which you are receiving these messages. And you are having trouble achieving this using the TimeLib ?

TimeLib is not actually tracking elapsed time. Well technically it is but not the way you may be thinking.
TimeLib is based on the unix time tracking method which tracks the number of seconds since Jan 1, 1970 12:00am GMT.
That point in time is called the epoch.
This type of tracking is very useful when you want to keep things in sync between things that may cross timezones since timezones are irrelevant when tracking time in this way.
It is also very useful if wanting a timestamp that is immune to timezones and DST type adjustments.

You only have to deal with timezones or DST adjustments when converting the time_t value to a human readable format and the human wants to see the local time in some other timezone than GMT.
Other than that the raw time_t value is the timestamp.

If you don't initialize the time_t counter inside TimeLib it starts from 0 which can look like an elapsed time but is really allowing the time tracking to start counting from Jan 1, 1970 12:00am GMT.

If you were to wait a while, you would notice that hour() will start over each time 24 hours elapses.

If all you need to do is track elapsed time are not concerned about the actual time, then simply use millis()
Just subtract a saved value of millis() from the current value of millis() and you will know how many milliseconds have elapsed since the saved value of millis() was done.
You can do some simple math to convert that to hour, mins, etc...

--- bill

Thanks for the advice. I was not aware of millis(). I tried using it instead and the result is the same.

Here is a log from the USB Serial connection with debug enabled. BRKWS01 is the Sigfox card, AT$SF is the command to send a message to the Sigfox server.

[00:10:00.790] DATA GOT TO NEXT ID: 5
[00:12:00.391] DATA GOT TO NEXT ID: 6
SENT TO BRKWS01: AT$SF=030a020e0000000007050000
RECIEVED FROM BRKWS01: OK
\n
[00:14:00.800] DATA GOT TO NEXT ID: 1
[00:16:00.375] DATA GOT TO NEXT ID: 2
[00:18:00.805] DATA GOT TO NEXT ID: 3
[00:20:00.347] DATA GOT TO NEXT ID: 4
[00:22:00.785] DATA GOT TO NEXT ID: 5
[00:24:00.391] DATA GOT TO NEXT ID: 6
SENT TO BRKWS01: AT$SF=000000000000000000000000
RECIEVED FROM BRKWS01: OK
\n
[00:26:00.001] DATA GOT TO NEXT ID: 1
[00:28:00.457] DATA GOT TO NEXT ID: 2
[00:30:00.081] DATA GOT TO NEXT ID: 3
[00:32:00.541] DATA GOT TO NEXT ID: 4
[00:34:00.140] DATA GOT TO NEXT ID: 5
[00:36:00.569] DATA GOT TO NEXT ID: 6
SENT TO BRKWS01: AT$SF=000000000000000000000000
RECIEVED FROM BRKWS01: OK
\n
[00:38:00.109] DATA GOT TO NEXT ID: 1
[00:40:00.489] DATA GOT TO NEXT ID: 2

And here is the result on the Sigfox API.

2018-01-17 10:24:05 	030a020e0000000007050000 
2018-01-17 10:37:10 	000000000000000000000000 
2018-01-17 10:50:15 	000000000000000000000000

Is it possible the high amount of reads on datagiverSerial causes delay to the clock ? I've used a stopwatch and 130s elapsed between two "NEXT ID" prints (should be 120s).

I tried with and without debug, the total delay between each message ends up being from 1min 03s to 1min 05s over 12m

Tried disconnecting the datagiverSerial device and reconnecting it every 2 minutes. The delay reduces drastically.

Overloading a SoftwareSerial port makes the internal clock slow down, apparently.

Can you give the hardware serial port to the application and use software serial for your debug messages ?

My debug commands/prints are sent via the micro-USB serial port.

The hardware serial port (pins RX/TX) is connected to the Sigfox card, and the software serial port (pins 10/11) is connected to my data source.

I'll try switching them up.

Works perfectly when the large amount of reads is on the hardware serial port, the messages are recieved exactly every 12 minutes.

Thanks!

The softwareSerial port is used very often (about 70 characters per second).

I missed this earlier.

It isn't an "overloading" issue, it likely has to do with the way SoftwareSerial works and the baudrate being used.

SoftwareSerial has to mask interrupts while transmitting and at 9600 baud the character time is close to 1ms so it could potentially cause a missed timer tick, which happen at 1ms intervals.

I would try bumping the SoftwareSerial baud rate and see if the time stops slipping.

--- bill