diff --git a/onnxruntime/core/common/profiler.cc b/onnxruntime/core/common/profiler.cc index 18c46a994f..d8eb1b2354 100644 --- a/onnxruntime/core/common/profiler.cc +++ b/onnxruntime/core/common/profiler.cc @@ -72,6 +72,11 @@ std::string Profiler::EndProfiling() { profile_with_logger_ = false; return std::string(); } + + if (session_logger_) { + LOGS(*session_logger_, INFO) << "Writing profiler data to file " << profile_stream_file_; + } + std::lock_guard lock(mutex_); profile_stream_ << "[\n"; diff --git a/onnxruntime/core/common/profiler.h b/onnxruntime/core/common/profiler.h index 3e04962827..48ecf57474 100644 --- a/onnxruntime/core/common/profiler.h +++ b/onnxruntime/core/common/profiler.h @@ -44,7 +44,10 @@ class Profiler { */ TimePoint StartTime() const; - bool FEnabled() const { + /* + Whether data collection and output from this profiler is enabled. + */ + bool IsEnabled() const { return enabled_; } diff --git a/onnxruntime/core/framework/parallel_executor.cc b/onnxruntime/core/framework/parallel_executor.cc index dccdfc46d9..72ee80cd42 100644 --- a/onnxruntime/core/framework/parallel_executor.cc +++ b/onnxruntime/core/framework/parallel_executor.cc @@ -35,8 +35,8 @@ Status ParallelExecutor::Execute(const SessionState& session_state, const std::v const std::unordered_map& fetch_allocators, const logging::Logger& logger) { TimePoint tp; - bool f_profiler_enabled = session_state.Profiler().FEnabled(); - if (f_profiler_enabled) { + const bool is_profiler_enabled = session_state.Profiler().IsEnabled(); + if (is_profiler_enabled) { tp = session_state.Profiler().StartTime(); } @@ -102,7 +102,7 @@ Status ParallelExecutor::Execute(const SessionState& session_state, const std::v } } - if (f_profiler_enabled) { + if (is_profiler_enabled) { session_state.Profiler().EndTimeAndRecordEvent(profiling::SESSION_EVENT, "ParallelExecutor::Execute", tp); } @@ -121,7 +121,7 @@ Status ParallelExecutor::RunNodeAsync(size_t p_node_index, auto graph_viewer = session_state.GetGraphViewer(); TimePoint sync_time_begin; TimePoint kernel_begin_time; - bool f_profiler_enabled = session_state.Profiler().FEnabled(); + const bool f_profiler_enabled = session_state.Profiler().IsEnabled(); // Avoid context switching if possible. while (keep_running) { diff --git a/onnxruntime/core/framework/sequential_executor.cc b/onnxruntime/core/framework/sequential_executor.cc index 44425c4ec7..bd45bbfdc0 100644 --- a/onnxruntime/core/framework/sequential_executor.cc +++ b/onnxruntime/core/framework/sequential_executor.cc @@ -27,12 +27,12 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std: std::vector& fetches, const std::unordered_map& fetch_allocators, const logging::Logger& logger) { - bool f_profiler_enabled = session_state.Profiler().FEnabled(); + const bool is_profiler_enabled = session_state.Profiler().IsEnabled(); TimePoint tp; TimePoint sync_time_begin; TimePoint kernel_begin_time; - if (f_profiler_enabled) { + if (is_profiler_enabled) { tp = session_state.Profiler().StartTime(); } @@ -65,7 +65,7 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std: OpKernelContextInternal op_kernel_context(session_state, frame, *p_op_kernel, logger, p_op_kernel->Node().ImplicitInputDefs(), terminate_flag_); // TODO: log kernel outputs? - if (f_profiler_enabled) { + if (is_profiler_enabled) { sync_time_begin = session_state.Profiler().StartTime(); } @@ -104,7 +104,7 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std: utils::DumpNodeInputs(op_kernel_context, p_op_kernel->Node()); #endif - if (f_profiler_enabled) { + if (is_profiler_enabled) { session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, p_op_kernel->Node().Name() + "_fence_before", sync_time_begin, @@ -128,7 +128,7 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std: return Status(compute_status.Category(), compute_status.Code(), msg_string); } - if (f_profiler_enabled) { + if (is_profiler_enabled) { session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, p_op_kernel->Node().Name() + "_kernel_time", kernel_begin_time, @@ -159,7 +159,7 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std: } } - if (f_profiler_enabled) { + if (is_profiler_enabled) { session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, p_op_kernel->Node().Name() + "_fence_after", sync_time_begin, @@ -199,7 +199,7 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std: } } - if (f_profiler_enabled) { + if (is_profiler_enabled) { session_state.Profiler().EndTimeAndRecordEvent(profiling::SESSION_EVENT, "SequentialExecutor::Execute", tp); } diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 98cbb126cb..10ceef943a 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -220,7 +220,7 @@ common::Status InferenceSession::Load(std::function