diff --git a/docs/locales/zh_CN/LC_MESSAGES/references/profiling.po b/docs/locales/zh_CN/LC_MESSAGES/references/profiling.po index 35c313da08..d60a93c09c 100644 --- a/docs/locales/zh_CN/LC_MESSAGES/references/profiling.po +++ b/docs/locales/zh_CN/LC_MESSAGES/references/profiling.po @@ -59,19 +59,22 @@ msgstr "" #: ../../references/profiling.md:23 msgid "Service-Wide Timeline" -msgstr "" +msgstr "服务级 Timeline" #: ../../references/profiling.md:25 msgid "" "You may use start arg `--gen_timeline_sync` or specify env " -"`GEN_TIMELINE_SYNC=1` to enable service level timeline profiling. When " -"this option is used, every model request would generate a profiling " -"timeline." +"`GEN_TIMELINE_SYNC=1` to enable service level timeline profiling. This " +"captures a window of inference engine steps and saves the trace as a " +"perfetto-compatible JSON file." msgstr "" +"可以使用启动参数 `--gen_timeline_sync` 或环境变量 " +"`GEN_TIMELINE_SYNC=1` 开启服务级 timeline profiling。该方式会采集一段推理 " +"engine step 窗口，并将 trace 保存为 perfetto 兼容的 JSON 文件。" #: ../../references/profiling.md:27 msgid "How to visualize timeline" -msgstr "" +msgstr "如何可视化 timeline" #: ../../references/profiling.md:29 msgid "" diff --git a/docs/references/profiling.md b/docs/references/profiling.md index b80770e22b..357f4ae719 100644 --- a/docs/references/profiling.md +++ b/docs/references/profiling.md @@ -22,7 +22,7 @@ The generated timeline json file is located at the workdir where you started rtp ### Service-Wide Timeline -You may use start arg `--gen_timeline_sync` or specify env `GEN_TIMELINE_SYNC=1` to enable service level timeline profiling. When this option is used, every model request would generate a profiling timeline. +You may use start arg `--gen_timeline_sync` or specify env `GEN_TIMELINE_SYNC=1` to enable service level timeline profiling. This captures a window of inference engine steps and saves the trace as a perfetto-compatible JSON file. ### How to visualize timeline diff --git a/rtp_llm/cpp/config/ConfigModules.cc b/rtp_llm/cpp/config/ConfigModules.cc index cd776bd13d..0d95899850 100644 --- a/rtp_llm/cpp/config/ConfigModules.cc +++ b/rtp_llm/cpp/config/ConfigModules.cc @@ -144,6 +144,9 @@ std::string ProfilingDebugLoggingConfig::to_string() const { << "ft_core_dump_on_exception: " << ft_core_dump_on_exception << "\n" << "ft_alog_conf_path: " << ft_alog_conf_path << "\n" << "gen_timeline_sync: " << gen_timeline_sync << "\n" + << "timeline_start_step: " << timeline_start_step << "\n" + << "timeline_num_steps: " << timeline_num_steps << "\n" + << "timeline_trace_name: " << timeline_trace_name << "\n" << "torch_cuda_profiler_dir: " << torch_cuda_profiler_dir << "\n" << "log_file_backup_count: " << log_file_backup_count << "\n" << "debug_load_server: " << debug_load_server << "\n" diff --git a/rtp_llm/cpp/config/ConfigModules.h b/rtp_llm/cpp/config/ConfigModules.h index 0f4bbf1deb..25f7623847 100644 --- a/rtp_llm/cpp/config/ConfigModules.h +++ b/rtp_llm/cpp/config/ConfigModules.h @@ -200,6 +200,9 @@ struct ProfilingDebugLoggingConfig { bool ft_core_dump_on_exception = false; std::string ft_alog_conf_path = ""; bool gen_timeline_sync = false; + int timeline_start_step = 0; + int timeline_num_steps = 3; + std::string timeline_trace_name = "profiler"; std::string torch_cuda_profiler_dir = ""; int log_file_backup_count = 16; bool debug_load_server = false; diff --git a/rtp_llm/cpp/embedding_engine/EmbeddingEngine.cc b/rtp_llm/cpp/embedding_engine/EmbeddingEngine.cc index 98d3eed9bb..61459d864a 100644 --- a/rtp_llm/cpp/embedding_engine/EmbeddingEngine.cc +++ b/rtp_llm/cpp/embedding_engine/EmbeddingEngine.cc @@ -29,6 +29,7 @@ EmbeddingEngine::EmbeddingEngine(const EngineInitParams& params, py::object hand executor_.reset(new EmbeddingExecutor(params, handler)); scheduler_.reset( new EmbeddingScheduler(model_config_, concurrency_config, params.runtime_config, metrics_reporter_)); + step_profiler_.configureFromConfig(params.profiling_debug_logging_config); (void)startLoop(); } @@ -103,29 +104,32 @@ absl::Status EmbeddingEngine::step() { RTP_LLM_LOG_INFO("no query run and sleep"); return absl::OkStatus(); } - step_profiler_.tick(); - try { - auto status = executor_->process(streams); - if (!status.ok()) { + { + [[maybe_unused]] auto profile_step = step_profiler_.stepScope(); + try { + auto status = executor_->process(streams); + if (!status.ok()) { + for (auto& stream : streams) { + stream->setError(status.ToString()); + RTP_LLM_LOG_WARNING("error_stream_info: length: %d, exception: %s", + stream->inputLength(), + status.ToString().c_str()); + } + } + } catch (const exception& e) { + std::string error_msg = e.what(); + RTP_LLM_LOG_WARNING("run engine failed, stream size: %d, error: %s", streams.size(), error_msg.c_str()); for (auto& stream : streams) { - stream->setError(status.ToString()); - RTP_LLM_LOG_WARNING( - "error_stream_info: length: %d, exception: %s", stream->inputLength(), status.ToString().c_str()); + stream->setError(error_msg); + RTP_LLM_LOG_WARNING("error_stream_info: length: %d", stream->inputLength()); + } + if (error_msg.find("CUDA Driver error") != string::npos || error_msg.find("CUDA error") != string::npos) { + RTP_LLM_LOG_ERROR("detect CUDA error, do abort"); + abort(); } } - } catch (const exception& e) { - std::string error_msg = e.what(); - RTP_LLM_LOG_WARNING("run engine failed, stream size: %d, error: %s", streams.size(), error_msg.c_str()); - for (auto& stream : streams) { - stream->setError(error_msg); - RTP_LLM_LOG_WARNING("error_stream_info: length: %d", stream->inputLength()); - } - if (error_msg.find("CUDA Driver error") != string::npos || error_msg.find("CUDA error") != string::npos) { - RTP_LLM_LOG_ERROR("detect CUDA error, do abort"); - abort(); - } + cudaSyncAndCheck(); } - cudaSyncAndCheck(); return absl::OkStatus(); } diff --git a/rtp_llm/cpp/engine_base/TorchProfiler.cc b/rtp_llm/cpp/engine_base/TorchProfiler.cc index ac6746d463..7bccd7afa5 100644 --- a/rtp_llm/cpp/engine_base/TorchProfiler.cc +++ b/rtp_llm/cpp/engine_base/TorchProfiler.cc @@ -1,4 +1,5 @@ #include "rtp_llm/cpp/engine_base/TorchProfiler.h" +#include "rtp_llm/cpp/config/ConfigModules.h" #include "rtp_llm/cpp/utils/Logger.h" #include "autil/TimeUtility.h" #include @@ -91,6 +92,20 @@ void ProfilerSaveWorker::run() { StepWindowProfiler::StepWindowProfiler(const std::string& default_output_dir, int world_rank): default_output_dir_(default_output_dir.empty() ? "." : default_output_dir), world_rank_(world_rank) {} +StepWindowProfiler::StepScope::StepScope(StepWindowProfiler& profiler): profiler_(profiler) { + profiler_.beginStep(); +} + +StepWindowProfiler::StepScope::~StepScope() { + try { + profiler_.endStep(); + } catch (const std::exception& e) { + RTP_LLM_LOG_ERROR("timeline profiler endStep failed: %s", e.what()); + } catch (...) { + RTP_LLM_LOG_ERROR("timeline profiler endStep failed with unknown exception"); + } +} + void StepWindowProfiler::configure(bool enable, const std::string& trace_name, int start_step, int num_steps) { // First-come-first-served: if a profiling session is already active, ignore new requests // to prevent concurrent requests from repeatedly restarting the profiler. @@ -114,7 +129,14 @@ void StepWindowProfiler::configure(bool enable, const std::string& trace_name, i trace_name.c_str()); } -void StepWindowProfiler::tick() { +void StepWindowProfiler::configureFromConfig(const ProfilingDebugLoggingConfig& cfg) { + if (!cfg.gen_timeline_sync) { + return; + } + configure(true, cfg.timeline_trace_name, cfg.timeline_start_step, cfg.timeline_num_steps); +} + +void StepWindowProfiler::beginStep() { // Fast path: no profiling active and no profiler to clean up — zero cost if (!enabled_.load(std::memory_order_relaxed) && !has_profiler_.load(std::memory_order_relaxed)) { return; @@ -166,6 +188,22 @@ void StepWindowProfiler::tick() { prefix.c_str(), start_step_.load(), num_steps_.load()); + } +} + +void StepWindowProfiler::endStep() { + // Fast path: no profiling active and no profiler to clean up — zero cost + if (!enabled_.load(std::memory_order_relaxed) && !has_profiler_.load(std::memory_order_relaxed)) { + return; + } + + if (!enabled_.load(std::memory_order_relaxed)) { + stopProfiler("disabled"); + return; + } + + std::lock_guard lock(mu_); + if (!profiler_) { return; } diff --git a/rtp_llm/cpp/engine_base/TorchProfiler.h b/rtp_llm/cpp/engine_base/TorchProfiler.h index a354cc7036..ac4d70f5ff 100644 --- a/rtp_llm/cpp/engine_base/TorchProfiler.h +++ b/rtp_llm/cpp/engine_base/TorchProfiler.h @@ -13,6 +13,8 @@ namespace rtp_llm { namespace tpi = torch::profiler::impl; +struct ProfilingDebugLoggingConfig; + // Low-level profiler wrapper around Kineto. // IMPORTANT: start() and stop() MUST be called on the same thread (Kineto thread-affinity). class TorchProfile { @@ -68,44 +70,66 @@ class ProfilerSaveWorker { }; // Step-window profiler controlled via API (sglang-style). -// Thread-safe: configure() is called from gRPC thread, tick() from engine loop thread. -// The actual TorchProfile start/stop happens only inside tick(), satisfying Kineto thread-affinity. +// Thread-safe: configure() is called from gRPC thread, stepScope() from engine loop thread. +// The actual TorchProfile start/stop happens only inside engine step callbacks, satisfying Kineto thread-affinity. // Trace export is done asynchronously on a background thread to avoid blocking inference. class StepWindowProfiler { public: + // RAII guard that brackets a single engine step. Construct with stepScope() before + // process(), destruction after process() advances the profiler state machine. + // Strictly scope-bound: not movable, not copyable. + class StepScope { + public: + explicit StepScope(StepWindowProfiler& profiler); + ~StepScope(); + StepScope(const StepScope&) = delete; + StepScope& operator=(const StepScope&) = delete; + StepScope(StepScope&&) = delete; + StepScope& operator=(StepScope&&) = delete; + + private: + StepWindowProfiler& profiler_; + }; + explicit StepWindowProfiler(const std::string& default_output_dir = "", int world_rank = 0); ~StepWindowProfiler(); // Configure a profiling session. Safe to call from any thread (sets atomic state). - // The actual profiler start happens inside tick() (on the engine loop thread), - // satisfying Kineto thread-affinity. If a session is already active, this is a no-op - // (first-come-first-served). - // - // For in-step capture: the engine loop can call configure(start_step=0) and then - // tick() BEFORE process() to start the profiler before the work runs. + // The actual profiler start happens inside the next stepScope() (on the engine loop + // thread), satisfying Kineto thread-affinity. If a session is already active, this is + // a no-op (first-come-first-served). void configure(bool enable, const std::string& trace_name, int start_step, int num_steps); - // Called once per engine step() on the engine loop thread. - // Handles start/stop of the underlying TorchProfile based on step counts. - void tick(); + // Convenience overload: enable service-wide timeline profiling from config. + // No-op if cfg.gen_timeline_sync is false. + void configureFromConfig(const ProfilingDebugLoggingConfig& cfg); + + // Returns an RAII scope that wraps a single engine step. + StepScope stepScope() { + return StepScope(*this); + } bool enabled() const { return enabled_.load(std::memory_order_relaxed); } private: + friend class StepScope; + + void beginStep(); + void endStep(); void stopProfiler(const char* reason); std::string default_output_dir_; - // Atomic state set by configure(), read by tick() + // Atomic state set by configure(), read by beginStep()/endStep() std::atomic enabled_{false}; std::atomic reconfigure_{false}; std::atomic has_profiler_{false}; std::atomic start_step_{0}; std::atomic num_steps_{0}; - // State managed exclusively on the engine loop thread (inside tick/shutdown) + // State managed exclusively on the engine loop thread (inside begin/end/shutdown) std::mutex mu_; std::string trace_name_; std::shared_ptr profiler_; diff --git a/rtp_llm/cpp/normal_engine/NormalEngine.cc b/rtp_llm/cpp/normal_engine/NormalEngine.cc index 9ff9caa273..6effed3d6d 100644 --- a/rtp_llm/cpp/normal_engine/NormalEngine.cc +++ b/rtp_llm/cpp/normal_engine/NormalEngine.cc @@ -112,6 +112,7 @@ NormalEngine::NormalEngine(const EngineInitParams& params, releaseHostMemoryCache(); initScheduler(); + step_profiler_.configureFromConfig(profiling_debug_logging_config); (void)startLoop(); } @@ -461,31 +462,24 @@ absl::Status NormalEngine::step() { int64_t step_begin_time_us = autil::TimeUtility::currentTimeInMicroSeconds(); absl::Status status = absl::OkStatus(); - // If any stream in this batch requested gen_timeline AND no profiling session is - // already active, configure + tick BEFORE process() so the profiler is up before - // the actual work runs. This guarantees the trace captures THIS step's work, not - // the next step's. If a session is already active (e.g. external StartProfile RPC), - // skip — first-come-first-served. + // Per-request timeline: if any stream requested gen_timeline and no session is + // active yet, configure the profiler so the next stepScope() captures THIS step. if (!step_profiler_.enabled()) { for (const auto& stream : streams) { if (stream && stream->genTimeline()) { const auto& cfg = stream->generateConfig(); step_profiler_.configure(true, cfg->profile_trace_name, 0, cfg->profile_step); - step_profiler_.tick(); // start profiler now (start_step=0) break; } } } { + [[maybe_unused]] auto profile_step = step_profiler_.stepScope(); RTP_LLM_PROFILE_SCOPE_DYNAMIC("engine.normal.execute(stream_size=%zu)", streams.size()); status = executor_->process(streams); } - // tick profiler after process() to count this step (and stop when num_steps reached). - // All TP ranks synchronize inside process() via NCCL, so stop happens at aligned points. - step_profiler_.tick(); - // report step metrics if (parallelism_config.tp_rank == 0) { RTP_LLM_PROFILE_SCOPE("engine.normal.report_metrics_work"); diff --git a/rtp_llm/cpp/pybind/ConfigInit.cc b/rtp_llm/cpp/pybind/ConfigInit.cc index 66d31fb189..1c49b9912b 100644 --- a/rtp_llm/cpp/pybind/ConfigInit.cc +++ b/rtp_llm/cpp/pybind/ConfigInit.cc @@ -510,6 +510,9 @@ PYBIND11_MODULE(libth_transformer_config, m) { .def_readwrite("ft_core_dump_on_exception", &ProfilingDebugLoggingConfig::ft_core_dump_on_exception) .def_readwrite("ft_alog_conf_path", &ProfilingDebugLoggingConfig::ft_alog_conf_path) .def_readwrite("gen_timeline_sync", &ProfilingDebugLoggingConfig::gen_timeline_sync) + .def_readwrite("timeline_start_step", &ProfilingDebugLoggingConfig::timeline_start_step) + .def_readwrite("timeline_num_steps", &ProfilingDebugLoggingConfig::timeline_num_steps) + .def_readwrite("timeline_trace_name", &ProfilingDebugLoggingConfig::timeline_trace_name) .def_readwrite("torch_cuda_profiler_dir", &ProfilingDebugLoggingConfig::torch_cuda_profiler_dir) .def_readwrite("log_file_backup_count", &ProfilingDebugLoggingConfig::log_file_backup_count) .def_readwrite("debug_load_server", &ProfilingDebugLoggingConfig::debug_load_server) @@ -525,6 +528,9 @@ PYBIND11_MODULE(libth_transformer_config, m) { self.ft_core_dump_on_exception, self.ft_alog_conf_path, self.gen_timeline_sync, + self.timeline_start_step, + self.timeline_num_steps, + self.timeline_trace_name, self.torch_cuda_profiler_dir, self.log_file_backup_count, self.debug_load_server, @@ -534,7 +540,7 @@ PYBIND11_MODULE(libth_transformer_config, m) { self.check_nan); }, [](py::tuple t) { - if (t.size() != 12) + if (t.size() != 12 && t.size() != 15) throw std::runtime_error("Invalid state!"); ProfilingDebugLoggingConfig c; @@ -544,13 +550,26 @@ PYBIND11_MODULE(libth_transformer_config, m) { c.ft_core_dump_on_exception = t[2].cast(); c.ft_alog_conf_path = t[3].cast(); c.gen_timeline_sync = t[4].cast(); - c.torch_cuda_profiler_dir = t[5].cast(); - c.log_file_backup_count = t[6].cast(); - c.debug_load_server = t[7].cast(); - c.hack_layer_num = t[8].cast(); - c.debug_start_fake_process = t[9].cast(); - c.enable_detail_log = t[10].cast(); - c.check_nan = t[11].cast(); + if (t.size() == 12) { + c.torch_cuda_profiler_dir = t[5].cast(); + c.log_file_backup_count = t[6].cast(); + c.debug_load_server = t[7].cast(); + c.hack_layer_num = t[8].cast(); + c.debug_start_fake_process = t[9].cast(); + c.enable_detail_log = t[10].cast(); + c.check_nan = t[11].cast(); + } else { + c.timeline_start_step = t[5].cast(); + c.timeline_num_steps = t[6].cast(); + c.timeline_trace_name = t[7].cast(); + c.torch_cuda_profiler_dir = t[8].cast(); + c.log_file_backup_count = t[9].cast(); + c.debug_load_server = t[10].cast(); + c.hack_layer_num = t[11].cast(); + c.debug_start_fake_process = t[12].cast(); + c.enable_detail_log = t[13].cast(); + c.check_nan = t[14].cast(); + } } catch (const std::exception& e) { throw std::runtime_error(std::string("ProfilingDebugLoggingConfig unpickle error: ") + e.what()); } diff --git a/rtp_llm/ops/libth_transformer_config.pyi b/rtp_llm/ops/libth_transformer_config.pyi index 0ece9995c0..48f5380aec 100644 --- a/rtp_llm/ops/libth_transformer_config.pyi +++ b/rtp_llm/ops/libth_transformer_config.pyi @@ -1150,6 +1150,9 @@ class ProfilingDebugLoggingConfig: gen_timeline_sync: bool hack_layer_num: int log_file_backup_count: int + timeline_num_steps: int + timeline_start_step: int + timeline_trace_name: str torch_cuda_profiler_dir: str trace_memory: bool def __getstate__(self) -> tuple: diff --git a/rtp_llm/server/server_args/profile_debug_logging_group_args.py b/rtp_llm/server/server_args/profile_debug_logging_group_args.py index 9d3096e8ee..041fe87c72 100644 --- a/rtp_llm/server/server_args/profile_debug_logging_group_args.py +++ b/rtp_llm/server/server_args/profile_debug_logging_group_args.py @@ -48,6 +48,30 @@ def init_profile_debug_logging_group_args(parser, profiling_debug_config): default=False, help="是否开启收集Timeline信息用于性能分析", ) + profile_debug_logging_group.add_argument( + "--gen_timeline_start_step", + env_name="GEN_TIMELINE_START_STEP", + bind_to=(profiling_debug_config, "timeline_start_step"), + type=int, + default=0, + help="Timeline采集跳过前N步(warmup)，从第N+1步开始", + ) + profile_debug_logging_group.add_argument( + "--gen_timeline_num_steps", + env_name="GEN_TIMELINE_NUM_STEPS", + bind_to=(profiling_debug_config, "timeline_num_steps"), + type=int, + default=3, + help="Timeline采集步数，采集N步后自动停止并保存", + ) + profile_debug_logging_group.add_argument( + "--gen_timeline_trace_name", + env_name="GEN_TIMELINE_TRACE_NAME", + bind_to=(profiling_debug_config, "timeline_trace_name"), + type=str, + default="profiler", + help="Timeline输出文件名前缀", + ) profile_debug_logging_group.add_argument( "--torch_cuda_profiler_dir", env_name="TORCH_CUDA_PROFILER_DIR",