Odd timing behaviour on Serial

I’m using a BMP to upload and look at the serial port output of this sketch (tested with generic F103T and F103R):

void setup () {
Serial.begin(115200);
Serial.println("[hello]");
}

void loop () {
Serial.println(millis());
delay(1000);
}

what line ending have you set?
could you please try with delay(100)

timing with 1000mS is
seconds +seconds*168 +/-1msec(rounding?)

overhead of the ‘ln’ part of println is 168mS??

stephen

I haven’t set any line endings (can I?).

I should probably clairfy that I only changed the first println to print. So the first line is different, but the rest of the test is the same for both cases, println is used inside the loop and still the timing differs.

With 100 ms loop delay, I get:

[hello] 0
117
234
351
468
585

@jcw
I haven’t set any line endings (can I?).
in the bottom right of the serial monitor window is a line ending drop down selection box

that output looks like count*(100+17)
original output now looks like 10*count*(100 + 17)

so what’s got a ‘do something’ on a 100mS cycle/clock/interrupt?

stephen

Ah, but I’m not using the IDE, I’m using the BMP’s serial bridging.
FWIW, it’s no different with the serial monitor – line mode is set to “Newline”.
Anyway, I don’t see how the receiving / displaying end could affect this.

Puzzling…

Anyway, I don’t see how the receiving / displaying end could affect this.

neither do i

Ah, but I’m not using the IDE, I’m using the BMP’s serial bridging

real BMP or rick kimballs version on a ‘pill’?
i’ve had his outputting to serial monitor from the targets PA9/PA10 pins; if that’s ‘serial bridging’?
maybe i’m thinking of semi-hosting?

so what’s got a ‘do something’ on a 100mS cycle/clock/interrupt?

so what’s got a ‘do something taking 17mSec’ on a 100mSec cycle/clock/interrupt?

stephen

I’m using an “Ugly Board” (Roger’s name for it, I think) from eBay, with Rick’s jc66 firmware.
My unit works well, both SWD and serial bridging (real UART, not semi-hosted).

I think my first question would be a different one: why is the timing different in the loop, with the same code, when the only difference is in setup, a call to print vs println?

what happens with the first print/println removed?
srp

Ah, good point! Back to 0/1001/2002/3003. Add the println in setup, and the extra delays come back.

Nothing going on between setup() and loop(): https://github.com/rogerclarkmelbourne/ … e/main.cpp

Maybe it’s related to USB after all (interrupts?). I’m using latest 100% unmodified checkout of Arduino-STM32.
But the reason I got here at all, was that I can’t get USB serial to appear – my Serial is tied to a USART.
I’ve had USB serial working before, on this same board (it’s a HY-TinySTM103, PA0 is active D+ pull-up).
I’m using F103T, which was copied and tweaked from F103C. But note that same happens if I chose F103R.

The 17% across 100ms and 1000ms periods is a hint. Must be some interrupt eating up processor cycles.
But why the difference in loop() with a one-line change in setup()?

Might be helpful if someone else could reproduce this problem on a USART. Or USB, for that matter.

All I can think of is a code size change, triggering a Heisenbug, causing the USB driver to start firing, perhaps.

oh that’s count*(1000+1)

could you try 100 & 10000 without the setup print/println?
i’m wondering if 10000 will become 10017 ***edit 17% is 1700 doh!

‘bell going ting ting’ is it somehow related to usb serial slow down and/or buffer size problems?

what we have got in the mix is the bmp and it’s code. that it’s using st(?) & opencm3 libs etc maybe there’s something in the system clocks setup and we don’t know enough about the bmp code
srp

jcw wrote:Might be helpful if someone else could reproduce this problem on a USART. Or USB, for that matter.

We can rule out the BMP, IMO. It reports serial from the board to my screen, just like serial monitor in the IDE.
It can’t affect what the target board does, it just passes characters back to me, regardless of time delays.

100 ms, no setup print: 0/100/200/301/401/501/602/702/802/903/1003
10000 ms, no setup print: 0/10006/20014/30021/40028/50035

In a way, it’s plausible: a little overhead per loop.

But then again, it isn’t. The millis() clock is driven from the systick interrupt, I assume.
So even with the µC busy with other interrupts, it shouldn’t be losing time.

Let alone that 17% loss:

10000 ms, with setup println: 0/11674/23348/35023/46697/58371

Thanks, Rick.

Maybe your problem has something to do with your STM32F103T platform port?
Thought so too at first. But the same happens when I build for F103R.

I just tried on an Olimex-P103 board. Same 17% millis() oddity.
Upload via BMP, serial on ext header via FTDI UART.

Gremlins!

@rick – worth asking the question though?
@rick – always worth asking the wrong or silly question though? sometimes they ting
where did you get HY-TinySTM103? aliexpress gives nothing & ebay gives motor parts

what happens with a guarded first pass print/println in loop e.g.

int count =0;

void setup () {
}

void loop () {
if ( count==0) {
Serial.begin(115200);
Serial.println("[hello]");
count=1;
}
Serial.println(millis());
delay(10000);
}


Ok, one part of the puzzle solved – delay() isn’t doing what I expected, it does cycle-eating instead of checking the elapsed time tracked by the systick interrupt: https://github.com/rogerclarkmelbourne/ … pp#L36-L45

What delay() should do, is read out millis(), and then idle loop until N milliseconds have elapsed. Then, it won’t be affected by interrupt activity in the background.

So now remains the question: what is eating up 17% of the µC cycles in one case, and why not in the other?

Edit: here’s the fix – https://github.com/jcw/Arduino_STM32/co … b9d3a4649b
(note that to track down the 17% overhead, you should NOT apply this change)

where did you get HY-TinySTM103?
Heh – http://www.hotmcu.com/stm32f103tb-arm-c … p-222.html

what happens with a guarded first pass print/println in loop e.g.
I still get the 17% extra overhead.

I also moved the begin() to setup, and changed the string println to an int println. No change. Crazy, I know.
This is either something ridiculous staring me right in the face, or a very important bug, yearning to get caught 🙂

I’ll stick to the P103 w/ F103R, to rule out h/w or variant quirks.

Edit – this too has the slowdown:
void setup () {
Serial.begin(115200);
Serial.println("[hello]");
while (1) {
Serial.println(millis());
delay(1000);
}
}

next daft idea, split the delay and in between capture millis() to ints, capture millis() before & after printing all those ints, print that difference as well

srp

I’m not sure as to what that would tell us. The delay / millis anomaly has been resolved.
There’s something eating up 17% of the cycles. Sometimes. Murphy and Heisenberg in one.

I’m going to let this roast for a while. Maybe Oct 31st is not the right day for catching this one.
Will look into why I’m not seeing a USB serial device in my sketches. Maybe it’s related. Who knows?

If you have enabled the usb serial stuff, that is going to chew up cycles that would affect the amount of cpu available to a cycle counting delay loop. I would check in other parts of the code to see if the libmaple code expects to be able to run without the systick timer enabled. Maybe they use it in places that run before the SysTick handler has been initialized?

-rick

[edit1] removed bad code suggestion [/edit1]

Thx. Here’s what I could find about init order: https://github.com/rogerclarkmelbourne/ … pp#L65-L76

Looking through the original libmaple

https://github.com/leaflabs/libmaple/bl … h_time.cpp

It appears that code has been in there from the start. * I was wondering if that was a stm32duino change, and it doesn’t appear it was *

It does appear that some people decided to roll their own:

https://github.com/leaflabs/libmaple/bl … Wire.h#L54

hmm ..

-rick

It does appear that some people decided to roll their own
Not uncommon, even in OSS-land 🙂

That one could call “delay_us()”, which is there for precisely this purpose: a spin loop for very brief delays.

I would only think at Tx buffer overflow.

If you print”[hello]” this is 7 chars long. Plus 2 more line ending chars (\n + \r) makes 9 chars.
If the Tx buffer size is 8 byte, then for the very last line ending char the SW would wait time to free up buffer space for one char.
Does it make sense?

Try to println “hello” (without brackets).

When there’s no println() in setup(), the times are 0/1002/2005/3007.
When the println has even just an empty string as arg, the times are 0/1169/2339/3508.

The reported data use does not change, only the code size, but three println’s without arg are fine, while one println(“”) isn’t, and the former generate more code.

One more datapoint: if I call print iso of println in setup() then I can print large strings without seeing any extra delays. Maybe there’s something special happening with new-line processing?

I’m not too concerned a.t.m. because the sketch does work, it’s just that something starts eating up 17% of the processor cycles for no clear reason, which is definitely cause for concern if we cannot explain it.

Update – note that with PR#131 now merged into the dev branch, the timer will no longer show these delays (but the 17% cycle-eating will continue, I expect). So to investigate this, you should not run from the “development” branch in GitHub.

Update #2 – this appears to be the central code for writing out characters to USB: https://github.com/rogerclarkmelbourne/ … #L107-L136 – It’s non-trivial, but I can’t think of any reason why this would lead to interrupts firing rapidly, or something like that.

Aha!

If I comment out this code: https://github.com/rogerclarkmelbourne/ … #L129-L134 – then everything works as expected, no more slowdowns. That empty while loop may be a hint, though I can’t say I understand why this change works. Maybe sending out 2 chars (\r\n), i.e. the line ending from a println call, matters – in this particular state?

Empty, short, long… everything works. Even sending thousands of characters still works, so I’m not sure what that test does. Maybe the code should be compared with older versions and something got left out or changed accidentally?

My suggestion would be: let’s comment it out and make that change in the development branch.

You could try looking in the leadlabs/libmaple repo.

There were some changes / bug fixes that they applied after we seriously diverged from their code about a year ago.

I did try to manually update any of the code where they did bug fixes, until about April 2015, but I may have missed some fixes.

However I suspect its a bug that no one else spotted.

RogerClark wrote:You could try looking in the leadlabs/libmaple repo.

Thanks

I’ll pull that PR into the development branch when I get time.