scalene
scalene copied to clipboard
Published
20 hours ago •
plasma-umass
plasma-umass
Probable bug with scalene when profiling async code
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
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):
