Delay function broken?

Question

I noticed timing inconsistencies in my project, and further debugging pinpointed it to the problem below. The text should be updating every second, but the returned values are >> 1000ms.

To clarify, the text is not showing up every second. The delays between texts vary according to fluctuating start and finish values.

I'm using a Teensy 3.2. Changing the baud rate doesn't help.

Is my timing crystal busted? Is there a serial buffering issue? I don't know how to fix either of these.

Any help would be appreciated!

Edit:

Here's the code if anyone wants to test. I found that adding more delay functions screws the output up in completely unlinear ways.

unsigned long start, finished, elapsed;

void setup() {
  Serial.begin(115200);
}

void loop() {
  Serial.println("Start...");
  start = millis();
  Serial.println(start);
  delay(1000);
  finished = millis();
  Serial.println(finished);
  Serial.println("Finished");
  elapsed = finished - start;
  Serial.print(elapsed);
  Serial.println(" milliseconds elapsed");
  Serial.println();
}

Edit #2:

I thought it was worth showing everyone this screenshot. It looks like delay(1000) just isn't functioning at all.

Edit #3:

I debugged it with an LED and it blinked at exactly 1s intervals. It seems like delay(1000) works, so the problem must be related to the serial buffering. I also updated my software but that didn't help.

Edit #4:

New developments from further debugging:

• The problem is not reproducible on a different computer. The Arduino serial monitor on other computers displays correctly.
• Updating to the latest OSX, arduino IDE, and teensyduino did not help.
• Terminal 'screen' command surprisingly prints correct serial communication.
• Serial monitors from 3rd party apps, like CoolTerm and Arduino IDE do not work.

Answer 1

After correcting the syntax error (missing semicolon) I tried your code on my Teensy 3.0. The results look OK to me:

Start...
1250
2250
Finished
1000 milliseconds elapsed

Start...
2250
3250
Finished
1000 milliseconds elapsed

Start...
3250
4250
Finished
1000 milliseconds elapsed

Start...
4250
5250
Finished
1000 milliseconds elapsed

Start...
5250
6250
Finished
1000 milliseconds elapsed

Start...
6250
7250
Finished
1000 milliseconds elapsed

Start...
7250
8250
Finished
1000 milliseconds elapsed

Start...
8250
9250
Finished
1000 milliseconds elapsed

---

Since the code you posted doesn't compile, can you re-test please with your posted code, assuming you add in the semicolon, and put a space before "milliseconds elapsed".

---

Further down my test I see this:

Start...
153258
154258
Finished
1000 milliseconds elapsed

Start...
154259
155259
Finished
1000 milliseconds elapsed

Start...
155259
156259
Finished
1000 milliseconds elapsed

Now are you talking about the "creep" in the start time? That doesn't totally surprise me, because the rest of the code must take some time to execute.

---

I know this isn't an "answer" per se, but I can't post this much information into a comment.

Answer 2

Since the subtraction's result (finished - start) displays alright, it means the right number is being stored in the variable, so it's Serial that is screwing up the task of printing it. Try reducing the baud rate to 9600 and try again.