First print to serial is slow in a while loop on nRF52840 possibly REPL only

[kevinjwalters]

I was trying to work out to what degree print() was slowing down some testing I was doing and noticed something else. This is a weird one, it's strangely reproducible. print() normally takes about 1ms but first one from a while loop (REPL only?) takes around 80ms extra:

Adafruit CircuitPython 6.0.0 on 2020-11-16; Adafruit Feather nRF52840 Express with nRF52840
>>>
>>> import time, random
>>> for _ in range(5):
...     t1 = time.monotonic_ns()
...     print("{:f} {:f} {:f} {:f}".format(1.1,2.2,3.3,4.4))
...     t2 = time.monotonic_ns()
...     print((t2-t1)/1e9)
...     time.sleep(random.random())
...
...
...
1.100000 2.200000 3.299999 4.400000
0.00115967
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00112915
>>> while True:
...     t1 = time.monotonic_ns()
...     print("{:f} {:f} {:f} {:f}".format(1.1,2.2,3.3,4.4))
...     t2 = time.monotonic_ns()
...     print((t2-t1)/1e9)
...     time.sleep(random.random())
...
...
...
1.100000 2.200000 3.299999 4.400000
0.0845031
1.100000 2.200000 3.299999 4.400000
0.00109863
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00112915
Traceback (most recent call last):
  File "<stdin>", line 6, in <module>
KeyboardInterrupt:
>>> for _ in range(5):
...     t1 = time.monotonic_ns()
...     print("{:f} {:f} {:f} {:f}".format(1.1,2.2,3.3,4.4))
...     t2 = time.monotonic_ns()
...     print((t2-t1)/1e9)
...     time.sleep(random.random())
...
...
...
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00109863
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00109863
>>> while True:
...     t1 = time.monotonic_ns()
...     print("{:f} {:f} {:f} {:f}".format(1.1,2.2,3.3,4.4))
...     t2 = time.monotonic_ns()
...     print((t2-t1)/1e9)
...     time.sleep(random.random())
...
...
...
1.100000 2.200000 3.299999 4.400000
0.0811462
1.100000 2.200000 3.299999 4.400000
0.00112915
1.100000 2.200000 3.299999 4.400000
0.00109863
1.100000 2.200000 3.299999 4.400000
0.00112915
Traceback (most recent call last):
  File "<stdin>", line 6, in <module>
KeyboardInterrupt:

Feather nRF52840 Express running 6.0.0 with a Windows 8.1 desktop.

I'm not saying this is half duplex but perhaps there's some sort of flow-control-like thing here between hitting return on REPL and the while loop executing quicker than the for loop sending data in the other direction? Tiny chance it's time.monotonic_ns misbehaving.