Can REPL affect the timing that 'print()'s are delivered to PC?

[mungewell]

I have quiet a complicated project which is counting the frames of a video, well timing along side the video to output a LTC signal which can be recorded to align recording later.

I implement some code where the moment the frame count changed, it is printed.

When the output is recorded on PC (with timestamps applied by grabserial) I am seeing occasional delays in the print - although by all accounts the code has ample 'slack time' to print at the correct time.

[20:46:30.554262 0.032448] 01:00:24.08
[20:46:30.588121 0.033859] 01:00:24.09
[20:46:30.621676 0.033554] 01:00:24.10
[20:46:30.673140 0.051464] 01:00:24.11 <----- delayed by 18ms
[20:46:30.687838 0.014698] 01:00:24.12
[20:46:30.721728 0.033889] 01:00:24.13
[20:46:30.755604 0.033877] 01:00:24.14
[20:46:30.787767 0.032163] 01:00:24.15

I re-implemented a similar script, cut down to try to identify issue. I am seeing similar occasional delays.
pulse_thread.py.txt

[20:20:19.080872 0.033373] ......................... 847 33321
[20:20:19.113946 0.033077] ......................... 848 33344
[20:20:19.155772 0.041827] ........................ 849 33329 <---- delayed by 8ms
[20:20:19.180592 0.024820] ................ 850 33339
[20:20:19.213930 0.033338] ......................... 851 33325
[20:20:19.247594 0.033664] ........................ 852 33332
[20:20:19.280608 0.033015] ......................... 853 33342
[20:20:19.314274 0.033661] ......................... 854 33331

Test code is structured similarly to proper code; One thread manages PIOs, which in turn trigger interrupt. Other thread manages UI, and prints to the 'screen'.

It appears the IRQs happen at the correct time (33ms intervals), and that the main thread has ample 'sleep time' (1ms sleeps per dot + 5ms focused wait) between prints.

Questions:
1). Can I disable REPL function, and still have the print() delivered to PC?
2). Can I force 'threading' never to interrupt a process, except when it actively calls sleep()? I have 2 threads, each should be exclusive to each core - though IRQ needs to run somewhere.
3). Any other suggestions where this delay is coming from?

[mungewell]

The same delays are visible when the test script is run on a UART REPL '.uf2'

If I grep the shorter "0.02" timestamps (right after delay) its pretty clear that this is happening every ~1.2s....

[21:39:01.292554 0.028528] ................... 2685 33331
[21:39:02.458737 0.026832] ................... 2720 33335
[21:39:03.625425 0.027149] ................... 2755 33328
[21:39:04.791713 0.025480] ................... 2790 33333
[21:39:05.958385 0.027098] ................... 2825 33334
[21:39:07.126104 0.028568] .................... 2860 33335
[21:39:08.292646 0.028484] ................... 2895 33331
[21:39:09.458826 0.027050] ................... 2930 33327
[21:39:10.625518 0.025796] ................. 2965 33333
[21:39:11.791739 0.025458] ................. 3000 33335
[21:39:12.959497 0.028242] .................... 3035 33324
[21:39:14.125945 0.027126] .................... 3070 33332
[21:39:15.292666 0.025611] .................. 3105 33335
[21:39:16.458942 0.025608] .................. 3140 33325
[21:39:17.625480 0.025833] .................. 3175 33336
[21:39:18.793094 0.028347] ................... 3210 33318
[21:39:19.959656 0.027173] .................. 3245 33335
[21:39:21.126066 0.028359] ..................... 3280 33336
[21:39:22.292453 0.025743] .................. 3315 33335
[21:39:23.458963 0.025599] .................. 3350 33334
[21:39:24.626718 0.026896] ................... 3385 33329
[21:39:25.793362 0.028654] ................... 3420 33334

[robert-hh]

When a Python script is running, the REPL loop is not active. Actually, the running Python is started by the most recent action of REPL (Read Eval Print Loop). The short delays may result from either garbage collection or reloading code from serial flash into the code cache.

[IHOXOHI]

In this case, If the board is in VCP mode, the part of the serial flash should not appear?

[robert-hh]

Cache misses and cache reload delays are independent from the communication channel for print. But these delays should be shorter than 8ms.

[IHOXOHI]

Thanks.

[mungewell]

The short delays may result from either garbage collection or reloading code from serial flash into the code cache.

@robert-hh Garbage collection, of course.... if I force GC at an appropriate time I only have a handful of deltas larger than +/-3ms in a dataset of 30K frames.

            else:
                if a == "":
                    # Force Garbage collection
                    gc.collect()
                a = a + "."
                utime.sleep(0.001)
                continue

It also looks like USB is working within some discrete time frame. But that's a story for another time.

[IHOXOHI]

Maybe you can try different kinds of boards...
Maybe you can check the stability in the time of each board.
You can use my repository 'IXI' [(https://github.com/IHOXOHI/IXI)] for that.
I'm questionning about the result...