Serial.print 0 from elapsed millis() [SOLVED]

fabelizer · March 15, 2021, 9:06pm

Today I am working on a Chinese Nano clone. This started out as a quick programming exercise to count loops in a second to practice using the attached RTC. I sorted that out, and decided to add a millis timer to see how far away from a second the code varied. This took a few hours, as I am less than a proficient coder! (hence the practice project ) In any case, my issue for the past few hours has been trying to get the difference in elapsed time to print in the serial monitor and I have been unsuccessful in finding an answerto why I only get a zero, when plainly the difference is ~1000mS. Below is the code I am using.

/*
 * Demonstrates timing.counting with RTC
 * seconds field. Since seconds are so long
 * in microprocessor time, it is imperative
 * to begin timing at a known point after
 * the seconds field changes. In this program,
 * the loop is completed 939 (usually) in one
 * second on the RTC. This does not account for
 * data fetch from the RTC, print and could vary in
 * time to complete the loop.
 * 
 * A millis counter was included as an after
 * thought, but consumes additional cycles to
 * calculate and print the values,adding error time.
 * 
 * Currently,
 * I cannot get a difference in millis to print.
 * and I am lost in rabbit hole after rabbit hole!
 * It should be 1000, but I only get 0.
 */
 
#include "Arduino.h"
#include <math.h>
#include <Wire.h>
#include "RTClib.h"

//pin A4 SDA
//pin A5 SCL

int loopCounter = 0;
int printCounter = 0; //to avoid repeatedly printing time
int sec = 0;  //seconds
int lastSec = 0;
int firstSec = 0;
unsigned long startMillis = 0;
unsigned long endMillis = 0;
unsigned long elapsedMillis = 0;

DateTime now;
RTC_DS1307 rtc;

void setup() {
  Serial.begin(115200);
  rtc.begin();
  if (!rtc.begin()) {
    Serial.println("Couldn't find RTC");
    while (1);
  }
  
  Serial.println();
  Serial.println("FinishedSetup");
  now = rtc.now();
  firstSec = now.second();

}//end setup

void loop() {

  now = rtc.now();
  sec = now.second();

  if (sec > firstSec) {
    startMillis = millis();
    lastSec = sec;
    //Serial.println("DEBUG1");
    loopCounter++;
    if (printCounter < 1) {
      Serial.print(startMillis);
      Serial.println(" startMillis");
      printTime();
      printCounter ++;
    }
  }

  if (lastSec == (firstSec + 2)) {
    endMillis = millis();
    Serial.print(endMillis);
    Serial.println(" endMillis");
    printTime();
    elapsedMillis = endMillis - startMillis;
    Serial.print(elapsedMillis);
    Serial.println(" elapsedMillis");
    Serial.print(loopCounter);
    Serial.println(" loops in an RTC second");
    while (1);
  }
}//end loop


void printTime() {
  Serial.println();
  if (now.hour() < 10)
  {
    Serial.print("0");
  }
  Serial.print(now.hour());
  Serial.print(':');
  if (now.minute() < 10)
  {
    Serial.print("0");
  }
  Serial.print(now.minute());
  Serial.print(':');
  if (now.second() < 10)
  {
    Serial.print("0");
  }
  Serial.println(now.second());
  Serial.println();
}

Any help would be greatly appreciated!
Cheers,
-fab

Paul_KD7HB · March 15, 2021, 9:35pm

fabelizer:
Today I am working on a Chinese Nano clone. This started out as a quick programming exercise to count loops in a second to practice using the attached RTC. I sorted that out, and decided to add a millis timer to see how far away from a second the code varied. This took a few hours, as I am less than a proficient coder! (hence the practice project ) In any case, my issue for the past few hours has been trying to get the difference in elapsed time to print in the serial monitor and I have been unsuccessful in finding an answerto why I only get a zero, when plainly the difference is ~1000mS. Below is the code I am using.
/*

Demonstrates timing.counting with RTC
seconds field. Since seconds are so long
in microprocessor time, it is imperative
to begin timing at a known point after
the seconds field changes. In this program,
the loop is completed 939 (usually) in one
second on the RTC. This does not account for
data fetch from the RTC, print and could vary in
time to complete the loop.
A millis counter was included as an after
thought, but consumes additional cycles to
calculate and print the values,adding error time.
Currently,
I cannot get a difference in millis to print.
and I am lost in rabbit hole after rabbit hole!
It should be 1000, but I only get 0.
*/

#include "Arduino.h"
#include <math.h>
#include <Wire.h>
#include "RTClib.h"

//pin A4 SDA
//pin A5 SCL

int loopCounter = 0;
int printCounter = 0; //to avoid repeatedly printing time
int sec = 0; //seconds
int lastSec = 0;
int firstSec = 0;
unsigned long startMillis = 0;
unsigned long endMillis = 0;
unsigned long elapsedMillis = 0;

DateTime now;
RTC_DS1307 rtc;

void setup() {
Serial.begin(115200);
rtc.begin();
if (!rtc.begin()) {
Serial.println("Couldn't find RTC");
while (1);
}

Serial.println();
Serial.println("FinishedSetup");
now = rtc.now();
firstSec = now.second();

}//end setup

void loop() {

now = rtc.now();
sec = now.second();

if (sec > firstSec) {
startMillis = millis();
lastSec = sec;
//Serial.println("DEBUG1");
loopCounter++;
if (printCounter < 1) {
Serial.print(startMillis);
Serial.println(" startMillis");
printTime();
printCounter ++;
}
}

if (lastSec == (firstSec + 2)) {
endMillis = millis();
Serial.print(endMillis);
Serial.println(" endMillis");
printTime();
elapsedMillis = endMillis - startMillis;
Serial.print(elapsedMillis);
Serial.println(" elapsedMillis");
Serial.print(loopCounter);
Serial.println(" loops in an RTC second");
while (1);
}
}//end loop

void printTime() {
Serial.println();
if (now.hour() < 10)
{
Serial.print("0");
}
Serial.print(now.hour());
Serial.print(':');
if (now.minute() < 10)
{
Serial.print("0");
}
Serial.print(now.minute());
Serial.print(':');
if (now.second() < 10)
{
Serial.print("0");
}
Serial.println(now.second());
Serial.println();
}




Any help would be greatly appreciated!
Cheers,
-fab

Lets not guess! Print the values of sec and firstSec.
Paul

Idahowalker · March 15, 2021, 10:32pm

unsigned long startMillis = millis();
unsigned long endMillis = millis(); //<<<
unsigned long elapsedMillis = millis();

fabelizer · March 15, 2021, 11:05pm

Idaho:
Thanks, but didn't change anything. The initialization to zero is just as effective.

Paul:
I got prints of the seconds as expected. But this is not part of the problem. The serial output shows the 1st sec as 48, the sec as 49, and ends at 50...as expected. That would change according to the time the program starts, but is only related to the RTC. Not much to do with millis().

In fact, I think this might be a quirk in the print function. It either refuses the unsigned long, or for some reason can't deal with it. Unfortunately, I still have not figured it out. The Arduino reference page show no such restriction, but then there is no UL example either. All references I have found in the forum do not deal with printing, only that the elapsed time is simply an arithmetic subtraction. That part I had already!

I have also tried just using "millis()" in the subraction to eliminate the endMillis variable....no help. (lot's of other things too...too many to mention! Always with the result that the elapsedMillis variable get printed as 0.

I am attaching a printed screen for reference, this is after I returned to the original code posted:

FinishedSetup
754 startMillis

18:03:01

1755 endMillis

18:03:02

0 elapsedMillis
939 loops in an RTC second

Appreciate the input from you guys.
-fab

Idahowalker · March 16, 2021, 12:07am

Have you looked at the values?

Serial.println( endMillis );
Serial.println( startMillis );
elapsedMillis = endMillis - startMillis;
    Serial.print(elapsedMillis);
    Serial.println(" elapsedMillis");
    Serial.print(loopCounter);

?

fabelizer · March 16, 2021, 12:20am

Yes. They are in the monitor screen above?
1755 endMillis

754 startMillis

1001 elapsedMillis....but elapsedMillis prints a 0

Curiously, as all three variables are unsigned longs, it makes no sense to me that elapsed doesn't print properly.

-fab

Erik_Baas · March 16, 2021, 12:37am

if (sec > firstSec){ will be executed more than once, so the value of startMillis will continue to rise. You don't see that in the serial monitor because printCounter has become 1 (one).
Later on, when if (lastSec == (firstSec + 2)){ becomes true, you substract startMillis from endMillis, but since startMillis has become ~~larger than endMillis, the result will be negative. Which is impossible, because it's an unsigned long integer.~~

Add two lines to this code:

  if (lastSec == (firstSec + 2)) {
    endMillis = millis();
    Serial.print(startMillis);        // <= added line 1
    Serial.println(" startMillis");   // <= added line 2
    Serial.print(endMillis);
    Serial.println(" endMillis");

to see if I'm right. I hope so, I didn't check it...

fabelizer · March 16, 2021, 12:46am

Just for giggles I switched the code into a Duemilanove I had on the bench. Same issue.

david_2018 · March 16, 2021, 1:02am

Erik_Baas:
Later on, when if (lastSec == (firstSec + 2)){ becomes true, you substract startMillis from endMillis, but since startMillis has become larger than endMillis, the result will be negative. Which is impossible, because it's an unsigned long integer.

Almost correct, except that startMillis will not be larger than endMillis, but either the same or a bit less, depending on when the interrupt for the millis counter occurs. A 'negative' result on unsigned arithmetic would cause a very large positive number, not 0.

fabelizer · March 16, 2021, 1:33am

Did the add, and THANKS! that appears to be the problem!!

Of course it printed correctly when I captured it, but as you said, it adds to same as other! See....that's why I practice coded today! I never would've noticed!

Thank You Erik and David!

-fab

fabelizer · March 16, 2021, 1:55am

FinishedSetup
82 startMillis

20:44:01

1083 endMillis

20:44:02

1001 elapsedMillis
939 loops in an RTC second

FinishedSetup
731 startMillis

20:44:14

1730 endMillis

20:44:15

999 elapsedMillis
938 loops in an RTC second

FinishedSetup
26 startMillis

20:44:23

1027 endMillis

20:44:24

1001 elapsedMillis
939 loops in an RTC second

FinishedSetup
924 startMillis

20:44:33

1924 endMillis

20:44:34

1000 elapsedMillis
938 loops in an RTC second

/*
 * Demonstrates timing.counting with RTC
 * seconds field. Since seconds are so long
 * in microprocessor time, it is imperative
 * to begin timing at a known point after
 * the seconds field changes. In this program,
 * the loop is completed 939 times. (usually) in one
 * second on the RTC. This does not account for
 * data fetch from the RTC, prints, etc. and could 
 * vary in time to complete the loop.
 * 
 * A millis counter was included as an after
 * thought, but consumes additional cycles to
 * calculate and print the values, increasing error time,
 * but providing a finer grain of execution time.
 * 
 * Thanks to Idahowalker, Erik_Baas, and david_2018
 * for helping me sort out my error.
 */
 
#include "Arduino.h"
#include <math.h>
#include <Wire.h>
#include "RTClib.h"

//pin A4 SDA
//pin A5 SCL

int loopCounter = 0;
int printCounter = 0; //to avoid repeatedly printing time
int sec = 0;  //seconds
int lastSec = 0;
int firstSec = 0;
unsigned long startMillis = 0;
unsigned long endMillis = 0;
unsigned long elapsedMillis = 0;

DateTime now;
RTC_DS1307 rtc;

void setup() {
  Serial.begin(115200);
  rtc.begin();
  if (!rtc.begin()) {
    Serial.println("Couldn't find RTC");
    while (1);
  }
  
  Serial.println();
  Serial.println("FinishedSetup");
  now = rtc.now();
  firstSec = now.second();
  //Serial.println(firstSec);

}//end setup

void loop() {

  now = rtc.now();
  sec = now.second();
  //Serial.println(sec);

  if (sec > firstSec) {
    if(startMillis == 0){
    startMillis = millis();
    }
    lastSec = sec;
    //Serial.println("DEBUG1");
    loopCounter++;
    if (printCounter < 1) {
      Serial.print(startMillis);
      Serial.println(" startMillis");
      printTime();
      printCounter ++;
    }
  }

  if (lastSec == (firstSec + 2)) {
    endMillis = millis();
    //Serial.print(startMillis);        // <= added line 1
    //Serial.println(" startMillis");   // <= added line 2
    Serial.print(endMillis);
    Serial.println(" endMillis");
    printTime();

    elapsedMillis = endMillis - startMillis;
    Serial.print(elapsedMillis);
    Serial.println(" elapsedMillis");
    Serial.print(loopCounter);
    Serial.println(" loops in an RTC second");
    while (1);
  }
}//end loop


void printTime() {
  Serial.println();
  if (now.hour() < 10)
  {
    Serial.print("0");
    
  }
  Serial.print(now.hour());
  Serial.print(':');
  if (now.minute() < 10)
  {
    Serial.print("0");
  }
  Serial.print(now.minute());
  Serial.print(':');
  if (now.second() < 10)
  {
    Serial.print("0");
  }
  Serial.println(now.second());
  Serial.println();
}

Posted patched up code and included screen print with 3 resets for posterity!
Thanks again!
-fab

system · July 14, 2021, 1:56am

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Measure elapsed time from RTC Sensors	2	722	May 6, 2021
Correct millis() with an RTC Programming	21	5790	September 4, 2021
Millis() refuses to count (Arduino NANO) Programming	3	1462	May 5, 2021
trouble using millis() for timing less than 0.5sec Programming	10	3392	May 5, 2021
My Millis is not equal to 1 second (UNO) Programming	8	1956	May 5, 2021

Serial.print 0 from elapsed millis() [SOLVED]

0 elapsedMillis 939 loops in an RTC second

Related topics

0 elapsedMillis
939 loops in an RTC second