From d58712b7fc8de0e1f87fe2ea5221bc3c85230ed3 Mon Sep 17 00:00:00 2001 From: "A. Unique TensorFlower" Date: Mon, 8 Oct 2018 18:12:42 -0700 Subject: Add a tracing::ScopedActivity event to track the duration of a Session::Run() call for better xprof tracing. Also annotate synchronous op execution with the session-run id (or step_id) as metadata leveraging the support introduced in cl/215985561. This should enable highlighting the duration of a Session::Run and all the ops that ran in it for visualizing latency regressions in the case of CPU inference. PiperOrigin-RevId: 216284682 --- tensorflow/core/common_runtime/direct_session.cc | 4 ++++ tensorflow/core/common_runtime/executor.cc | 12 ++++++++---- 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/tensorflow/core/common_runtime/direct_session.cc b/tensorflow/core/common_runtime/direct_session.cc index 458e133b68..52c1cd2691 100644 --- a/tensorflow/core/common_runtime/direct_session.cc +++ b/tensorflow/core/common_runtime/direct_session.cc @@ -64,6 +64,7 @@ limitations under the License. #include "tensorflow/core/platform/device_tracer.h" #include "tensorflow/core/platform/logging.h" #include "tensorflow/core/platform/mutex.h" +#include "tensorflow/core/platform/tracing.h" #include "tensorflow/core/platform/types.h" #include "tensorflow/core/util/device_name_utils.h" #include "tensorflow/core/util/env_var.h" @@ -453,6 +454,9 @@ Status DirectSession::RunInternal(int64 step_id, const RunOptions& run_options, CallFrameInterface* call_frame, ExecutorsAndKeys* executors_and_keys, RunMetadata* run_metadata) { + string session_id_meta = strings::StrCat("SessionRun #id=", step_id, "#"); + tracing::ScopedActivity activity(session_id_meta); + const int64 executor_step_count = executors_and_keys->step_count.fetch_add(1); std::unique_ptr debugger_state; diff --git a/tensorflow/core/common_runtime/executor.cc b/tensorflow/core/common_runtime/executor.cc index 40ec1502da..eb69d1991c 100644 --- a/tensorflow/core/common_runtime/executor.cc +++ b/tensorflow/core/common_runtime/executor.cc @@ -1771,14 +1771,18 @@ void ExecutorState::Process(TaggedNode tagged_node, int64 scheduled_nsec) { // The OpKernel may create child activities (such as GPU kernel // launches), so use a `ScopedAnnotation` to relate these activities // in the trace. - tracing::ScopedAnnotation activity(op_name, - op_kernel->type_string()); + tracing::ScopedAnnotation activity( + op_name, strings::StrCat(op_kernel->type_string(), + "#id=", step_id_, "#")); device->Compute(op_kernel, &ctx); } else { // Use the cheaper `ScopedActivity` to trace just the OpKernel // execution. - tracing::ScopedActivity activity(op_name, op_kernel->type_string(), - item.kernel_is_expensive); + tracing::ScopedActivity activity( + op_name, + strings::StrCat(op_kernel->type_string(), "#id=", step_id_, + "#"), + item.kernel_is_expensive); device->Compute(op_kernel, &ctx); } } else { -- cgit v1.2.3