Started 23April2015, updated …

Disclaimer: The heading reflects my intital suspect. It turns out it wasn’t. It was the internal buffer of my microcontroller! I’ll still keep the blog note, as it’s an ok lab memo that you might learn from.

I downloaded ExtraPuTTY (www.extraputty.com/, version 0.29) the other day. It’s supposed to be an extension to PuTTY (http://en.wikipedia.org/wiki/PuTTY) and takes over config files from it. I needed time tagging, and I needed 9600 baud. The nice interactive tools we had written were more specialised (like they couldn’t cope with so low speed), so I had to take what I found.

I had got some problems with the timing mechanism of my small controller when I had lots of debug prints (for some reasen I haven’t found out yet) . So I decided to see if I really got one seconds ticks every second, and not every third second.

I had put a breakpoint on the debugger at the value 60. This took 2:48 minutes!

When it had stopped I grabbed ExtraPuTTY’s log. It stopped at 54! I then did Clear Scrollback end Reset Terminal. (All Clear causes an assertion in ldisc.c at line 143 with expression len.) (We run Windows 7 Enterprise at work.)

After some itching for some 17 minutes I though I should let the debugger continue. ExtraPuTTY started to log again, with time stamps according to now. Result: the log text contained the ticks, starting from 55!

Why did it stop at 54 and then continued? Where is the hidden buffer? Why was it only triggered on new data? Has it to do with the newlines? (The prime suspect is the internal buffer in the microcontroller, I am investigating this now. Done: it turned out the the internal print buffer was as large as 16K, and I could see by the debugger that it was filled to full, and that the putChar function looped for a free buffer byte, that got available when the USART took a char off it. But it did enable interrupts in that loop. Case closed!)

Anyhow (since I keep the blog note as a lab memo), here’s the first and last log line with 1 and 54:

[22/04/15 - 15:23:01:224] S:0:1
...
[22/04/15 - 15:25:49:016] S:0:54 #L 5->6

And here’s the first seconds count when I restarted:

[22/04/15 - 15:42:40:563] S:0:55 #L 5->6

But when I tried to recreate this today with less logs, one second was one second and it came to 59 – 100% correct (the debugger stopped before the print of 60):

[23/04/15 - 08:41:22:860] S:0:59

With the to-54-continue-55 sequence I printed out the CSP process synchronous channel communication as well, since «5->6» means that there is some message and synchronization and rescheduling between process 5 and 6. And this adds a lot of lines in the to-54-continue-55 case. When I added these lines again, the result was repeatable: the log started from a lower value.