Probable bug with scalene when profiling async code

[dheerajck]

Python 3.11.6 Scalene version 1.5.38 (2024.03.24)

Profiled values arent in the correct place

To reproduce run this scalene --cpu-percent-threshold 0 async_await.py --cli and press Control + C after 3 seconds from when program prints "Task 1 done"

#  async_await.py
import asyncio

async def task():
    print('Task 1')
    await asyncio.sleep(5)
    a = 1
    a = a * 100
    print('Task 1 done')

async def gather():
    print('Gather 1')
    asyncio.create_task(task())
    print('Gather 1 done')

async def main():
    await asyncio.gather(gather())
    while True:
        await asyncio.sleep(1)

    print('Main done')

if __name__ == '__main__':
    try:
        asyncio.run(main())
    except KeyboardInterrupt:
        pass

output

/home/dheeraj/playground/profiler_test/async_await.py: % of time = 100.00% (5.009s) out of 5.009s.                                                       
       ╷       ╷       ╷       ╷        ╷       ╷               ╷       ╷                                                                                                                                       
       │Time   │–––––– │–––––– │Memory  │–––––– │–––––––––––    │Copy   │                                                                                                                                       
  Line │Python │native │system │Python  │peak   │timeline/%     │(MB/s) │/home/dheeraj/playground/profiler_test/async_await.py                                                                                  
╺━━━━━━┿━━━━━━━┿━━━━━━━┿━━━━━━━┿━━━━━━━━┿━━━━━━━┿━━━━━━━━━━━━━━━┿━━━━━━━┿━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━╸
     1 │       │       │       │        │       │               │       │import asyncio                                                                                                                         
     2 │       │       │       │        │       │               │       │                                                                                                                                       
     3 │       │       │       │        │       │               │       │                                                                                                                                       
     4 │       │       │       │        │       │               │       │async def task():                                                                                                                      
     5 │       │       │       │        │       │               │       │    print('Task 1')                                                                                                                    
     6 │       │       │  [1]  │        │       │               │       │    await asyncio.sleep(5)                                                                                                             
     7 │       │       │       │        │       │               │       │    a = 1                                                                                                                              
     8 │  [2]  |       |       │        │       │               │       │    a = a + 1                                                                                                                          
     9 │       │       │       │        │       │               │       │    print('Task 1 done')                                                                                                               
    10 │       │       │       │        │       │               │       │    exit(0)                                                                                                                            
    11 │       │       │       │        │       │               │       │                                                                                                                                       
    12 │       │       │       │        │       │               │       │                                                                                                                                       
    13 │       │       │       │        │       │               │       │async def gather():                                                                                                                    
    14 │       │       │       │        │       │               │       │    print('Gather 1')                                                                                                                  
    15 │       │       │       │        │       │               │       │    asyncio.create_task(task())                                                                                                        
    16 │       │       │       │        │       │               │       │    print('Gather 1 done')                                                                                                             
    17 │       │       │       │        │       │               │       │                                                                                                                                       
    18 │       │       │       │        │       │               │       │                                                                                                                                       
    19 │       │       │       │        │       │               │       │async def main():                                                                                                                      
    20 │       │       │       │        │       │               │       │    await asyncio.gather(gather())                                                                                                     
    21 │       │       │       │        │       │               │       │    while True:                                                                                                                        
    22 │       │       │       │        │       │               │       │        await asyncio.sleep(1)                                                                                                         
    23 │       │       │       │        │       │               │       │                                                                                                                                       
    24 │       │       │       │        │       │               │       │    print('Main done')                                                                                                                 
    25 │       │       │       │        │       │               │       │                                                                                                                                       
    26 │       │       │       │        │       │               │       │                                                                                                                                       
    27 │       │       │       │        │       │               │       │if __name__ == '__main__':                                                                                                             
    28 │    1% │       │  99%  │        │       │               │       │    asyncio.run(main())    

I would expect some numbers at [1] and [2] is this the intended behaviour when profiling async code with async tasks or is it a bug

[dheerajck]

[emeryberger]

I made a minor modification to your code: it now actually does some modicum of computation, and it exits on its own without having to press Ctrl-C.

#  async_await.py
import asyncio

def do_something():
    a = 1
    for i in range(100_000):
        a = a * 2

async def task():
    print('Task 1')
    do_something()
    await asyncio.sleep(5)
    print('Task 1 done')

async def gather():
    print('Gather 1')
    asyncio.create_task(task())
    print('Gather 1 done')

async def main():
    await asyncio.gather(gather())
    countdown_timer = 3
    while countdown_timer > 0:
        print(f"{countdown_timer}...")
        await asyncio.sleep(1)
        countdown_timer -= 1

    print('Main done')

if __name__ == '__main__':
    try:
        asyncio.run(main())
    except KeyboardInterrupt:
        pass

When I run it as follows:

python3 -m scalene --cli --cpu test-async.py --reduced-profile

I get the expected results (CPU time for the line doing computation and sleep time for the line waiting):