[tracing] sglang tracing v2: support exporting tracing data asynchronously (#30023)
This commit is contained in:
@@ -1053,6 +1053,16 @@ SGLang supports various environment variables that can be used to configure its
|
|||||||
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.05)"}}>Config BatchSpanProcessor.max_export_batch_size if tracing is enabled</td>
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.05)"}}>Config BatchSpanProcessor.max_export_batch_size if tracing is enabled</td>
|
||||||
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.02)"}}>`64`</td>
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.02)"}}>`64`</td>
|
||||||
</tr>
|
</tr>
|
||||||
|
<tr>
|
||||||
|
<td style={{padding: "9px 12px", fontWeight: 500, backgroundColor: "rgba(255,255,255,0.02)"}}>`SGLANG_TRACE_ASYNC`</td>
|
||||||
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.05)"}}>Enable async tracing: span creation is offloaded to a dedicated exporter process via ZMQ, reducing OTel overhead on the inference hot path</td>
|
||||||
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.02)"}}>`false`</td>
|
||||||
|
</tr>
|
||||||
|
<tr>
|
||||||
|
<td style={{padding: "9px 12px", fontWeight: 500, backgroundColor: "rgba(255,255,255,0.02)"}}>`SGLANG_TRACE_ASYNC_FLUSH_THRESHOLD`</td>
|
||||||
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.05)"}}>Number of buffered trace operations before an automatic flush to the exporter process</td>
|
||||||
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.02)"}}>`100`</td>
|
||||||
|
</tr>
|
||||||
<tr>
|
<tr>
|
||||||
<td style={{padding: "9px 12px", fontWeight: 500, backgroundColor: "rgba(255,255,255,0.02)"}}><code>SGLANG_PROFILE_V2</code></td>
|
<td style={{padding: "9px 12px", fontWeight: 500, backgroundColor: "rgba(255,255,255,0.02)"}}><code>SGLANG_PROFILE_V2</code></td>
|
||||||
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.05)"}}>Use the v2 profiler implementation.</td>
|
<td style={{padding: "9px 12px", backgroundColor: "rgba(255,255,255,0.05)"}}>Use the v2 profiler implementation.</td>
|
||||||
|
|||||||
@@ -70,6 +70,28 @@ This section explains how to configure the request tracing and export the trace
|
|||||||
|
|
||||||
**Note**: You must set the parameter `--enable-trace`; otherwise, the trace capability will not be enabled regardless of any dynamic adjustments to the trace level.
|
**Note**: You must set the parameter `--enable-trace`; otherwise, the trace capability will not be enabled regardless of any dynamic adjustments to the trace level.
|
||||||
|
|
||||||
|
## Async Tracing (Reducing Performance Overhead)
|
||||||
|
|
||||||
|
When batch sizes are large, synchronous OTel span creation can degrade inference throughput due to thread-safe locking and background export threads. Async tracing moves all span creation to a dedicated exporter process via ZMQ, keeping the scheduler and tokenizer hot paths free of OTel overhead.
|
||||||
|
|
||||||
|
**Enable async tracing:**
|
||||||
|
```bash
|
||||||
|
SGLANG_TRACE_ASYNC=1 python -m sglang.launch_server --enable-trace --otlp-traces-endpoint 0.0.0.0:4317 <other options>
|
||||||
|
```
|
||||||
|
|
||||||
|
**How it works:**
|
||||||
|
- A daemon exporter process is started per worker process (scheduler, tokenizer, etc.).
|
||||||
|
- The root span is still created in the caller process (one per request, negligible cost), preserving cross-process span linking via `traceparent`.
|
||||||
|
- Thread spans and slice spans are buffered as lightweight operation dicts and flushed to the exporter via ZMQ PUSH/PULL.
|
||||||
|
- Span IDs are pre-generated in the caller process using `TraceCustomIdGenerator.preset_next_span_id()`, so the exported span tree is identical to synchronous mode.
|
||||||
|
- Thread info (scheduler label, TP/DP/PP ranks) is registered once via a callback on `trace_set_thread_info()`.
|
||||||
|
|
||||||
|
**Tuning:**
|
||||||
|
| Environment Variable | Description | Default |
|
||||||
|
| --- | --- | --- |
|
||||||
|
| `SGLANG_TRACE_ASYNC` | Enable async tracing | `false` |
|
||||||
|
| `SGLANG_TRACE_ASYNC_FLUSH_THRESHOLD` | Max buffered ops before auto-flush | `100` |
|
||||||
|
|
||||||
## How to add Tracing for slices you're interested in?(API introduction)
|
## How to add Tracing for slices you're interested in?(API introduction)
|
||||||
We have already inserted instrumentation points in the tokenizer and scheduler main threads. If you wish to trace additional request execution segments or perform finer-grained tracing, please use the APIs from the tracing package as described below.
|
We have already inserted instrumentation points in the tokenizer and scheduler main threads. If you wish to trace additional request execution segments or perform finer-grained tracing, please use the APIs from the tracing package as described below.
|
||||||
|
|
||||||
|
|||||||
@@ -364,6 +364,8 @@ class Envs:
|
|||||||
SGLANG_MEM_PROFILE_MAX_ENTRIES = EnvInt(100000)
|
SGLANG_MEM_PROFILE_MAX_ENTRIES = EnvInt(100000)
|
||||||
SGLANG_OTLP_EXPORTER_SCHEDULE_DELAY_MILLIS = EnvInt(500)
|
SGLANG_OTLP_EXPORTER_SCHEDULE_DELAY_MILLIS = EnvInt(500)
|
||||||
SGLANG_OTLP_EXPORTER_MAX_EXPORT_BATCH_SIZE = EnvInt(64)
|
SGLANG_OTLP_EXPORTER_MAX_EXPORT_BATCH_SIZE = EnvInt(64)
|
||||||
|
SGLANG_TRACE_ASYNC = EnvBool(False)
|
||||||
|
SGLANG_TRACE_ASYNC_FLUSH_THRESHOLD = EnvInt(100)
|
||||||
SGLANG_NATIVE_MOVE_KV_CACHE = EnvBool(False)
|
SGLANG_NATIVE_MOVE_KV_CACHE = EnvBool(False)
|
||||||
# Disable lazy compaction in the unified memory pool allocator and
|
# Disable lazy compaction in the unified memory pool allocator and
|
||||||
# fall back to the per-free eager compaction. Used for production
|
# fall back to the per-free eager compaction. Used for production
|
||||||
|
|||||||
@@ -268,6 +268,7 @@ from sglang.srt.model_loader.utils import get_resolved_model_impl
|
|||||||
from sglang.srt.multiplex.multiplexing_mixin import SchedulerMultiplexMixin
|
from sglang.srt.multiplex.multiplexing_mixin import SchedulerMultiplexMixin
|
||||||
from sglang.srt.observability.metrics_collector import SchedulerMetricsCollector
|
from sglang.srt.observability.metrics_collector import SchedulerMetricsCollector
|
||||||
from sglang.srt.observability.req_time_stats import (
|
from sglang.srt.observability.req_time_stats import (
|
||||||
|
flush_trace_batch,
|
||||||
set_schedule_time_batch,
|
set_schedule_time_batch,
|
||||||
set_time_batch,
|
set_time_batch,
|
||||||
)
|
)
|
||||||
@@ -3889,6 +3890,9 @@ class Scheduler(
|
|||||||
batch: ScheduleBatch,
|
batch: ScheduleBatch,
|
||||||
result: Union[GenerationBatchResult, EmbeddingBatchResult],
|
result: Union[GenerationBatchResult, EmbeddingBatchResult],
|
||||||
):
|
):
|
||||||
|
# Flush async trace ops here: in overlap mode this CPU work runs while
|
||||||
|
# the next batch's GPU forward is in flight, giving free overlap.
|
||||||
|
flush_trace_batch(batch.reqs)
|
||||||
self.publish_load_snapshot(force=batch.forward_mode.is_extend())
|
self.publish_load_snapshot(force=batch.forward_mode.is_extend())
|
||||||
|
|
||||||
if batch.forward_mode.is_decode():
|
if batch.forward_mode.is_decode():
|
||||||
|
|||||||
@@ -37,6 +37,10 @@ from sglang.srt.observability.trace import (
|
|||||||
TraceSliceContext,
|
TraceSliceContext,
|
||||||
get_global_tracing_enabled,
|
get_global_tracing_enabled,
|
||||||
)
|
)
|
||||||
|
from sglang.srt.observability.trace_async import (
|
||||||
|
TraceReqContextAsync,
|
||||||
|
is_async_tracing_available,
|
||||||
|
)
|
||||||
from sglang.srt.utils import get_bool_env_var
|
from sglang.srt.utils import get_bool_env_var
|
||||||
|
|
||||||
if TYPE_CHECKING:
|
if TYPE_CHECKING:
|
||||||
@@ -286,6 +290,15 @@ class ReqTimeStatsBase:
|
|||||||
bootstrap_room: Optional[int],
|
bootstrap_room: Optional[int],
|
||||||
external_trace_header: Optional[Dict[str, str]] = None,
|
external_trace_header: Optional[Dict[str, str]] = None,
|
||||||
):
|
):
|
||||||
|
if is_async_tracing_available():
|
||||||
|
self.trace_ctx = TraceReqContextAsync(
|
||||||
|
rid=rid,
|
||||||
|
bootstrap_room=bootstrap_room,
|
||||||
|
role=self.disagg_mode_str(),
|
||||||
|
module_name="request",
|
||||||
|
external_trace_header=external_trace_header,
|
||||||
|
)
|
||||||
|
else:
|
||||||
self.trace_ctx = TraceReqContext(
|
self.trace_ctx = TraceReqContext(
|
||||||
rid=rid,
|
rid=rid,
|
||||||
bootstrap_room=bootstrap_room,
|
bootstrap_room=bootstrap_room,
|
||||||
@@ -339,6 +352,10 @@ class ReqTimeStatsBase:
|
|||||||
trace_ctx_state = state.get("trace_ctx")
|
trace_ctx_state = state.get("trace_ctx")
|
||||||
if isinstance(trace_ctx_state, dict):
|
if isinstance(trace_ctx_state, dict):
|
||||||
if trace_ctx_state.get("tracing_enable"):
|
if trace_ctx_state.get("tracing_enable"):
|
||||||
|
if trace_ctx_state.get("is_async"):
|
||||||
|
trace_ctx = object.__new__(TraceReqContextAsync)
|
||||||
|
trace_ctx.__setstate__(trace_ctx_state)
|
||||||
|
else:
|
||||||
trace_ctx = object.__new__(TraceReqContext)
|
trace_ctx = object.__new__(TraceReqContext)
|
||||||
trace_ctx.__setstate__(trace_ctx_state)
|
trace_ctx.__setstate__(trace_ctx_state)
|
||||||
state["trace_ctx"] = trace_ctx
|
state["trace_ctx"] = trace_ctx
|
||||||
@@ -1247,3 +1264,19 @@ def set_time_batch(
|
|||||||
method(ts)
|
method(ts)
|
||||||
else:
|
else:
|
||||||
method(ts, attrs)
|
method(ts, attrs)
|
||||||
|
|
||||||
|
|
||||||
|
def flush_trace_batch(reqs: List[Any]):
|
||||||
|
"""Proactively flush buffered trace ops for a batch of requests.
|
||||||
|
|
||||||
|
Call at natural CPU/GPU overlap points (e.g., right before run_batch)
|
||||||
|
so the ZMQ send overlaps with GPU forward compute.
|
||||||
|
"""
|
||||||
|
if reqs is None or not get_global_tracing_enabled():
|
||||||
|
return
|
||||||
|
for req in reqs:
|
||||||
|
time_stats = getattr(req, "time_stats", None)
|
||||||
|
if time_stats is not None:
|
||||||
|
trace_ctx = getattr(time_stats, "trace_ctx", None)
|
||||||
|
if trace_ctx is not None:
|
||||||
|
trace_ctx.flush()
|
||||||
|
|||||||
@@ -24,6 +24,7 @@ import uuid
|
|||||||
from dataclasses import dataclass
|
from dataclasses import dataclass
|
||||||
from typing import Any, Dict, List, Mapping, Optional
|
from typing import Any, Dict, List, Mapping, Optional
|
||||||
|
|
||||||
|
from sglang.srt.environ import envs
|
||||||
from sglang.srt.utils import get_int_env_var
|
from sglang.srt.utils import get_int_env_var
|
||||||
|
|
||||||
logger = logging.getLogger(__name__)
|
logger = logging.getLogger(__name__)
|
||||||
@@ -124,10 +125,29 @@ class TraceThreadContext:
|
|||||||
|
|
||||||
|
|
||||||
class TraceCustomIdGenerator(id_generator.IdGenerator):
|
class TraceCustomIdGenerator(id_generator.IdGenerator):
|
||||||
|
"""Custom ID generator with support for pre-setting the next span ID.
|
||||||
|
|
||||||
|
Why custom IDs are needed:
|
||||||
|
The default IdGenerator may produce duplicate trace IDs across
|
||||||
|
multiple TP scheduler processes.
|
||||||
|
|
||||||
|
Preset mechanism (used by async tracing):
|
||||||
|
When SGLANG_TRACE_ASYNC=1, span creation is deferred to an exporter
|
||||||
|
process while the caller process needs to know span IDs in advance
|
||||||
|
for cross-process span linking. The caller pre-generates a span ID
|
||||||
|
and sends it to the exporter. Before calling tracer.start_span(),
|
||||||
|
the exporter calls preset_next_span_id(id) — the next
|
||||||
|
generate_span_id() call consumes it, then falls back to random
|
||||||
|
generation. This avoids modifying the standard OTel start_span()
|
||||||
|
API while giving the caller full control over span IDs.
|
||||||
|
|
||||||
|
Thread-safety: _preset_local is a threading.local(), so concurrent
|
||||||
|
callers in different threads cannot interfere. The exporter process
|
||||||
|
is single-threaded, so no additional locking is needed.
|
||||||
"""
|
"""
|
||||||
The default IdGenerator may produce duplicate trace IDs across multiple TP scheduler processes,
|
|
||||||
hence a custom IdGenerator is implemented.
|
# Thread-local storage for the next span ID to use preset.
|
||||||
"""
|
_preset_local = threading.local()
|
||||||
|
|
||||||
def __init__(self):
|
def __init__(self):
|
||||||
super().__init__()
|
super().__init__()
|
||||||
@@ -138,12 +158,30 @@ class TraceCustomIdGenerator(id_generator.IdGenerator):
|
|||||||
return self.local_random.getrandbits(64)
|
return self.local_random.getrandbits(64)
|
||||||
|
|
||||||
def generate_span_id(self) -> int:
|
def generate_span_id(self) -> int:
|
||||||
|
# If a preset span ID was injected, consume it (one-shot).
|
||||||
|
preset = getattr(self._preset_local, "span_id", None)
|
||||||
|
if preset is not None:
|
||||||
|
self._preset_local.span_id = None
|
||||||
|
return preset
|
||||||
return self.local_random.getrandbits(64)
|
return self.local_random.getrandbits(64)
|
||||||
|
|
||||||
|
@classmethod
|
||||||
|
def preset_next_span_id(cls, span_id: int):
|
||||||
|
"""Inject a pre-generated span ID for the next start_span() call.
|
||||||
|
|
||||||
|
The ID is consumed exactly once by generate_span_id() and then
|
||||||
|
cleared. Call this immediately before tracer.start_span().
|
||||||
|
"""
|
||||||
|
cls._preset_local.span_id = span_id
|
||||||
|
|
||||||
|
|
||||||
# global variables
|
# global variables
|
||||||
threads_info: Dict[int, TraceThreadInfo] = {}
|
threads_info: Dict[int, TraceThreadInfo] = {}
|
||||||
|
|
||||||
|
# Optional callback invoked when a new thread registers its trace info.
|
||||||
|
# Used by trace_async to forward thread info to the exporter process.
|
||||||
|
_on_thread_info_set = None
|
||||||
|
|
||||||
get_cur_time_ns = lambda: int(time.time() * 1e9)
|
get_cur_time_ns = lambda: int(time.time() * 1e9)
|
||||||
if hasattr(time, "time_ns"):
|
if hasattr(time, "time_ns"):
|
||||||
get_cur_time_ns = lambda: int(time.time_ns())
|
get_cur_time_ns = lambda: int(time.time_ns())
|
||||||
@@ -199,12 +237,8 @@ def process_tracing_init(
|
|||||||
resource=resource, id_generator=TraceCustomIdGenerator()
|
resource=resource, id_generator=TraceCustomIdGenerator()
|
||||||
)
|
)
|
||||||
|
|
||||||
schedule_delay_millis = get_int_env_var(
|
schedule_delay_millis = envs.SGLANG_OTLP_EXPORTER_SCHEDULE_DELAY_MILLIS.get()
|
||||||
"SGLANG_OTLP_EXPORTER_SCHEDULE_DELAY_MILLIS", 500
|
max_export_batch_size = envs.SGLANG_OTLP_EXPORTER_MAX_EXPORT_BATCH_SIZE.get()
|
||||||
)
|
|
||||||
max_export_batch_size = get_int_env_var(
|
|
||||||
"SGLANG_OTLP_EXPORTER_MAX_EXPORT_BATCH_SIZE", 64
|
|
||||||
)
|
|
||||||
|
|
||||||
processor = BatchSpanProcessor(
|
processor = BatchSpanProcessor(
|
||||||
span_exporter=get_otlp_span_exporter(otlp_endpoint),
|
span_exporter=get_otlp_span_exporter(otlp_endpoint),
|
||||||
@@ -222,6 +256,12 @@ def process_tracing_init(
|
|||||||
opentelemetry_initialized = True
|
opentelemetry_initialized = True
|
||||||
tracer = trace.get_tracer("sglang server")
|
tracer = trace.get_tracer("sglang server")
|
||||||
|
|
||||||
|
# Auto-start async trace exporter when SGLANG_TRACE_ASYNC=1
|
||||||
|
if envs.SGLANG_TRACE_ASYNC.get():
|
||||||
|
from sglang.srt.observability.trace_async import start_trace_exporter
|
||||||
|
|
||||||
|
start_trace_exporter(otlp_endpoint, server_name, trace_modules=trace_modules)
|
||||||
|
|
||||||
|
|
||||||
def get_global_tracing_enabled():
|
def get_global_tracing_enabled():
|
||||||
return opentelemetry_initialized
|
return opentelemetry_initialized
|
||||||
@@ -266,6 +306,9 @@ def trace_set_thread_info(
|
|||||||
pp_rank=pp_rank,
|
pp_rank=pp_rank,
|
||||||
)
|
)
|
||||||
|
|
||||||
|
if _on_thread_info_set is not None:
|
||||||
|
_on_thread_info_set(threads_info[pid])
|
||||||
|
|
||||||
|
|
||||||
class TraceReqContext:
|
class TraceReqContext:
|
||||||
def __init__(
|
def __init__(
|
||||||
@@ -275,9 +318,12 @@ class TraceReqContext:
|
|||||||
role="unified",
|
role="unified",
|
||||||
module_name="",
|
module_name="",
|
||||||
external_trace_header: Optional[Dict[str, str]] = None,
|
external_trace_header: Optional[Dict[str, str]] = None,
|
||||||
|
trace_level: Optional[int] = None,
|
||||||
):
|
):
|
||||||
self.rid: str = str(rid)
|
self.rid: str = str(rid)
|
||||||
self.trace_level = get_global_trace_level()
|
self.trace_level = (
|
||||||
|
trace_level if trace_level is not None else get_global_trace_level()
|
||||||
|
)
|
||||||
self.tracing_enable: bool = opentelemetry_initialized and self.trace_level > 0
|
self.tracing_enable: bool = opentelemetry_initialized and self.trace_level > 0
|
||||||
|
|
||||||
# Filter by --trace-modules only for explicitly named modules; contexts
|
# Filter by --trace-modules only for explicitly named modules; contexts
|
||||||
@@ -453,7 +499,7 @@ class TraceReqContext:
|
|||||||
copied.trace_level = self.trace_level
|
copied.trace_level = self.trace_level
|
||||||
copied.module_name = self.module_name
|
copied.module_name = self.module_name
|
||||||
copied.is_copy = True # Mark as copy
|
copied.is_copy = True # Mark as copy
|
||||||
copied.pid = self.pid
|
copied.pid = None
|
||||||
|
|
||||||
# thread_context is None, will be rebuilt via rebuild_thread_context()
|
# thread_context is None, will be rebuilt via rebuild_thread_context()
|
||||||
copied.thread_context = None
|
copied.thread_context = None
|
||||||
@@ -476,11 +522,14 @@ class TraceReqContext:
|
|||||||
|
|
||||||
return copied
|
return copied
|
||||||
|
|
||||||
def rebuild_thread_context(self, ts: Optional[int] = None):
|
def rebuild_thread_context(
|
||||||
|
self, ts: Optional[int] = None, pid: Optional[int] = None
|
||||||
|
):
|
||||||
if not self.tracing_enable:
|
if not self.tracing_enable:
|
||||||
return
|
return
|
||||||
|
|
||||||
ts = ts or get_cur_time_ns()
|
ts = ts or get_cur_time_ns()
|
||||||
|
self.pid = pid if pid is not None else threading.get_native_id()
|
||||||
self.thread_context = self.__create_thread_context(ts)
|
self.thread_context = self.__create_thread_context(ts)
|
||||||
|
|
||||||
def trace_req_start(
|
def trace_req_start(
|
||||||
@@ -770,6 +819,9 @@ class TraceReqContext:
|
|||||||
self.thread_context.thread_span.end(end_time=ts)
|
self.thread_context.thread_span.end(end_time=ts)
|
||||||
self.thread_context = None
|
self.thread_context = None
|
||||||
|
|
||||||
|
def flush(self):
|
||||||
|
pass
|
||||||
|
|
||||||
def __del__(self):
|
def __del__(self):
|
||||||
self.abort(abort_info={"reason": "have unclosed span, auto closed"})
|
self.abort(abort_info={"reason": "have unclosed span, auto closed"})
|
||||||
|
|
||||||
|
|||||||
File diff suppressed because it is too large
Load Diff
@@ -553,5 +553,39 @@ class TestTraceEngine(CustomTestCase):
|
|||||||
engine.shutdown()
|
engine.shutdown()
|
||||||
|
|
||||||
|
|
||||||
|
class TestTraceServerAsync(TestTraceServer):
|
||||||
|
"""Async tracing variant — same server setup with SGLANG_TRACE_ASYNC=1."""
|
||||||
|
|
||||||
|
@classmethod
|
||||||
|
def setUpClass(cls):
|
||||||
|
cls.collector = LightweightOtlpCollector()
|
||||||
|
cls.collector.start()
|
||||||
|
time.sleep(0.2)
|
||||||
|
|
||||||
|
cls.process = popen_launch_server(
|
||||||
|
DEFAULT_SMALL_MODEL_NAME_FOR_TEST,
|
||||||
|
DEFAULT_URL_FOR_TEST,
|
||||||
|
timeout=DEFAULT_TIMEOUT_FOR_SERVER_LAUNCH,
|
||||||
|
other_args=[
|
||||||
|
"--enable-trace",
|
||||||
|
"--otlp-traces-endpoint",
|
||||||
|
"127.0.0.1:4317",
|
||||||
|
],
|
||||||
|
env={"SGLANG_TRACE_ASYNC": "1"},
|
||||||
|
)
|
||||||
|
|
||||||
|
response = requests.get(f"{DEFAULT_URL_FOR_TEST}/health_generate")
|
||||||
|
assert response.status_code == 200
|
||||||
|
|
||||||
|
cls.collector.clear()
|
||||||
|
|
||||||
|
# Only run trace_level_3 — the most comprehensive check.
|
||||||
|
test_trace_level_0 = None
|
||||||
|
test_trace_level_1 = None
|
||||||
|
test_trace_level_2 = None
|
||||||
|
test_batch_request = None
|
||||||
|
test_parallel_sample = None
|
||||||
|
|
||||||
|
|
||||||
if __name__ == "__main__":
|
if __name__ == "__main__":
|
||||||
unittest.main()
|
unittest.main()
|
||||||
|
|||||||
Reference in New Issue
Block a user