_threading: processing resources very unevenly distributed

[rkompass]

In testing how an idle loop (waiting for a flag) in a thread impairs the other threads performance I observed that as long as there is only one other thread it almost doesn't.
But with 3 threads is does (~50%) and the other two threads are very unevenly distributed.
Also with 2 or 3 identical computing threads the resources are very unevenly distributed, so that the first and third thread get ~49 % and the second only 1% !

Perhaps this is a bug? Should I raise an issue?

The following ran on an esp32:

import _thread
import time

flag = False
ret = [0, 0, 0]

def th_spin(i):
    while not flag:
        pass
    while flag:
        pass

def th_perf(i):
    global ret
    while not flag:
        pass
    n = 0
    while flag:
        n +=1
    ret[i] = n

def th_func(i):
    while not flag:
        pass
    while flag:
        time.sleep(2)
        print('Running thread %d' % i)

# _thread.start_new_thread(th_spin, (1,))
_thread.start_new_thread(th_perf, (0,))
_thread.start_new_thread(th_perf, (1,))
_thread.start_new_thread(th_perf, (2,))
# _thread.start_new_thread(th_func, (3,))
flag = True
time.sleep(10)
flag = False
time.sleep_ms(50)
print('Thread performance: {:d} {:d} {:d} iterations'.format(ret[0], ret[1], ret[2]))

Result:
Thread performance: 1804861 30301 1567005 iterations.

[robert-hh]

I usually avoid loops like:

    while not flag:
        pass

Instead I use:

    while not flag:
        idle()

[rkompass]

As expected, machine.idle() prevents the consumption of the resources in the idling thread. Thank you.
It has no influence on the uneven distribution, however.

[jimmo]

@rkompass The ESP32 / IDF scheduler's interval is in the order of 20ms. I think you'll need to run the test for much longer to see a more even distribution.

[rkompass]

It ran 10s, this is 500 times 20 ms.
Just now repeated with 100s, i.e. 5000 time slices:
Thread performance: 333149 16199133 17151709 iterations
The first thread this time gets only about 1 % of computation time, others ~ 50 %.

[rkompass]

Perhaps related: I found that ticks_us() is not threadsafe. Using it in threads even crashed the program sometimes. A search on this did not lead to anything so maybe this is not known yet?
Demonstration:

import _thread
from time import ticks_us, ticks_diff, sleep, sleep_ms
from machine import idle

def th_tims(i):
    global rmin, rmax
    while not flag:
        idle()
    tmin = 1_000_000; tmax = 0
    # lock.acquire()
    t0 = ticks_us()
    t1 = ticks_us()          # try to make this not the minimum
    # lock.release()
    td = ticks_diff(t1, t0)  #  .. so put some computation here
    t1 = min(td, tmin)
    t1 = max(td, tmin)
    t1 = min(td, tmin)
    t1 = max(td, tmin)
    while flag:
        # lock.acquire()
        t1 = ticks_us()    # get weird results without the lock (4, 5, 10 seconds for max) 
        # lock.release()
        td = ticks_diff(t1, t0)
        tmin = min(td, tmin)
        tmax = max(td, tmax)
        t0 = t1
    rmin[i] = tmin
    rmax[i] = tmax

_thread.start_new_thread(th_tims, (0,))
_thread.start_new_thread(th_tims, (1,))
# _thread.start_new_thread(th_tims, (2,))
# _thread.start_new_thread(th_tims, (3,))
# _thread.start_new_thread(th_tims, (4,))

flag = True
sleep(10)
flag = False
sleep_ms(50)
print('Threads tmin: {:d} {:d} {:d} us'.format(rmin[0], rmin[1], rmin[2]))
print('Threads tmax: {:d} {:d} {:d} us'.format(rmax[0], rmax[1], rmax[2]))

leads to:

Threads tmin: 22 22 0 us
Threads tmax: 9980096 10101 0 us

So this indicates that thread 1 had a break of about 9.9 seconds!! Was it only active in the beginning and the end of the 10s total duration?
With lock.acquire() and lock.release() uncommented the above program leads to more reasonable

Threads tmin: 42 42 0 us
Threads tmax: 140057 220088 0 us

which would mean the longest interval between time slices is > 130 ms.
Now this is not just a reproduction to prove that ticks_us() is not threadsafe. I had it and changed the code afterwards unfortunately, will try to reproduce the crash if you are interested.

But my point, if you are still reading this @jimmo : Could it be that the threads are scheduled by some variant of ticks_us() (in C of course) and the threading itself disturbes this function (impairs the carry over with timer interrupt for example)?

[rkompass]

An addition: All this irregularity only is observed on ESP32.
With MP Unix and on the pyboard I see equally distributed computation time and similar regular time slices.
Example output on pyboard:

Threads tmin: 21 21 0 0 0 us
Threads tmax: 735 742 0 0 0 us

with 2 threads, or

Threads tmin: 21 21 21 0 0 us
Threads tmax: 1434 1434 1434 0 0 us

or

Threads tmin: 21 21 21 21 0 us
Threads tmax: 2125 2125 2125 2127 0 us

if 4 threads run in parallel, which tells us that precisely every 705-720 us the threads are switched.
Similar behaviour with unix port.
I have to conclude that the ESP32 port has a bug.
It might be difficult to locate it. I tried but gave up to find the piece of source code (in IDF) that does the thread switching.

[PythonKai]

Hello rkompass,
thanks for the post. I tried similar experiments; with following results (I used your code):

import _thread
import time
from machine import freq

freq(240_000_000)

flag = False
ret = [0, 0, 0]

def th_perf(i):
    global ret
    while not flag:
        pass
    n = 0
    while flag:
        n +=1
        time.sleep_ms(0)
    ret[i] = n

_thread.start_new_thread(th_perf, (2,))
_thread.start_new_thread(th_perf, (0,))
_thread.start_new_thread(th_perf, (1,))

flag = True
time.sleep(1)
flag = False
time.sleep_ms(50)
print('Thread performance: {:d} {:d} {:d} iterations'.format(ret[0], ret[1], ret[2]))

result: Thread performance: 24969 24968 24965 iterations

Thread distribution seems to be equal. Ok the performance is worse. I guess the IDF scheduler needs a little bit time to run all the threads, with eaqual time slots, however, I have no idea why.
Maybe it helps to figure out ? And somebody understands the mechanism ?
As you mentioned, the sleep_us command has also a problem with threads.
By using this command the program crashes.

[rkompass]

This is a good result. The problem is: The scheduling should always be about fair, which is not the case.
If you only observe fair results, even with just 2 threads then we could try to find out what factors lead to irregularities in my test runs (specifics of the board, IDF, MP versions..).
Although I raised an issue on this I think it is a problem with FreeRTOS / IDF, so from the MP side it probably cannot be mended.
If anyone is experienced in programming the ESP32 under FreeRTOS and interested in this topic then similar tests could be devised for that platform. In the best scenario one would be able to document the problems and report there. I decided not to invest more energy into this.