micropython/aioprof: Add a simple profiler for asyncio applications.

[andrewleech]

Often when creating asyncio micropython applications that are growing in size, I get to a point where things start to run a bit sluggish and it can be hard to find which functions are the main culprit for the slowdown.

This tool is intended to help here.

It injects a hook / wrapper into asyncio to track timing in ticks/ms before and after each coroutine run. This is accululated and can be reported on to show the number of times each function has been called and the total accumulated time in ms.

I'm sure these hooks will add a considerable performance hit / overhead to the application but it should be generally relative and still help to identify "bad" functions that are taking too much real time to run, or being run way too frequently.

~/micropython-lib/micropython/aioprof$ micropython example_aioprof.py
┌──────────────────────────────────────────────┬───────┬─────┐
│ function name                                │ count │ ms  │
├──────────────────────────────────────────────┼───────┼─────┤
│ <generator object 'slow' at 7f33b8ea64c0>    │ 5     │ 400 │
│ <generator object 'quicker' at 7f33b8ea6680> │ 5     │ 5   │
│ <generator object 'main' at 7f33b8ea5ca0>    │ 1     │ 0   │
└──────────────────────────────────────────────┴───────┴─────┘

[peterhinch]

This is impressive! Very useful.

I ran this against one of the micro-gui demos; with no evident drop in responsiveness. My only comment is that if you have many instances of an object, each of which runs a bound task (say ._go), the report shows a line for each instance of ._go. There is no means of figuring out which object is hogging resources. I guess this is inevitable.

[andrewleech]

Yeah I've thought it might be possible to label instances of a function perhaps with a decorator (provided by aioprof) that would handle creating the Task object / Coro with added extra label from either a decorator arg or the function args.

[peterhinch]

I'm not sure that would fix this. I encountered this in micropython-monitor.

Consider a class whose __init__() launches a task. An application creates instances of this class (and probably lets some go out of scope). The report lists each unique instance of the task which has run. You spot a misbehaving instance and need to trace back to the code that instantiated one particular object. It's not clear to me how you can do this without unpleasant hacking of the application.

[ned-pcs]

Very useful! However, when trying this on my app, I got this exception (I have fixed some line numbers in the traceback):

7.468 [app_main] [ERROR] Traceback (most recent call last):
  File "app/app_main.py", line 102, in run
  File "asyncio/core.py", line 1, in run
  File "asyncio/core.py", line 1, in run_until_complete
  File "asyncio/core.py", line 1, in run_until_complete
  File "app/aioprof.py", line 79, in send
  File "app/app_main.py", line 90, in main
  File "asyncio/funcs.py", line 89, in gather
  File "asyncio/funcs.py", line 89, in <listcomp>
  File "asyncio/core.py", line 139, in _promote_to_task
TypeError: issubclass() arg 2 must be a class or a tuple of classes

asyncio._promote_to_task() looks like this:

# Ensure the awaitable is a task
def _promote_to_task(aw):
    return aw if isinstance(aw, Task) else create_task(aw)

_promote_to_task() is also called from asyncio.wait_for() and run_until_complete().

But the problem is that asyncio.Task is now a function, having been replaced in aioprof.py.

Can you make this work with asyncio.gather(), asyncio.run_until_complete() and asyncio.wait_for()?

[andrewleech]

Oh interesting, I wasn't aware of that limitation! I'm not sure if it never worked, or if something has changed in asyncio since... regardless it'd be good to get fixed.

I think my gitlab copy has probably been updated a bit since this PR was raised, but doubt the issue is fixed there either: https://gitlab.com/alelec/aioprof

To be honest I've got a lot going on lately so don't know when I'll get time to fix this sorry!

[ned-pcs]

Actually, your latest does look like it works with the other asyncio methods since it doesn't re-define Task. I just tried it with my code and it's working.

[andrewleech]

Oh fantastic, I should update this PR then :-) hope it helps you either way!