[diffusion] profile: support performance metric dumping and comparison (#13630)
This commit is contained in:
Mick
@@ -2,6 +2,7 @@
|
||||
|
||||
import importlib
|
||||
import ipaddress
|
||||
import logging
|
||||
import os
|
||||
import platform
|
||||
import signal
|
||||
@@ -14,9 +15,8 @@ import psutil
|
||||
import torch
|
||||
import zmq
|
||||
|
||||
from sglang.multimodal_gen.runtime.utils.logging_utils import init_logger
|
||||
|
||||
logger = init_logger(__name__)
|
||||
# use the native logger to avoid circular import
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def kill_process_tree(parent_pid, include_parent: bool = True, skip_pid: int = None):
|
||||
|
||||
265
python/sglang/multimodal_gen/runtime/utils/perf_logger.py
Normal file
265
python/sglang/multimodal_gen/runtime/utils/perf_logger.py
Normal file
@@ -0,0 +1,265 @@
|
||||
# Copied and adapted from: https://github.com/hao-ai-lab/FastVideo
|
||||
import dataclasses
|
||||
import json
|
||||
import logging
|
||||
import os
|
||||
import subprocess
|
||||
import sys
|
||||
import time
|
||||
import traceback
|
||||
from datetime import datetime
|
||||
from functools import lru_cache
|
||||
from pathlib import Path
|
||||
from typing import Any, Dict, Optional
|
||||
|
||||
from dateutil.tz import UTC
|
||||
|
||||
import sglang
|
||||
import sglang.multimodal_gen.envs as envs
|
||||
|
||||
|
||||
@dataclasses.dataclass
|
||||
class RequestTimings:
|
||||
"""A lightweight data class to store performance timings for a single request."""
|
||||
|
||||
def __init__(self, request_id: str):
|
||||
self.request_id = request_id
|
||||
self.stages: Dict[str, float] = {}
|
||||
self.steps: list[float] = []
|
||||
self.total_duration_ms: float = 0.0
|
||||
|
||||
def record_stage(self, stage_name: str, duration_s: float):
|
||||
"""Records the duration of a pipeline stage"""
|
||||
self.stages[stage_name] = duration_s * 1000 # Store as milliseconds
|
||||
|
||||
def record_steps(self, index: int, duration_s: float):
|
||||
"""Records the duration of a denoising step"""
|
||||
assert index == len(self.steps)
|
||||
self.steps.append(duration_s * 1000)
|
||||
|
||||
def to_dict(self) -> Dict[str, Any]:
|
||||
"""Serializes the timing data to a dictionary."""
|
||||
return {
|
||||
"request_id": self.request_id,
|
||||
"stages": self.stages,
|
||||
"steps": self.steps,
|
||||
"total_duration_ms": self.total_duration_ms,
|
||||
}
|
||||
|
||||
|
||||
def get_diffusion_perf_log_dir() -> str:
|
||||
"""
|
||||
Determines the directory for performance logs.
|
||||
"""
|
||||
log_dir = os.environ.get("SGLANG_PERF_LOG_DIR")
|
||||
if log_dir:
|
||||
return os.path.abspath(log_dir)
|
||||
if log_dir is None:
|
||||
sglang_path = Path(sglang.__file__).resolve()
|
||||
target_path = (sglang_path.parent / "../../.cache/logs").resolve()
|
||||
return str(target_path)
|
||||
return ""
|
||||
|
||||
|
||||
@lru_cache(maxsize=1)
|
||||
def get_git_commit_hash() -> str:
|
||||
try:
|
||||
commit_hash = os.environ.get("SGLANG_GIT_COMMIT")
|
||||
if not commit_hash:
|
||||
commit_hash = (
|
||||
subprocess.check_output(
|
||||
["git", "rev-parse", "HEAD"], stderr=subprocess.DEVNULL
|
||||
)
|
||||
.strip()
|
||||
.decode("utf-8")
|
||||
)
|
||||
_CACHED_COMMIT_HASH = commit_hash
|
||||
return commit_hash
|
||||
except (subprocess.CalledProcessError, FileNotFoundError):
|
||||
_CACHED_COMMIT_HASH = "N/A"
|
||||
return "N/A"
|
||||
|
||||
|
||||
@dataclasses.dataclass
|
||||
class RequestPerfRecord:
|
||||
request_id: str
|
||||
|
||||
timestamp: str
|
||||
commit_hash: str
|
||||
tag: str
|
||||
|
||||
stages: list[dict]
|
||||
steps: list[float]
|
||||
total_duration_ms: float
|
||||
|
||||
def __init__(
|
||||
self,
|
||||
request_id,
|
||||
commit_hash,
|
||||
tag,
|
||||
stages,
|
||||
steps,
|
||||
total_duration_ms,
|
||||
timestamp=None,
|
||||
):
|
||||
self.request_id = request_id
|
||||
if timestamp is not None:
|
||||
self.timestamp = timestamp
|
||||
else:
|
||||
self.timestamp = datetime.now(UTC).isoformat()
|
||||
|
||||
self.commit_hash = commit_hash
|
||||
self.tag = tag
|
||||
self.stages = stages
|
||||
self.steps = steps
|
||||
self.total_duration_ms = total_duration_ms
|
||||
|
||||
|
||||
class StageProfiler:
|
||||
"""
|
||||
A unified context manager, records timing information (usually of a single Stage or a step) into a provided RequestTimings object (usually from a Req).
|
||||
"""
|
||||
|
||||
def __init__(
|
||||
self,
|
||||
stage_name: str,
|
||||
logger: logging.Logger,
|
||||
timings: Optional["RequestTimings"],
|
||||
simple_log: bool = False,
|
||||
):
|
||||
self.stage_name = stage_name
|
||||
self.timings = timings
|
||||
self.logger = logger
|
||||
self.simple_log = simple_log
|
||||
self.logger = logging.getLogger(__name__)
|
||||
self.start_time = 0.0
|
||||
|
||||
# Check env var at runtime to ensure we pick up changes (e.g. from CLI args)
|
||||
self.metrics_enabled = envs.SGLANG_DIFFUSION_STAGE_LOGGING
|
||||
|
||||
def __enter__(self):
|
||||
if self.simple_log:
|
||||
self.logger.info(f"[{self.stage_name}] started...")
|
||||
|
||||
if (self.metrics_enabled and self.timings) or self.simple_log:
|
||||
self.start_time = time.perf_counter()
|
||||
|
||||
return self
|
||||
|
||||
def __exit__(self, exc_type, exc_val, exc_tb):
|
||||
if not ((self.metrics_enabled and self.timings) or self.simple_log):
|
||||
return False
|
||||
|
||||
execution_time_s = time.perf_counter() - self.start_time
|
||||
|
||||
if exc_type:
|
||||
self.logger.error(
|
||||
"[%s] Error during execution after %.4f ms: %s",
|
||||
self.stage_name,
|
||||
execution_time_s * 1000,
|
||||
exc_val,
|
||||
)
|
||||
if self.metrics_enabled:
|
||||
self.logger.error(
|
||||
"[%s] Traceback: %s",
|
||||
self.stage_name,
|
||||
"".join(traceback.format_tb(exc_tb)),
|
||||
)
|
||||
return False
|
||||
|
||||
if self.simple_log:
|
||||
self.logger.info(
|
||||
f"[{self.stage_name}] finished in {execution_time_s:.4f} seconds"
|
||||
)
|
||||
|
||||
if self.metrics_enabled and self.timings:
|
||||
if "denoising_step_" in self.stage_name:
|
||||
index = int(self.stage_name[len("denoising_step_") :])
|
||||
self.timings.record_steps(index, execution_time_s)
|
||||
else:
|
||||
self.timings.record_stage(self.stage_name, execution_time_s)
|
||||
|
||||
return False
|
||||
|
||||
|
||||
class PerformanceLogger:
|
||||
"""
|
||||
A global utility class for logging performance metrics for all request, categorized by request-id.
|
||||
|
||||
Serves both as a runtime logger (stream to file) and a dump utility.
|
||||
|
||||
Notice that ""RequestTimings"" stores the performance metrics of a single request
|
||||
"""
|
||||
|
||||
@classmethod
|
||||
def dump_benchmark_report(
|
||||
cls,
|
||||
file_path: str,
|
||||
timings: "RequestTimings",
|
||||
meta: Optional[Dict[str, Any]] = None,
|
||||
tag: str = "benchmark_dump",
|
||||
):
|
||||
"""
|
||||
Static method to dump a standardized benchmark report to a file.
|
||||
Eliminates duplicate logic in CLI/Client code.
|
||||
"""
|
||||
formatted_steps = [
|
||||
{"name": name, "duration_ms": duration_ms}
|
||||
for name, duration_ms in timings.stages.items()
|
||||
]
|
||||
|
||||
report = {
|
||||
"timestamp": datetime.now(UTC).isoformat(),
|
||||
"request_id": timings.request_id,
|
||||
"commit_hash": get_git_commit_hash(),
|
||||
"tag": tag,
|
||||
"total_duration_ms": timings.total_duration_ms,
|
||||
"steps": formatted_steps,
|
||||
"meta": meta or {},
|
||||
}
|
||||
|
||||
try:
|
||||
abs_path = os.path.abspath(file_path)
|
||||
os.makedirs(os.path.dirname(abs_path), exist_ok=True)
|
||||
with open(abs_path, "w", encoding="utf-8") as f:
|
||||
json.dump(report, f, indent=2)
|
||||
print(f"[Performance] Metrics dumped to: {abs_path}")
|
||||
except IOError as e:
|
||||
print(f"[Performance] Failed to dump metrics to {abs_path}: {e}")
|
||||
logging.getLogger(__name__).error(f"Dump failed: {e}")
|
||||
|
||||
@classmethod
|
||||
def log_request_summary(
|
||||
cls,
|
||||
timings: "RequestTimings",
|
||||
tag: str = "total_inference_time",
|
||||
):
|
||||
"""logs the stage metrics and total duration for a completed request
|
||||
to the performance_log file.
|
||||
"""
|
||||
formatted_stages = [
|
||||
{"name": name, "execution_time_ms": duration_ms}
|
||||
for name, duration_ms in timings.stages.items()
|
||||
]
|
||||
|
||||
record = RequestPerfRecord(
|
||||
timings.request_id,
|
||||
commit_hash=get_git_commit_hash(),
|
||||
tag="pipeline_stage_metrics",
|
||||
stages=formatted_stages,
|
||||
steps=timings.steps,
|
||||
total_duration_ms=timings.total_duration_ms,
|
||||
)
|
||||
|
||||
try:
|
||||
log_dir = get_diffusion_perf_log_dir()
|
||||
if not os.path.exists(log_dir):
|
||||
os.makedirs(log_dir, exist_ok=True)
|
||||
|
||||
log_file = os.path.join(log_dir, "performance.log")
|
||||
|
||||
with open(log_file, "a", encoding="utf-8") as f:
|
||||
f.write(json.dumps(dataclasses.asdict(record)) + "\n")
|
||||
|
||||
except (OSError, PermissionError) as e:
|
||||
print(f"WARNING: Failed to log performance record: {e}", file=sys.stderr)
|
||||
@@ -1,204 +0,0 @@
|
||||
# Copied and adapted from: https://github.com/hao-ai-lab/FastVideo
|
||||
|
||||
import json
|
||||
import logging
|
||||
import os
|
||||
import subprocess
|
||||
import time
|
||||
from datetime import datetime
|
||||
from pathlib import Path
|
||||
from typing import Any
|
||||
|
||||
from dateutil.tz import UTC
|
||||
|
||||
import sglang
|
||||
|
||||
|
||||
def get_diffusion_perf_log_dir() -> str:
|
||||
"""
|
||||
Determines the directory for performance logs, centralizing the logic.
|
||||
|
||||
Resolution order:
|
||||
1. SGLANG_PERF_LOG_DIR environment variable, if set and not empty.
|
||||
2. Default to ~/.cache/sglang/logs if the environment variable is not set.
|
||||
3. Returns an empty string if SGLANG_PERF_LOG_DIR is set to an empty string,
|
||||
which effectively disables file logging.
|
||||
"""
|
||||
log_dir = os.environ.get("SGLANG_PERF_LOG_DIR")
|
||||
if log_dir:
|
||||
return os.path.abspath(log_dir)
|
||||
if log_dir is None:
|
||||
# Not set, use default
|
||||
sglang_path = Path(sglang.__file__).resolve()
|
||||
# .gitignore
|
||||
target_path = (sglang_path.parent / "../../.cache/logs").resolve()
|
||||
return str(target_path)
|
||||
# Is set, but is an empty string
|
||||
return ""
|
||||
|
||||
|
||||
LOG_DIR = get_diffusion_perf_log_dir()
|
||||
|
||||
# Configure a specific logger for performance metrics
|
||||
perf_logger = logging.getLogger("performance")
|
||||
perf_logger.setLevel(logging.INFO)
|
||||
perf_logger.propagate = False # Prevent perf logs from going to the main logger
|
||||
|
||||
_perf_logger_initialized = False
|
||||
|
||||
|
||||
class OnDemandFileHandler(logging.Handler):
|
||||
"""
|
||||
A logging handler that opens the file for each log record, writes, and closes it.
|
||||
This is less performant than FileHandler but avoids long-lived file handles,
|
||||
which can be problematic on certain filesystems like NFS.
|
||||
"""
|
||||
|
||||
def __init__(self, filename: str, mode: str = "a", encoding: str | None = None):
|
||||
super().__init__()
|
||||
self.baseFilename = os.path.abspath(filename)
|
||||
self.mode = mode
|
||||
self.encoding = encoding
|
||||
self.terminator = "\n"
|
||||
|
||||
def emit(self, record: logging.LogRecord):
|
||||
"""Emit a record."""
|
||||
try:
|
||||
msg = self.format(record)
|
||||
with open(
|
||||
self.baseFilename, self.mode, encoding=self.encoding, errors="replace"
|
||||
) as f:
|
||||
f.write(msg + self.terminator)
|
||||
except Exception:
|
||||
self.handleError(record)
|
||||
|
||||
|
||||
def _initialize_perf_logger():
|
||||
"""Initialize the performance logger with a file handler."""
|
||||
global _perf_logger_initialized
|
||||
if _perf_logger_initialized or not LOG_DIR:
|
||||
return
|
||||
|
||||
try:
|
||||
# Ensure the logs directory exists
|
||||
if not os.path.exists(LOG_DIR):
|
||||
os.makedirs(LOG_DIR)
|
||||
|
||||
# Set up a file handler for the performance logger
|
||||
handler = OnDemandFileHandler(os.path.join(LOG_DIR, "performance.log"))
|
||||
handler.setFormatter(logging.Formatter("%(message)s"))
|
||||
perf_logger.addHandler(handler)
|
||||
except (OSError, PermissionError) as e:
|
||||
perf_logger.warning(f"Failed to initialize performance logger: {e}")
|
||||
# Disable file logging if initialization fails
|
||||
globals()["LOG_DIR"] = ""
|
||||
finally:
|
||||
_perf_logger_initialized = True
|
||||
|
||||
|
||||
def get_git_commit_hash() -> str:
|
||||
"""Get the current git commit hash."""
|
||||
try:
|
||||
commit_hash = (
|
||||
subprocess.check_output(["git", "rev-parse", "HEAD"])
|
||||
.strip()
|
||||
.decode("utf-8")
|
||||
)
|
||||
return commit_hash
|
||||
except (subprocess.CalledProcessError, FileNotFoundError):
|
||||
return "N/A"
|
||||
|
||||
|
||||
class PerformanceLogger:
|
||||
"""
|
||||
A utility class for logging performance metrics.
|
||||
"""
|
||||
|
||||
def __init__(self, request_id: str):
|
||||
self.request_id = request_id
|
||||
self.start_time = time.monotonic()
|
||||
self.step_timings = []
|
||||
self.commit_hash = get_git_commit_hash()
|
||||
|
||||
def record_step_start(self):
|
||||
"""Records the start time of a step."""
|
||||
self.step_start_time = time.monotonic()
|
||||
|
||||
def record_step_end(self, step_name: str, step_index: int | None = None):
|
||||
"""Records the end time of a step and calculates the duration."""
|
||||
duration = time.monotonic() - self.step_start_time
|
||||
self.step_timings.append(
|
||||
{"name": step_name, "index": step_index, "duration_ms": duration * 1000}
|
||||
)
|
||||
|
||||
def log_total_duration(self, tag: str):
|
||||
"""Logs the total duration of the operation and all recorded steps."""
|
||||
_initialize_perf_logger()
|
||||
total_duration = time.monotonic() - self.start_time
|
||||
log_entry = {
|
||||
"timestamp": datetime.now(UTC).isoformat(),
|
||||
"request_id": self.request_id,
|
||||
"commit_hash": self.commit_hash,
|
||||
"tag": tag,
|
||||
"total_duration_ms": total_duration * 1000,
|
||||
"steps": self.step_timings,
|
||||
}
|
||||
perf_logger.info(json.dumps(log_entry))
|
||||
|
||||
def log_stage_metric(self, stage_name: str, duration_ms: float):
|
||||
"""Logs a single pipeline stage timing entry."""
|
||||
_initialize_perf_logger()
|
||||
log_entry = {
|
||||
"timestamp": datetime.now(UTC).isoformat(),
|
||||
"request_id": self.request_id,
|
||||
"commit_hash": self.commit_hash,
|
||||
"tag": "pipeline_stage_metric",
|
||||
"stage": stage_name,
|
||||
"duration_ms": duration_ms,
|
||||
}
|
||||
perf_logger.info(json.dumps(log_entry))
|
||||
|
||||
def log_stage_metrics(self, stages: Any):
|
||||
"""
|
||||
Persist per-stage execution stats to performance.log.
|
||||
|
||||
Args:
|
||||
stages: Either a PipelineLoggingInfo instance or any object exposing
|
||||
a mapping of stage metadata via a `stages` attribute/dict.
|
||||
"""
|
||||
_initialize_perf_logger()
|
||||
if stages is None:
|
||||
return
|
||||
|
||||
if hasattr(stages, "stages"):
|
||||
stage_items = getattr(stages, "stages", {}).items()
|
||||
elif isinstance(stages, dict):
|
||||
stage_items = stages.items()
|
||||
else:
|
||||
return
|
||||
|
||||
formatted_stages: list[dict[str, Any]] = []
|
||||
for name, info in stage_items:
|
||||
if not info:
|
||||
continue
|
||||
entry = {"name": name}
|
||||
execution_time = info.get("execution_time")
|
||||
if execution_time is not None:
|
||||
entry["execution_time_ms"] = execution_time * 1000
|
||||
for key, value in info.items():
|
||||
if key == "execution_time":
|
||||
continue
|
||||
entry[key] = value
|
||||
formatted_stages.append(entry)
|
||||
|
||||
if not formatted_stages:
|
||||
return
|
||||
|
||||
log_entry = {
|
||||
"timestamp": datetime.now(UTC).isoformat(),
|
||||
"request_id": self.request_id,
|
||||
"commit_hash": self.commit_hash,
|
||||
"tag": "pipeline_stage_metrics",
|
||||
"stages": formatted_stages,
|
||||
}
|
||||
perf_logger.info(json.dumps(log_entry))
|
||||
Reference in New Issue
Block a user