[SOLVED] uasyncio thread safe flag re-entry issue

[oclyke]

I've noticed unexpected behavior (at least to me that is) with which I could really use help from the experts.

(note: not an overflow but I don't know how else to succinctly describe whatever is happening here...)

My goal is to use a uasyncio.ThreadSafeFlag object to limit the rate at which an output task runs. The output task may have a variable workload and so when that load is small I'd like to give CPU time to other processes, but when that load is high I expect the output task to complete its own processing and then (per uasyncio design) allow other coroutines to be run before coming back.

It took me quite a lot of paring down and hypothesizing to boil the issue down from my full application to this demo code:

Code: Select all

import uasyncio
import time
from machine import Timer

timer_id = 0 # edit to suit your platform

stats = {}
def start_stat(tag):
  now = time.ticks_us()
  try:
    s = stats[tag]
    s['start'] = now
    s['stop'] = None
    s['updated'] = now
  except KeyError:
    stats[tag] = {'start': now, 'updated': now, 'history': [], 'avg': None}

def stop_stat(tag):
  now = time.ticks_us()
  s = stats[tag]
  s['updated'] = now
  elapsed = now - s['start']
  hist = s['history']
  hist.append(elapsed)
  if len(hist) > 10:
    hist = hist[-10:]
  s['history'] = hist
  s['avg'] = sum(hist) / len(hist)

async def print_stats_task():
  while True:
    await uasyncio.sleep_ms(1000)
    now = time.ticks_us()
    for tag, s in stats.items():
      print('\t', tag, 'avg (ms):', s['avg']/1000, 'age (s):', (now-s['updated'])/1000000)
    print('\n')

async def output_task():
  timer = Timer(timer_id)
  timer_flag = uasyncio.ThreadSafeFlag()
  timer_period_ms = 30

  load_period_ms = timer_period_ms - 1 # this works reliably on esp32
  # load_period_ms = timer_period_ms # fails, likely same mode as longer delays but due to overhead
  # load_period_ms = timer_period_ms + 1 # seems to always fail

  def timer_cb(self):
    timer_flag.set()

  timer.init(period=timer_period_ms, callback=timer_cb)
  while True:
    start_stat('t_total')
    start_stat('t_timer')
    await timer_flag.wait()
    stop_stat('t_timer')

    start_stat(' t_load')
    time.sleep_ms(load_period_ms)
    stop_stat(' t_load')
    stop_stat('t_total')

loop = uasyncio.get_event_loop()
loop.create_task(print_stats_task())
loop.create_task(output_task())

loop.run_forever()

The concept is that a hardware timer callback is used to set the thread safe flag which will then allow the output coroutine to continue. In the program a blocking process is simulated using time.sleep_ms. When the processing step takes less time than the timer period all is well - the statistic printing task runs as well as the output task. However when the processing step is near, equal, or greater than the timer period all program execution appears to stop.

This was tested on ESP32 with timer 0

I'm truly at a loss... Is this expected behavior for uasyncio? If so it feels very surprising. If not then this seems like a bug - the proper behavior would be for the flag to be set (perhaps multiple times while processing is occurring) and then for it to be unset the next time around.

Thanks for looking!

[pythoncoder]

I can replicate this behaviour on a Pyboard, however the cause is not as you describe. I changed

Code: Select all

load_period_ms = timer_period_ms + 1

so that it failed and inserted the following code

Code: Select all

    print('about to wait')
    await timer_flag.wait()
    print('done')

The outcome was as follows

Code: Select all

MPY: soft reboot
MicroPython v1.17-75-ge9d71ffb0-dirty on 2021-10-08; PYBv1.1 with STM32F405RG
Type "help()" for more information.
>>> import rats104
about to wait
done
about to wait
done
about to wait
done
about to wait
done  # forever

so the ThreadSafeFlag is behaving correctly. If you look at the source you will see that it really can't fail in the way you suggest.

The bug is that your loop locks up the scheduler because, in the case where the ThreadSafeFlag is already set, the loop never yields to the scheduler. It is fixed with:

Code: Select all

  while True:
    start_stat('t_total')
    start_stat('t_timer')
    await timer_flag.wait()
    stop_stat('t_timer')

    start_stat(' t_load')
    time.sleep_ms(load_period_ms)
    stop_stat(' t_load')
    stop_stat('t_total')
    await uasyncio.sleep_ms(0)  # Give other tasks a chance

Incidentally explicit event loop code is no longer required. See my uasyncio tutorial.

[oclyke]

Aha! This is obvious now that you mention it. Thanks a ton!
Also glad to see your tutorial - I've heard it mentioned a lot but never seem to have found the source.