microSecond timing discrepancy

[Turgut Guneysu]

Hi John,

As I was working on a UART project code, I encountered some transmission errors and started looking at instruction timings to see where I was taking too much time. I wrote a simple microsecond timing routine and started timing. And I noticed this strange result:

Following sample block code execution time starts at 236 uSecs and for each Click of the block keeps going up in 6 or 7 uSec increments, all the way up to 1465 uSec and then starts over again from 236 uSec.

Since everything is initialized, I was expecting some minimal drift, but not this much !

Is this a bug or some internal error in timing or what?

Thanks, Turgut

[John Maloney]

Adding a new element to a list takes a variable amount of time depending on whether the list needs to grow. If it does need to grow, the cost depends on how many elements it already has in it (since they need to get copied into a larger piece of memory) and whether MicroBlocks needs to reclaim and compact memory to make room.

To avoid that uncertainty in time-critical operations, you can pre-allocate a list of the maximum size, then clear it:

Now you can add up to the preallocated number of elements and each add operation will take a consistent, small amount of time (e.g. 46 usecs each on a BBC micro:bit).

[Turgut Guneysu]

I'm totally with you on the list op overhead. However, the list is initialized to a blank one in the beginning of each cycle.

I can definitely take advantage of the prealloc trick. But still have hard time understanding the incremental increase of the same block of ops from 236uSec up to about 1.5ms and then revert back to initial exec time. Rinse and repeat!

I don't know if you actually tried it but keep clicking the block and look at the timings sequence.

I tried this with other instruction sequences as well and I got similar results there too. However I did not have the time to analyze the types of instruction seqs exhibiting this behaviour.

If you think it is what you said it is, I'll leave it at that for now and work with prealloc.

Thx

[John Maloney]

Agreed, an incremental increase by 6-7 usecs each time is strange. I didn’t see that in my tests on a BBC micro:bit. What microcontroller are you testing on?

The ESP8266 and ESP32 have a complex memory architecture that might have some unexpected performance characteristics. Even there, what you’re reporting would be surprising. There could be an issue the the microsecond clock itself, I suppose.

[Turgut Guneysu]

I am using micro:bit version 1.5. I have two. Both exhibit the same pattern.

By the way, Merry Xmas to you and microBlocks. Thanks again for making this environment possible for us the consuming crowd ! Learned a lot from you and the platform while trying to contribute in my own little way.

Brads, Turgut

Get Outlook for Androidhttps://aka.ms/ghei36

[John Maloney]

I’ve reproduced this on a micro:bit. (I hadn’t copied your exact program before – my bad!) It’s not a bug, it’s the cost of growing the empty list to have room for the new element. Doing that involves not only allocating a larger chunk of memory, but scanning all the objects in memory to update any pointers to the old list to point to the newly allocated one. As memory fills up with garbage objects, that takes a few more microseconds each time. Eventually the garbage collector runs, cleans up all the old lists, and it goes back to the original speed. In short, this isn’t a bug, although it did puzzle me at first.

As mentioned, pre-allocating a list of the expected maximum size (and clearing it with “delete item ‘all’ of list _”) will avoid the cost of incrementally growing the list, resulting in the same time for adding each new element.