From ceac16fc6dd79d1ddf447b582534cb8ead0d9a89 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=94=90=E8=B1=AA=E6=9D=B0?= Date: Mon, 10 Feb 2025 16:43:00 +0800 Subject: [PATCH] test zj cost --- tf_adapter/kernels/geop_npu.cc | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/tf_adapter/kernels/geop_npu.cc b/tf_adapter/kernels/geop_npu.cc index 312e9e736..75aa10f54 100644 --- a/tf_adapter/kernels/geop_npu.cc +++ b/tf_adapter/kernels/geop_npu.cc @@ -90,6 +90,7 @@ Status FunctionalizeControlFlow(Graph *graph, FunctionLibraryDefinition *library Status FunctionalizeControlFlow(Graph *graph, FunctionLibraryDefinition *library); #endif namespace { +int64_t enter_ts, call_runasync_ts, end_ts; const std::string ATTR_NAME_CONST_INPUT_NAME = "_const_input"; const std::string kAutoRecompute = "auto"; const std::string kTotalStep = "TOTAL_STEP"; @@ -1144,6 +1145,7 @@ Status GeOp::RunGraph(OpKernelContext *ctx, const uint32_t &graph_id, << ", graph id: " << graph_id; int64_t run_start_time = InferShapeUtil::GetCurrentTimestap(); auto callback = [done, ctx, run_start_time, this](ge::Status ge_status, std::vector &outputs) { + int64_t callback_start_time = InferShapeUtil::GetCurrentTimestap(); ExitCallbackGuarder guarder([this] () { mutex_lock lock(graph_handler_.graph_mu); ADP_LOG(INFO) << "Callback end, run_num: " << graph_handler_.graph_run_num; @@ -1170,11 +1172,14 @@ Status GeOp::RunGraph(OpKernelContext *ctx, const uint32_t &graph_id, OP_REQUIRES_ASYNC(ctx, false, errors::Internal(ss.str()), done); } int64_t run_end_time = InferShapeUtil::GetCurrentTimestap(); - ADP_LOG(INFO) << "[GEOP] RunGraphAsync callback, status:" << ge_status - << ", kernel_name:" << ctx->op_kernel().name() << "[ " << (run_end_time - run_start_time) << "us]"; + ADP_LOG(EVENT) << "[GEOP] RunGraphAsync callback, status:" << ge_status + << ", kernel_name:" << ctx->op_kernel().name() << "[ " << (run_end_time - run_start_time) << "us], " + << "callback cost [ " << (run_end_time - callback_start_time) << "us], " << callback_start_time << " end time " + << run_end_time; done(); }; const std::string geop_name = ctx->op_kernel().name(); + call_runasync_ts = InferShapeUtil::GetCurrentTimestap(); ge::Status run_graph_status = ge_session_->RunGraphAsync(graph_id, inputs, callback); std::stringstream ss; if (run_graph_status != ge::SUCCESS) { @@ -1188,6 +1193,10 @@ Status GeOp::RunGraph(OpKernelContext *ctx, const uint32_t &graph_id, graph_handler_.graph_run_num++; ADP_LOG(INFO) << "End RunGraph: "<< geop_name << ", run_num: " << graph_handler_.graph_run_num; + end_ts = InferShapeUtil::GetCurrentTimestap(); + ADP_LOG(EVENT) << "TFA total cost "<< (end_ts - start_ts) << " before call ge rungraphasync cost " << (call_runasync_ts - start_ts) + << " call ge cost " << (end_ts - call_runasync_ts) << " start_ts " << start_ts + << " call_runasync_ts "<< call_runasync_ts << " end_ts " << end_ts; return Status::OK(); } @@ -1365,6 +1374,7 @@ bool GeOp::IsLazyCompile() { } void GeOp::ComputeAsync(OpKernelContext *ctx, DoneCallback done) { + enter_ts = InferShapeUtil::GetCurrentTimestap(); ADP_LOG(INFO) << "[GEOP] Begin GeOp::ComputeAsync, kernel_name: " << ctx->op_kernel().name(); int64_t start_time = InferShapeUtil::GetCurrentTimestap(); const std::string geop_name = ctx->op_kernel().name(); -- Gitee