caught AssertionError: Please raise an issue at https://github.com/joerick/pyinstrument/issues and let me know how you caused this error!
erez-marmor opened this issue · 12 comments
version: 4.1.1
I've been able to write a pytest scenario reproducing the error:
app code:
#!/usr/bin/env python3
from typing import Callable
from fastapi import FastAPI
from pyinstrument import Profiler
from starlette.requests import Request
from starlette.responses import Response
class ProfilingMiddleware:
""" middleware that profiles request """
def __init__(self, profiler_interval: float = 0.0001, ):
self._profiler = Profiler(interval=profiler_interval)
async def __call__(self, request: Request, call_next: Callable) -> Response:
""" profile request """
self._profiler.start()
try:
response = await call_next(request)
finally:
self._profiler.stop()
output = self._profiler.output_text(color=True)
print(output)
return response
def create_app() -> FastAPI:
""" application factory """
app = FastAPI()
@app.post('/')
def endpoint():
""" endpoint example """
print('inside endpoint')
return {}
app.middleware('http')(ProfilingMiddleware())
return app
APP = create_app()test code:
from fastapi.testclient import TestClient
from app import APP
client = TestClient(APP)
def test_case() -> None:
""" test 2 requests lead to an error while 1 passes """
client.post(url='/')
client.get(url='/dfhjhjkdfs') # no matter which request you send you get the error (tried switching method/url etc)executing the test leads to the following:
=================================================================================================================== test session starts ====================================================================================================================
platform darwin -- Python 3.9.6, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- /Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/bin/python
cachedir: .pytest_cache
rootdir: /Users/erezm/repos/ec-notification-service, configfile: pytest.ini, testpaths: .
plugins: anyio-3.5.0, pythonpath-0.7.3
collected 1 item
tests/feature_test/test_app_routes.py::test_case FAILED [100%]
========================================================================================================================= FAILURES =========================================================================================================================
________________________________________________________________________________________________________________________ test_case _________________________________________________________________________________________________________________________
Traceback (most recent call last):
File "/Users/erezm/repos/ec-notification-service/tests/feature_test/test_app_routes.py", line 12, in test_case
client.get(url='/dfhjhjkdfs')
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/requests/sessions.py", line 555, in get
return self.request('GET', url, **kwargs)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/testclient.py", line 468, in request
return super().request(
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/requests/sessions.py", line 542, in request
resp = self.send(prep, **send_kwargs)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/requests/sessions.py", line 655, in send
r = adapter.send(request, **kwargs)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/testclient.py", line 266, in send
raise exc
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/testclient.py", line 263, in send
portal.call(self.app, scope, receive, send)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/anyio/from_thread.py", line 240, in call
return cast(T_Retval, self.start_task_soon(func, *args).result())
File "/Users/erezm/.pyenv/versions/3.9.6/lib/python3.9/concurrent/futures/_base.py", line 445, in result
return self.__get_result()
File "/Users/erezm/.pyenv/versions/3.9.6/lib/python3.9/concurrent/futures/_base.py", line 390, in __get_result
raise self._exception
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/anyio/from_thread.py", line 187, in _call_func
retval = await retval
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/fastapi/applications.py", line 208, in __call__
await super().__call__(scope, receive, send)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/applications.py", line 112, in __call__
await self.middleware_stack(scope, receive, send)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/middleware/errors.py", line 181, in __call__
raise exc
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/middleware/errors.py", line 159, in __call__
await self.app(scope, receive, _send)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/middleware/base.py", line 55, in __call__
response = await self.dispatch_func(request, call_next)
File "/Users/erezm/repos/ec-notification-service/src/app.py", line 24, in __call__
output = self._profiler.output_text(color=True)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/profiler.py", line 295, in output_text
return self.output(
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/profiler.py", line 323, in output
return renderer.render(session)
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/renderers/console.py", line 34, in render
frame = self.preprocess(session.root_frame())
File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/session.py", line 145, in root_frame
assert root_frame is None, ASSERTION_MESSAGE
AssertionError: Please raise an issue at https://github.com/joerick/pyinstrument/issues and let me know how you caused this error!
------------------------------------------------------------------------------------------------------------------- Captured stdout call -------------------------------------------------------------------------------------------------------------------
inside endpoint
_ ._ __/__ _ _ _ _ _/_ Recorded: 19:21:02 Samples: 15
/_//_/// /_\ / //_// / //_'/ // Duration: 0.002 CPU time: 0.002
/ _/ v4.1.1
Program: /Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/bin/pytest -k test_app_routes -vv
0.002 run_forever asyncio/base_events.py:583
|- 0.001 _run_once asyncio/base_events.py:1815
| [49 frames hidden] asyncio, starlette, fastapi, anyio, t...
| 0.000 __call__ starlette/middleware/base.py:20
| `- 0.000 __call__ app.py:17
| `- 0.000 stop pyinstrument/profiler.py:136
| [3 frames hidden] pyinstrument
`- 0.000 [self]
=================================================================================================================== slowest 5 durations ====================================================================================================================
0.07s call tests/feature_test/test_app_routes.py::test_case
0.00s setup tests/feature_test/test_app_routes.py::test_case
0.00s teardown tests/feature_test/test_app_routes.py::test_case
================================================================================================================= short test summary info ==================================================================================================================
FAILED tests/feature_test/test_app_routes.py::test_case - AssertionError: Please raise an issue at https://github.com/joerick/pyinstrument/issues and let me know how you caused this error!
==================================================================================================================== 1 failed in 0.32s =====================================================================================================================note that the test passes if a single request is issued.
my environment:
Package Version
------------------ ---------
anyio 3.5.0
asgiref 3.4.1
astroid 2.8.6
attrs 21.4.0
certifi 2021.10.8
charset-normalizer 2.0.10
click 8.0.3
fastapi 0.70.0
gunicorn 20.0.4
h11 0.12.0
idna 3.3
iniconfig 1.1.1
isort 5.10.1
lazy-object-proxy 1.7.1
mccabe 0.6.1
ntplib 0.4.0
packaging 21.3
pip 21.3.1
platformdirs 2.4.1
pluggy 1.0.0
prometheus-client 0.11.0
py 1.11.0
pydantic 1.9.0
pyinstrument 4.1.1
pylint 2.11.1
pyparsing 3.0.6
pytest 6.2.5
pytest-pythonpath 0.7.3
python-multipart 0.0.5
redis 3.5.3
requests 2.26.0
setuptools 59.8.0
six 1.16.0
sniffio 1.2.0
starlette 0.16.0
starlette-exporter 0.8.2
texel-common 0.8.12
texel-logging 0.1.3
toml 0.10.2
typing_extensions 4.0.1
urllib3 1.26.8
uvicorn 0.15.0
wheel 0.37.1
wrapt 1.13.3
- running on macOS 12.1 (though it reproduced on ubuntu machines as well)
inspecting with pdb shows that indeed there are multiple root frames:
(Pdb) set(frame_tuple[0][0] for frame_tuple in self.frame_records)
{'ThreadPoolExecutor-1_0\x00<thread>\x00123145414610944', 'ThreadPoolExecutor-0_0\x00<thread>\x00123145414610944'}
(Pdb) this I assume is because of fastapi's thread pool.
am I misusing the framework?
Hi @erez-marmor, thanks for filing this will full repro details, I was able to reproduce the error locally.
Your middleware isn't correct, because of how starlette/fastapi uses threads. The profiler object in your Middleware is shared between two threads, so you can run into a situation where the profiler is started in one thread and stopped in another, or where it is profiling multiple threads at once.
I changed the middleware to this and it works:
class ProfilingMiddleware:
""" middleware that profiles request """
def __init__(self, profiler_interval: float = 0.0001, ):
self.profiler_interval = profiler_interval
async def __call__(self, request: Request, call_next: Callable) -> Response:
""" profile request """
profiler = Profiler(interval=self.profiler_interval)
profiler.start()
try:
response = await call_next(request)
finally:
profiler.stop()
output = profiler.output_text(color=True)
print(output)
return responseBut I should probably add in some runtime warnings about this, or perhaps improve this error message. Although in the past I have come across cases where users are calling Profiler from multiple threads deliberately!
@joerick , thanks for the speedy reply!
ideally, I would expect the profiler instance to be created only once instead of per request (right now it's not a problem since the profiler object is lightweight, but that might change in the future).
IMO it would be better to add a flag controlling whether or not to raise an exception (raise by default) - most naive users won't notice a runtime warning and indeed calling the profiler from multiple threads should be done mindfully ("explicit better than implicit").
for the meanwhile, I'll change the middleware on my end
ideally, I would expect the profiler instance to be created only once instead of per request (right now it's not a problem since the profiler object is lightweight, but that might change in the future).
The profiler isn't heavy, as you say, but also it isn't intended to be reused (without a call to reset()). In fact, you can call start(), stop(), start(), stop() and it's still appending to the same session. So in this example, you'd get bad data by using it in this way.
IMO it would be better to add a flag controlling whether or not to raise an exception (raise by default) - most naive users won't notice a runtime warning and indeed calling the profiler from multiple threads should be done mindfully ("explicit better than implicit").
you're probably right, exception would be better
The profiler isn't heavy, as you say, but also it isn't intended to be reused (without a call to reset()). In fact, you can call start(), stop(), start(), stop() and it's still appending to the same session. So in this example, you'd get bad data by using it in this way.
actually, I thought it was a feature :) (aggregating results from multiple requests helps identifying hotspots in the code)
Yes, it is :) but keeping the same profiler between requests is going to aggregate those timings together. Although, maybe you wanted that?
since it's a statistical profiler I think aggregating results has its merits:
consider 2 endpoints using the same utility function ; in the call graph you'll see both branches and the time spent in each function will correctly identify the utility as a hotspot.
trying to eat the cake and having it too, we would be able to come up with a solution to support both one-off and aggregated results modes
@joerick , it occurred to me that if I would make the changes you suggested to the middleware (or using reset()) and at the same time aggregate the session data in an independent Session object, getting both per-request and aggregated results is possible.
the only problem is that combining session data with multiple root frames won't be possible (I assume) with the current code - is there a way around this?
Yes, Session.combine() should be able to handle the combination. As for the multiple root frames, it feels like we could probably refactor to remove this limitation now. The simplest way would be to insert an extra parent synthetic root frame if multiple roots are found.
@joerick , following your advice I changed the middleware to be:
class ProfilingMiddleware:
""" middleware that profiles request """
def __init__(self, profiler_interval: float = 0.0001, ):
self._profiler = Profiler(interval=profiler_interval)
self._renderer_speedscope = SpeedscopeRenderer()
self._aggregated: Session
async def __call__(self, request: Request, call_next: Callable) -> Response:
""" profile request """
self._profiler.start()
try:
response = await call_next(request)
finally:
last_session = self._profiler.stop()
output = self._profiler.output_text(color=True)
print(output)
try:
self._aggregated = self._aggregated.combine(self._aggregated, last_session)
except AttributeError:
self._aggregated = last_session
self._profiler.reset()
return response
def render_speed_scope(self) -> str:
""" hook for speedscope format output """
return self._renderer_speedscope.render(self._aggregated)allowing for both aggregated and per-request stats.
self._aggregated = self._aggregated.combine(self._aggregated, last_session)is an awkward syntax. IMO we should implement__add__&__iadd__for Session.- having a dummy Session object would allow for a much cleaner construct (instead of try-except or the likes), ending up with:
self._aggregated: Session = create_dummy_session()
...
self._aggregated += last_sessiondo you think you'll have the time to fix it?
This is fixed in v4.4.0.