sys.settrace and perfetto tool

C programming, build, interpreter/VM.
Target audience: MicroPython Developers.
Post Reply
jgpeiro
Posts: 7
Joined: Wed Aug 05, 2015 8:27 am

sys.settrace and perfetto tool

Post by jgpeiro » Tue Mar 23, 2021 10:04 am

Recently I discover sys.settreace functionality and it is really amazing.
I also using an android trace visualization https://ui.perfetto.dev/#!/ that takes a json data like {"name":foo, "time start":0.1, "duration":0.4} and generates a cool interactive visualizations.
It is easy generate such data from trace events, but my problem appears with asyncio programs.

Does anyone know how to use traces to calculate task_A/B running time?

Code: Select all


import time
import sys  # Build mpy with MICROPY_PY_SYS_SETTRACE 1 to enable sys.settrace feature
import uasyncio as asyncio

def _print( *kw ): # built in print wrapper to allow trace
    print( *kw )

async def task_A():
    _print( "A", "Hello" )
    await asyncio.sleep( 0.4 )
    _print( "A", "World" )

async def task_B():
    _print( "B", "Hello" )
    await asyncio.sleep( 0.1 )
    _print( "B", "World" )

async def main():
    asyncio.create_task( task_A() )
    asyncio.create_task( task_B() )
    await asyncio.sleep( 0.5 )

def trace_tick_handler( frame, event, arg ):
    global t0, traces
    
    if( event != "line" ):
        t = time.ticks_us()-t0
    
        func_name = frame.f_code.co_name
        func_line_no = frame.f_lineno
        func_filename = frame.f_code.co_filename
        
        caller = frame.f_back
        caller_line_no = caller.f_lineno
        caller_filename = caller.f_code.co_filename
        
        traces += [(t, (func_name, func_line_no, func_filename, caller_line_no, caller_filename), event, arg)]

    return trace_tick_handler

print( "done" )

traces = []
t0 = time.ticks_us()

print( "Enable traces")
sys.settrace( trace_tick_handler )

asyncio.run( main() )
asyncio.new_event_loop()

sys.settrace( None )
print( "Disable traces" )

print( "len( traces )", len( traces ) )
print( "done" )

for i, trace in enumerate( traces ):
    print( i, trace )
I tried this:

Code: Select all

text_start = """{
    "displayTimeUnit": "ns",
    "traceEvents": [ 
        {"args": {"name": "MainProcess"},"name": "process_name","ph": "M","pid": 1111,"tid": 1111},
        {"args": {"name": "MainThread"},"name": "thread_name","ph": "M","pid": 1111,"tid": 2222},"""

text_end = """    ]
}
"""

event_template = {
    "caller_lineno": 1,
    "cat": "FEE",
    "dur": 1,
    "name": "foo (C:\\program.py:1)",
    "ph": "X",
    "pid": 1111,
    "tid": 2222,
    "ts": 1
}
print( text_start )

ts = []
caller_lineno = []
name = []
for trace in traces:
    t, frame, event, arg = trace
    func_name, func_line_no, func_filename, caller_line_no, caller_filename = frame
    
    if( event == "call" ):
        ts += [t]
        
    if( event == "return" ):
        event = dict( event_template )
                
        event["caller_lineno"] = caller_line_no
        event["name"] = func_name + " " + "(" + func_filename + ":" + str( func_line_no ) + ")"
        event["ts"] = ts.pop()
        event["dur"] = t - event["ts"]
        
        print( "        " + str( event ).replace( "'","\"" ), end="" )
        if( trace != traces[-1] ):
            print( "," )
        else:
            print( "" )
    
print( text_end )

witch generates json data that can be loaded in perfetto and looks like:
Image

But still is wrong.
How can I interpret asyncio __iter__/__next__/wait_io_event call/return/exception as different threads?

Note: If you dont need asyncio, enable traces and visualize with perfetto its amazing to visualize how ur micropython program execution!

Post Reply