Starlette/FastAPI body streaming time not included in transaction

[jeffffrye]

Update: See this comment for the actual action items on this issue.

Describe the bug:
After updating our application to use elastic-apm 6.12, we are seeing on average 40% higher latency compared to 6.11. The increase is generally lower when the request payload is on the low end (~10 KB) and reaches from 70% to as much as 500% higher with larger payloads (>50KB).

To Reproduce

1. Create a FastAPI app with a "/save" endpoint which accepts an arbitrary (e.g. Request(id=0,data={...}) request object
2. Create an elasticapm client with default capture_body=False and add to the app as middleware
3. Wrap the endpoint method with an elasticapm.async_capture_span decorator
4. Build the FastAPI app environment with elastic-apm==6.11
5. Call the save endpoint with 50KB test requests at a rate of ~250 TPM and record the resulting average latency
6. Rebuild the app with elastic-apm==6.12 and repeat the load test

Environment (please complete the following information)

• OS: Linux
• Python version: 3.10
• Framework and version [e.g. Django 2.1]: FastAPI 0.103.1
• APM Server version: v8.5.0
• Agent version: 6.11.0, >=6.12.0 (observed in 6.12, 6.13, 6.18, and 6.19)

Additional context

We have been able to isolate the latency issues to the elastic-apm version alone, the issue is seen before and after updating from 6.11 to 6.12 without making any other change. I have not been able to identify the root cause yet but I'm continuing to research and will update this issue as I learn more.

I noticed an interesting pattern in some recent testing with CPU usage reported in Kibana, see attached screenshots. With peak load (250 TPM) and the same length testing window, the max utilization in 6.11 peaks initially but remains flat throughout the rest of the test period whereas 6.12 the utilization rises and falls periodically seemingly at fixed intervals.

• Agent config options

  Click to expand

  {'service_name': 'Python-FastAPI-Service', 'server_url': *************, 'secret_token': *************}
  

• requirements.txt:

  Click to expand

  anyio==3.7.1
  asn1crypto==1.5.1
  boto3==1.28.57
  botocore==1.31.85
  certifi==2023.11.17
  cffi==1.16.0
  chardet==5.2.0
  charset-normalizer==3.3.2
  click==8.1.7
  coverage==7.3.2
  cryptography==41.0.7
  ecs-logging==2.1.0
  elastic-apm==6.12.0
  exceptiongroup==1.2.0
  fastapi==0.103.1
  filelock==3.13.1
  gunicorn==21.2.0
  h11==0.14.0
  httpcore==1.0.2
  httptools==0.6.1
  httpx==0.25.2
  idna==3.6
  iniconfig==2.0.0
  jmespath==1.0.1
  libcst==1.1.0
  markdown-it-py==3.0.0
  mdurl==0.1.2
  mypy-extensions==1.0.0
  oscrypto==1.3.0
  packaging==23.2
  pendulum==2.1.2
  platformdirs==3.8.1
  pluggy==1.3.0
  pycparser==2.21
  pycryptodomex==3.19.0
  pydantic==2.5.2
  pydantic-settings==2.1.0
  pydantic_core==2.14.5
  Pygments==2.16.1
  PyJWT==2.8.0
  pyOpenSSL==23.3.0
  pytest==7.4.3
  pytest-cov==4.1.0
  pytest-env==1.1.3
  python-dateutil==2.8.2
  python-dotenv==1.0.0
  python-json-logger==2.0.7
  pytz==2023.3.post1
  pytzdata==2020.1
  PyYAML==6.0.1
  requests==2.31.0
  rich==13.6.0
  s3transfer==0.7.0
  six==1.16.0
  sniffio==1.3.0
  snowflake-connector-python==3.2.0
  sortedcontainers==2.4.0
  starlette==0.27.0
  tomli==2.0.1
  tomlkit==0.12.3
  typer==0.9.0
  typing-inspect==0.9.0
  typing_extensions==4.9.0
  urllib3==1.26.18
  uvicorn==0.18.3
  uvloop==0.19.0
  watchfiles==0.21.0
  websockets==12.0
  wrapt==1.14.1
  

[basepi]

Very strange! Have you tested with the current version of the agent, 6.19.0? I'm curious if this issue persists for you there.

I'm a bit mystified about what could be causing this -- the release is pretty mundane. We did change some handling for Starlette (and FastAPI by association) request bodies, but you are using capture_body: "off" so I'm not sure how that would affect you.

Unfortunately, I won't be able to look into this more until the new year due to holiday plans.

[jeffffrye]

Wow thanks so much for getting back to me so quickly! And no worries on not being able to look into it right away, I'll be away for some time myself for the holidays anyway.

But to answer your question, unfortunately none of the subsequent versions past 6.12 have any noticeable impact on latency, including 6.19.

I also suspected the changes to the Starlette init module but couldn't pinpoint any specific change that could explain this. However I just finished up another round of testing and have narrowed it down to the __call__ dunder method. By replacing the entire method's code from 6.12 with the method code from 6.11, I'm seeing average latency of 115ms with the 6.12 code vs. 22ms with 6.11 code!

The biggest change I can see between the two is that in 6.11 there is no check on the capture_body flag before the body is consumed from receive:

# When we consume the body from receive, we replace the streaming
# mechanism with a mocked version -- this workaround came from
# https://github.com/encode/starlette/issues/495#issuecomment-513138055
body = b""
while True:
    message = await receive()
    if not message:
break
    if message["type"] == "http.request":
b = message.get("body", b"")
if b:
    body += b
if not message.get("more_body", False):
    break
    if message["type"] == "http.disconnect":
break

Whereas in 6.12, the body is not consumed from receive if capture_body is set to "off":

if self.client.config.capture_body != "off":

    # When we consume the body from receive, we replace the streaming
    # mechanism with a mocked version -- this workaround came from
    # https://github.com/encode/starlette/issues/495#issuecomment-513138055
    body = []
    while True:
        message = await receive()
        if not message:
            break
        if message["type"] == "http.request":
            b = message.get("body", b"")
            if b:
                body.append(b)
            if not message.get("more_body", False):
                break
        if message["type"] == "http.disconnect":
            break

    joined_body = b"".join(body)

This logic makes sense to me intuitively (why retrieve the body from receive if we don't need to use it?) but I do wonder if the act of consuming the body from receive is itself resulting in the latency improvement.

[basepi]

Good catch! I have a hypothesis: My bet is that the latency is actually the same from a user's perspective. What's happening is we're awaiting the request body before we start the transaction. So that await time is not included in the trace. We then re-wrap the request body so the app can consume it, but that wrapper is much more performant than streaming the request body in the first place.

I think in 6.11, the end-to-end time is likely the same as in 6.12; in 6.12, you have to await the request body yourself, introducing latency into the trace.

You could test this by timing a curl against your endpoint in 6.11 and 6.12. I bet they come out very similar.

[basepi]

This begs the question: what should we be doing? Should we start the transaction before we await the body so that additional latency is always included in the trace? That's probably the correct course of action. It's weird that your latency would increase when you turn off capture_body. That's counter-intuitive.

[jeffffrye]

Ah so it sounds like our app had been a fair bit slower than it seemed from what we could see on our dashboard, it's just that awaiting the request body before starting the transaction had hidden that processing time from our view. Our app didn't slow down, we're just now seeing the correct figures. Your hypothesis was correct by the way--testing locally with the curl on both 6.11 and 6.12 versions did in fact show nearly identical transaction times.

I would agree that the transaction should be started beforehand if the end goal is to account for the full processing time end to end. My assumption is that this fix would not affect our app at this point, but definitely seems very important for users who do have the config set to capture the body from the request.

[xrmx]

Regarding starting the transaction earlier, doesn't it have a dependency on the body for the request?

[basepi]

@xrmx Technically no. We just need to move these lines:

apm-agent-python/elasticapm/contrib/starlette/__init__.py

Lines 237 to 238 in 460f141

	trace_parent = TraceParent.from_headers(dict(request.headers))
	self.client.begin_transaction("request", trace_parent=trace_parent)

up above the capture_body work here:

apm-agent-python/elasticapm/contrib/starlette/__init__.py

Line 154 in 460f141

if self.client.config.capture_body != "off":

It might make sense to remove the request_started() method at that point; I'll leave that decision to you.