Skip to content

perf: span_processor.on_end evaluates span_formatter(span) eagerly via f-string regardless of log level #15339

Description

@805795108

Summary

LangfuseSpanProcessor.on_end in langfuse/_client/span_processor.py evaluates span_formatter(span) eagerly inside an f-string passed to langfuse_logger.debug(...). Because Python f-strings are evaluated before being handed to the logger, the full span serialization runs on every span end, regardless of the effective log level. This is a measurable per-span CPU cost on the thread that ends the span (in async apps, the event loop thread), and cannot be mitigated by raising the log level.

Environment

  • Langfuse Python SDK: langfuse-python 4.14.0 (also confirmed still present on main as of 2026-07-23)
  • Python 3.12
  • OS: Linux (containerized, FastAPI + asyncio)

Reproducible example

The offending code (current main, langfuse/_client/span_processor.py, LangfuseSpanProcessor.on_end):

langfuse_logger.debug(
    f"Trace: Processing span name='{span._name}' | Full details:\n{span_formatter(span)}"
)

span_formatter(span) performs a full json.dumps of the span (attributes, events, links, resource, instrumentationScope). Profiling a decorated async handler returning ~1000 spans/s shows this single call at ~0.27 ms/span, i.e. ~27% of one core purely on formatting a debug message that is never emitted (logger at WARNING).

Crucially, setting LANGFUSE_LOG_LEVEL=WARNING (or debug=False) does not help: the f-string is constructed before logger.debug is called, so the formatting cost is paid unconditionally.

Root cause

Python logging defers %-formatting of arguments (via logger.debug(msg, *args)), but it cannot defer evaluation of expressions already embedded in an f-string. The f-string is built at call time, so span_formatter(span) runs even when the DEBUG level is disabled. This is the well-known f-string-in-logging anti-pattern (https://stackoverflow.com/questions/54367975).

Impact

  • Per-span overhead on the calling thread (event loop in async apps) → contributes to GIL pressure under high span throughput.
  • In our deployment this combined with high-frequency spans to saturate CPU and cause service restarts. Even in isolation it is a non-trivial tax proportional to span throughput.
  • Not mitigated by log level configuration, which is counter-intuitive for users trying to reduce SDK overhead.

Suggested fix

Guard the formatting with an enabled check (cheapest, no API change):

if langfuse_logger.isEnabledFor(logging.DEBUG):
    langfuse_logger.debug(
        f"Trace: Processing span name='{span._name}' | Full details:\n{span_formatter(span)}"
    )

or use lazy %-style args (note: span_formatter(span) would still evaluate as an arg, so the isEnabledFor guard is preferred; alternatively defer via a small lazy wrapper).

Additional context

  • A related but different closed issue is Functions dramatically slower when using langfuse, lots of logs being dumped. #4863 (serializer print(obj.__dict__) dumping object graphs). That was fixed by removing the print; the on_end f-string here was not addressed.
  • The same f-string eager-eval pattern also appears in on_start (f"Propagated {len(...)} attributes...") and several on_end debug branches; worth auditing together.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions