profiler.output_text: float division by zero
Opened this issue · 1 comments
antoineqian commented
Hi I use this middleware for my fastapi app
@app.middleware("http")
async def profile_request(request: Request, call_next: Callable):
with Profiler(interval=0.001, async_mode="enabled") as profiler:
response = await call_next(request)
logger.warning(profiler.output_text())
return response
However, I get this error when testing an endpoint. The error only happens for this endpoint, and I don't understand why
+ Exception Group Traceback (most recent call last):
| File "/home/runner/work/match-making/match-making/tests/local/integration/matching_scenarios/****.py", line 71, in test_***
| navigate = await client_test.post(
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_client.py", line 1848, in post
| return await self.request(
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_client.py", line 1530, in request
| return await self.send(request, auth=auth, follow_redirects=follow_redirects)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_client.py", line 1617, in send
| response = await self._send_handling_auth(
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_client.py", line 1645, in _send_handling_auth
| response = await self._send_handling_redirects(
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_client.py", line 1682, in _send_handling_redirects
| response = await self._send_single_request(request)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_client.py", line 1719, in _send_single_request
| response = await transport.handle_async_request(request)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/httpx/_transports/asgi.py", line 162, in handle_async_request
| await self.app(scope, receive, send)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/fastapi/applications.py", line 276, in __call__
| await super().__call__(scope, receive, send)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/applications.py", line 122, in __call__
| await self.middleware_stack(scope, receive, send)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/errors.py", line 184, in __call__
| raise exc
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/errors.py", line 162, in __call__
| await self.app(scope, receive, _send)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 106, in __call__
| async with anyio.create_task_group() as task_group:
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
| raise BaseExceptionGroup(
| exceptiongroup.ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
+-+---------------- 1 ----------------
| Traceback (most recent call last):
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/anyio/streams/memory.py", line 97, in receive
| return self.receive_nowait()
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/anyio/streams/memory.py", line 92, in receive_nowait
| raise WouldBlock
| anyio.WouldBlock
|
| During handling of the above exception, another exception occurred:
|
| Traceback (most recent call last):
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 78, in call_next
| message = await recv_stream.receive()
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/anyio/streams/memory.py", line 112, in receive
| raise EndOfStream
| anyio.EndOfStream
|
| During handling of the above exception, another exception occurred:
|
| Exception Group Traceback (most recent call last):
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 108, in __call__
| response = await self.dispatch_func(request, call_next)
| File "/home/runner/work/match-making/match-making/src/main.py", line 137, in time_request
| response = await call_next(request)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 84, in call_next
| raise app_exc
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 70, in coro
| await self.app(scope, receive_or_disconnect, send_no_error)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 106, in __call__
| async with anyio.create_task_group() as task_group:
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
| raise BaseExceptionGroup(
| exceptiongroup.ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
+-+---------------- 1 ----------------
| Traceback (most recent call last):
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/starlette/middleware/base.py", line 108, in __call__
| response = await self.dispatch_func(request, call_next)
| File "/home/runner/work/match-making/match-making/src/main.py", line 130, in profile_request
| logger.warning(profiler.output_text())
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/profiler.py", line 297, in output_text
| return self.output(
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/profiler.py", line 337, in output
| return renderer.render(session)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/renderers/console.py", line 63, in render
| result += self.render_frame(self.root_frame)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/renderers/console.py", line 97, in render_frame
| result = f"***indent***self.frame_description(frame)***\n"
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/renderers/console.py", line 167, in frame_description
| time_color = self._ansi_color_for_time(time)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/renderers/console.py", line 192, in _ansi_color_for_time
| proportion_of_total = self.frame_proportion_of_total_time(time)
| File "/opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/site-packages/pyinstrument/renderers/console.py", line 189, in frame_proportion_of_total_time
| return time / self.root_frame.time
| ZeroDivisionError: float division by zero
pyinstrument: 4.6.2
python: 3.10
fastapi: 0.95.1
Thanks in advance for your help
joerick commented
It looks like there's a bug here, it's caused by a profile that has zero duration. The simplest fix would be to add a special case to frame_proportion_of_total_time to just return 1 if self.root_frame.time is zero. If you have time to submit a PR, that would be appriciated!