diff --git a/onnxruntime/core/common/profiler.cc b/onnxruntime/core/common/profiler.cc index 5c4384c5a3..30fdb0d581 100644 --- a/onnxruntime/core/common/profiler.cc +++ b/onnxruntime/core/common/profiler.cc @@ -18,6 +18,7 @@ void Profiler::Initialize(const logging::Logger* session_logger) { void Profiler::StartProfiling(const logging::Logger* custom_logger) { ORT_ENFORCE(custom_logger != nullptr); + enabled_ = true; profile_with_logger_ = true; custom_logger_ = custom_logger; profiling_start_time_ = StartTime(); @@ -35,13 +36,11 @@ void Profiler::EndTimeAndRecordEvent(EventCategory category, TimePoint& start_time, const std::initializer_list>& event_args, bool /*sync_gpu*/) { - if (!enabled_ && !profile_with_logger_) - return; long long dur = TimeDiffMicroSeconds(start_time); long long ts = TimeDiffMicroSeconds(profiling_start_time_, start_time); EventRecord event(category, logging::GetProcessId(), - logging::GetThreadId(), event_name, ts, dur, { event_args.begin(), event_args.end() }); + logging::GetThreadId(), event_name, ts, dur, {event_args.begin(), event_args.end()}); if (profile_with_logger_) { custom_logger_->SendProfileEvent(event); } else { @@ -99,12 +98,5 @@ std::string Profiler::EndProfiling() { return profile_stream_file_; } -// -// Conditionally sync the GPU if the syncGPU flag is set. -// -void ProfilerSyncGpu() { - ORT_NOT_IMPLEMENTED("Needs to implement only for gpus"); -} - } // namespace profiling } // namespace onnxruntime diff --git a/onnxruntime/core/common/profiler.h b/onnxruntime/core/common/profiler.h index 36c7655973..f743c0a531 100644 --- a/onnxruntime/core/common/profiler.h +++ b/onnxruntime/core/common/profiler.h @@ -40,6 +40,10 @@ class Profiler { */ TimePoint StartTime() const; + bool FEnabled() const { + return enabled_; + } + /* Record a single event. Time is measured till the call of this function from the start_time. diff --git a/onnxruntime/core/framework/parallel_executor.cc b/onnxruntime/core/framework/parallel_executor.cc index 98b8495a4d..a8033948ae 100644 --- a/onnxruntime/core/framework/parallel_executor.cc +++ b/onnxruntime/core/framework/parallel_executor.cc @@ -31,7 +31,11 @@ Status ParallelExecutor::Execute(const SessionState& session_state, const std::vector& output_names, std::vector& fetches, const logging::Logger& logger) { - auto tp = session_state.Profiler().StartTime(); + TimePoint tp; + bool f_profiler_enabled = session_state.Profiler().FEnabled(); + if (f_profiler_enabled) { + tp = session_state.Profiler().StartTime(); + } root_frame_ = std::make_unique(feeds, output_names, fetches, session_state); //std::cout << "start nodes:" << std::endl; @@ -72,7 +76,9 @@ Status ParallelExecutor::Execute(const SessionState& session_state, } } - session_state.Profiler().EndTimeAndRecordEvent(profiling::SESSION_EVENT, "ParallelExecutor::Execute", tp); + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::SESSION_EVENT, "ParallelExecutor::Execute", tp); + } return Status::OK(); } @@ -83,7 +89,7 @@ void ParallelExecutor::RunNodeAsync(size_t p_node_index, RunNodeAsyncInternal(p_node_index, session_state, logger); } catch (...) { FinishNodeRun(); - throw; + throw; } } @@ -95,6 +101,9 @@ void ParallelExecutor::RunNodeAsyncInternal(size_t p_node_index, size_t node_index = p_node_index; bool keep_running = true; auto graph_viewer = session_state.GetGraphViewer(); + TimePoint sync_time_begin; + TimePoint kernel_begin_time; + bool f_profiler_enabled = session_state.Profiler().FEnabled(); // Avoid context switching if possible. while (keep_running) { // TODO: Convert RunNodeAsync return Status. @@ -109,14 +118,16 @@ void ParallelExecutor::RunNodeAsyncInternal(size_t p_node_index, // if a kernel has been added in the session state, it better be NON-null. if (p_op_kernel == nullptr) { ORT_THROW("Got nullptr from GetKernel for node: ", - graph_viewer->GetNode(node_index)->Name()); + graph_viewer->GetNode(node_index)->Name()); } OpKernelContextInternal op_kernel_context(*root_frame_, *p_op_kernel, logger, p_op_kernel->Node().ImplicitInputDefs(), terminate_flag_); - auto sync_time_begin = session_state.Profiler().StartTime(); + if (f_profiler_enabled) { + sync_time_begin = session_state.Profiler().StartTime(); + } // sync before compute int queue_id = p_op_kernel->KernelDef().ExecQueueId(); @@ -141,31 +152,31 @@ void ParallelExecutor::RunNodeAsyncInternal(size_t p_node_index, } } - const std::string& node_name = p_op_kernel->Node().Name(); - const std::string& op_name = p_op_kernel->KernelDef().OpName(); + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, + p_op_kernel->Node().Name() + "_fence_before", + sync_time_begin, + {{"op_name", p_op_kernel->KernelDef().OpName()}}); - session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, - node_name + "_fence_before", - sync_time_begin, - {{"op_name", op_name}}); + kernel_begin_time = session_state.Profiler().StartTime(); + } // call compute on the kernel VLOGS(logger, 1) << "Computing kernel: " << p_op_kernel->Node().Name(); - auto kernel_begin_time = session_state.Profiler().StartTime(); - // Execute the kernel. auto status = p_op_kernel->Compute(&op_kernel_context); if (!status.IsOK()) { ORT_THROW("Compute failed for node: ", graph_viewer->GetNode(node_index)->Name()); } + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, + p_op_kernel->Node().Name() + "_kernel_time", + kernel_begin_time, + {{"op_name", p_op_kernel->KernelDef().OpName()}}); - session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, - node_name + "_kernel_time", - kernel_begin_time, - {{"op_name", op_name}}); - - sync_time_begin = session_state.Profiler().StartTime(); + sync_time_begin = session_state.Profiler().StartTime(); + } // sync after compute for outputs for (int input_index = 0; input_index < op_kernel_context.InputCount(); ++input_index) { Fence_t fence = op_kernel_context.InputFence(input_index); @@ -187,11 +198,12 @@ void ParallelExecutor::RunNodeAsyncInternal(size_t p_node_index, fence->AfterUsedAsOutput(queue_id); } } - session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, - node_name + "_fence_after", - sync_time_begin, - {{"op_name", op_name}}); - + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, + p_op_kernel->Node().Name() + "_fence_after", + sync_time_begin, + {{"op_name", p_op_kernel->KernelDef().OpName()}}); + } //std::cout << "Run async node finish: " << p_node_index << std::endl; keep_running = false; @@ -241,8 +253,8 @@ Status ParallelExecutor::FetchOutput(const MLValueNameIdxMap& name_idx_map, } else { // this should've been checked before already ORT_ENFORCE(output_names.size() == fetches.size(), - "output_names vector size: " + std::to_string(output_names.size()) + - " does not match that of fetches vector: " + std::to_string(fetches.size())); + "output_names vector size: " + std::to_string(output_names.size()) + + " does not match that of fetches vector: " + std::to_string(fetches.size())); } auto idx = 0; diff --git a/onnxruntime/core/framework/sequential_executor.cc b/onnxruntime/core/framework/sequential_executor.cc index a5d704a0b0..d465279104 100644 --- a/onnxruntime/core/framework/sequential_executor.cc +++ b/onnxruntime/core/framework/sequential_executor.cc @@ -31,7 +31,14 @@ Status SequentialExecutor::Execute(const SessionState& session_state, const std::vector& output_names, std::vector& fetches, const logging::Logger& logger) { - auto tp = session_state.Profiler().StartTime(); + bool f_profiler_enabled = session_state.Profiler().FEnabled(); + TimePoint tp; + TimePoint sync_time_begin; + TimePoint kernel_begin_time; + + if (f_profiler_enabled) { + tp = session_state.Profiler().StartTime(); + } ExecutionFrame frame{feeds, output_names, fetches, session_state}; @@ -55,17 +62,17 @@ Status SequentialExecutor::Execute(const SessionState& session_state, // if a kernel has been added in the session state, it better be NON-null. if (p_op_kernel == nullptr) return ORT_MAKE_STATUS(ONNXRUNTIME, FAIL, "Got nullptr from GetKernel for node: ", - session_state.GetGraphViewer()->GetNode(node_index)->Name()); + session_state.GetGraphViewer()->GetNode(node_index)->Name()); - const std::string& node_name = p_op_kernel->Node().Name(); - const std::string& op_name = p_op_kernel->KernelDef().OpName(); // construct OpKernelContext // TODO: log kernel inputs? OpKernelContextInternal op_kernel_context(frame, *p_op_kernel, logger, p_op_kernel->Node().ImplicitInputDefs(), terminate_flag_); // TODO: log kernel outputs? + if (f_profiler_enabled) { + sync_time_begin = session_state.Profiler().StartTime(); + } - auto sync_time_begin = session_state.Profiler().StartTime(); // sync before compute int queue_id = p_op_kernel->KernelDef().ExecQueueId(); for (int input_index = 0; input_index < op_kernel_context.InputCount(); ++input_index) { @@ -89,22 +96,28 @@ Status SequentialExecutor::Execute(const SessionState& session_state, } } - session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, - node_name + "_fence_before", - sync_time_begin, - {{"op_name", op_name}}); + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, + p_op_kernel->Node().Name() + "_fence_before", + sync_time_begin, + {{"op_name", p_op_kernel->KernelDef().OpName()}}); - // call compute on the kernel - VLOGS(logger, 1) << "Computing kernel: " << p_op_kernel->Node().Name(); + // call compute on the kernel + VLOGS(logger, 1) << "Computing kernel: " << p_op_kernel->Node().Name(); - auto kernel_begin_time = session_state.Profiler().StartTime(); + kernel_begin_time = session_state.Profiler().StartTime(); + } ORT_RETURN_IF_ERROR(p_op_kernel->Compute(&op_kernel_context)); - session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, - node_name + "_kernel_time", - kernel_begin_time, - {{"op_name", op_name}}); - sync_time_begin = session_state.Profiler().StartTime(); + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, + p_op_kernel->Node().Name() + "_kernel_time", + kernel_begin_time, + {{"op_name", p_op_kernel->KernelDef().OpName()}}); + + sync_time_begin = session_state.Profiler().StartTime(); + } + // sync after compute for outputs for (int input_index = 0; input_index < op_kernel_context.InputCount(); ++input_index) { Fence_t fence = op_kernel_context.InputFence(input_index); @@ -126,10 +139,13 @@ Status SequentialExecutor::Execute(const SessionState& session_state, fence->AfterUsedAsOutput(queue_id); } } - session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, - node_name + "_fence_after", - sync_time_begin, - {{"op_name", op_name}}); + + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::NODE_EVENT, + p_op_kernel->Node().Name() + "_fence_after", + sync_time_begin, + {{"op_name", p_op_kernel->KernelDef().OpName()}}); + } // free ml-values corresponding to this node VLOGS(logger, 1) << "Releasing node ML values after computing kernel: " << p_op_kernel->Node().Name(); @@ -158,7 +174,10 @@ Status SequentialExecutor::Execute(const SessionState& session_state, } } - session_state.Profiler().EndTimeAndRecordEvent(profiling::SESSION_EVENT, "SequentialExecutor::Execute", tp); + if (f_profiler_enabled) { + session_state.Profiler().EndTimeAndRecordEvent(profiling::SESSION_EVENT, "SequentialExecutor::Execute", tp); + } + return Status::OK(); } @@ -172,8 +191,8 @@ static Status FetchOutput(const MLValueNameIdxMap& name_idx_map, } else { // this should've been checked before already ORT_ENFORCE(output_names.size() == fetches.size(), - "output_names vector size: " + std::to_string(output_names.size()) + - " does not match that of fetches vector: " + std::to_string(fetches.size())); + "output_names vector size: " + std::to_string(output_names.size()) + + " does not match that of fetches vector: " + std::to_string(fetches.size())); } auto idx = 0; diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index f61cd61122..f85f177623 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -145,7 +145,9 @@ class InferenceSession::Impl { LOGS(*session_logger_, ERROR) << "Unknown exception in Load()"; return Status(common::ONNXRUNTIME, common::RUNTIME_EXCEPTION, "Encountered unknown exception in Load()"); } - session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_uri", tp); + if (session_profiler_.FEnabled()) { + session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_uri", tp); + } return common::Status::OK(); } @@ -176,7 +178,9 @@ class InferenceSession::Impl { LOGS(*session_logger_, ERROR) << "Unknown exception in Load()"; return Status(common::ONNXRUNTIME, common::RUNTIME_EXCEPTION, "Encountered unknown exception in Load()"); } - session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_proto", tp); + if (session_profiler_.FEnabled()) { + session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_proto", tp); + } return Status::OK(); } @@ -207,7 +211,9 @@ class InferenceSession::Impl { LOGS(*session_logger_, ERROR) << "Unknown exception in Load()"; return Status(common::ONNXRUNTIME, common::RUNTIME_EXCEPTION, "Encountered unknown exception in Load()"); } - session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_proto", tp); + if (session_profiler_.FEnabled()) { + session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_proto", tp); + } return Status::OK(); } @@ -244,7 +250,9 @@ class InferenceSession::Impl { LOGS(*session_logger_, ERROR) << "Unknown exception in Load()"; return Status(common::ONNXRUNTIME, common::RUNTIME_EXCEPTION, "Encountered unknown exception in Load()"); } - session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_istream", tp); + if (session_profiler_.FEnabled()) { + session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_loading_istream", tp); + } return common::Status::OK(); } @@ -419,7 +427,9 @@ class InferenceSession::Impl { LOGS(*session_logger_, ERROR) << status.ErrorMessage(); } - session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "session_initialization", tp); + if (session_profiler_.FEnabled()) { + session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "session_initialization", tp); + } return status; } @@ -841,7 +851,9 @@ class InferenceSession::Impl { ORT_CHECK_AND_SET_RETVAL(xp->OnRunEnd()); --current_num_runs_; - session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_run", tp); + if (session_profiler_.FEnabled()) { + session_profiler_.EndTimeAndRecordEvent(profiling::SESSION_EVENT, "model_run", tp); + } return retval; }