From efb59247953f3062ba25e98f9ba04dff5ca47c0a Mon Sep 17 00:00:00 2001 From: unknown Date: Sat, 20 Mar 2021 10:49:33 +0800 Subject: [PATCH 01/13] For step profiling. --- ge/graph/load/model_manager/davinci_model.cc | 64 +++++++++++++++++++ ge/graph/load/model_manager/davinci_model.h | 2 + ge/hybrid/executor/hybrid_model_executor.cc | 64 +++++++++++++++++++ ge/hybrid/executor/hybrid_model_executor.h | 2 + tests/depends/runtime/src/runtime_stub.cc | 2 + tests/ut/ge/CMakeLists.txt | 1 + .../ge/graph/load/davinci_model_unittest.cc | 6 ++ tests/ut/ge/hybrid/ge_hybrid_unittest.cc | 17 ++++- third_party/fwkacllib/inc/runtime/base.h | 6 ++ 9 files changed, 163 insertions(+), 1 deletion(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index c053ad63..14c48014 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -111,6 +111,9 @@ const char *const kWorkSpaceSize = "workspace_size"; const char *const kTotalSize = "total_size"; const char *const kTaskCount = "task_count"; const char *const kTaskId = "task_id"; +const char *const kIndexId = "index_id"; +const char *const kTimeStamp = "time_stamp"; +const char *const kTagId = "tag_id"; const char* const kRequestId = "request_id"; const char* const kThreadId = "thread_id"; const char* const kInputBeginTime = "input_begin_time"; @@ -2305,6 +2308,59 @@ Status DavinciModel::SinkTimeProfile(const InputData ¤t_data) { return SUCCESS; } +Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { + auto &prof_mgr = ProfilingManager::Instance(); + if (prof_mgr.ProfilingModelExecuteOn()) { + uint64_t index_id = model->iterator_count_ + 1; + uint64_t model_id = static_cast(model->Id()); + rtStream_t stream = model->rt_model_stream_; + GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", + index_id, model_id, tag_id); + rtError_t rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream); + if (rt_ret != RT_ERROR_NONE) { + GELOGE(RT_FAILED, "[Call][rtProfilerTraceEx] failed, ret: 0x%X", rt_ret); + return RT_ERROR_TO_GE_STATUS(rt_ret); + } + GELOGD("Profiling Step Info TraceTask execute async success, index_id = %lu, model_id = %lu, tag_id = %u", + index_id, model_id, tag_id); + + mmTimespec timespec = mmGetTickCount(); + // 1000 ^ 3 converts second to nanosecond + int64_t time = timespec.tv_sec * 1000 * 1000 * 1000 + timespec.tv_nsec; + uint32_t task_id = 0; + uint32_t stream_id = 0; + rt_ret = rtGetTaskIdAndStreamID(&task_id, &stream_id); + if (rt_ret != RT_ERROR_NONE) { + GELOGE(RT_FAILED, "[Get][RtsInfo] task_id and stream_id failed, ret: 0x%X.", rt_ret); + return RT_ERROR_TO_GE_STATUS(rt_ret); + } + GELOGD("Get profiling args, task_id[%u], stream_id[%u]", task_id, stream_id); + uint32_t device_id = model->GetDeviceId(); + + Json step_info; + step_info[kIndexId] = index_id; + step_info[kModeleId] = model_id; + step_info[kTimeStamp] = time; + step_info[kTagId] = tag_id; + step_info[kTaskId] = task_id; + step_info[kStreamId] = stream_id; + step_info[kThreadId] = mmGetTid(); + + std::string reported_data; + try { + reported_data = step_info.dump(kInteval, ' ', false, Json::error_handler_t::ignore); + } catch (std::exception &e) { + GELOGE(FAILED, "Failed to convert JSON to string, reason: %s.", e.what()); + } catch (...) { + GELOGE(FAILED, "Failed to convert JSON to string."); + } + reported_data.append(",") + .append("\n"); + prof_mgr.ReportData(device_id, reported_data, "step_info"); + } + return SUCCESS; +} + void DavinciModel::SetProfileTime(ModelProcStage stage, int64_t endTime) { int64_t time = endTime; @@ -2599,6 +2655,8 @@ void *DavinciModel::Run(DavinciModel *model) { GELOGI("data_wrapper is null!"); continue; } + // tag_id 0 means step begin, 1 meas step end. + (void)DavinciModel::ProfileStepInfo(model, 0); GELOGI("Getting the input data, model_id:%u", model_id); GE_IF_BOOL_EXEC(!model->RunFlag(), break); @@ -2678,6 +2736,8 @@ void *DavinciModel::Run(DavinciModel *model) { GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), model->SetProfileTime(MODEL_AFTER_PROC_END)); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), (void)model->SinkTimeProfile(current_data)); + // tag_id 0 means step begin, 1 meas step end. + (void)DavinciModel::ProfileStepInfo(model, 1); model->iterator_count_++; model->is_first_execute_ = false; @@ -3691,6 +3751,8 @@ Status DavinciModel::NnExecute(rtStream_t stream, bool async_mode, const InputDa GELOGD("current_data.index=%u", input_data.index); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_PRE_PROC_END)); + // tag_id 0 means step begin, 1 meas step end. + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 0)); if (!task_list_.empty()) { GELOGD("rtModelExecute do"); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_INFER_START)); @@ -3698,7 +3760,9 @@ Status DavinciModel::NnExecute(rtStream_t stream, bool async_mode, const InputDa GE_CHK_RT_EXEC(rt_ret, return RT_ERROR_TO_GE_STATUS(rt_ret)); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_INFER_END)); GELOGD("rtModelExecute end"); + iterator_count_++; } + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 1)); if (!is_async_mode_) { GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_AFTER_PROC_START)); diff --git a/ge/graph/load/model_manager/davinci_model.h b/ge/graph/load/model_manager/davinci_model.h index 58478b0f..1adeb1cc 100755 --- a/ge/graph/load/model_manager/davinci_model.h +++ b/ge/graph/load/model_manager/davinci_model.h @@ -878,6 +878,8 @@ class DavinciModel { Status GetRealOutputSizeOfCase(const ComputeGraphPtr &graph, size_t input_index, const NodePtr &case_node); Status GetGearAndRealOutShapeInfo(const ComputeGraphPtr &graph, const NodePtr &node); + static Status ProfileStepInfo(DavinciModel *model, uint16_t tag_id); + bool is_weight_mem_has_inited_; bool is_feature_map_mem_has_inited_; diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index 4b589a03..ad295abf 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -18,12 +18,22 @@ #include "graph/ge_context.h" #include "graph/runtime_inference_context.h" #include "common/dump/dump_manager.h" +#include "common/profiling/profiling_manager.h" +#include "mmpa/mmpa_api.h" namespace ge { namespace hybrid { namespace { const int kIntBase = 10; const char *const kEnvProfilingLevel = "HYBRID_PROFILING_LEVEL"; +const char *const kIndexId = "index_id"; +const char *const kModeleId = "model_id"; +const char *const kTimeStamp = "time_stamp"; +const char *const kStreamId = "stream_id"; +const char *const kTaskId = "task_id"; +const char *const kTagId = "tag_id"; +const char *const kThreadId = "thread_id"; +const uint32_t kInteval = 2; } // namespace HybridModelExecutor::HybridModelExecutor(HybridModel *model, uint32_t device_id, rtStream_t stream) : model_(model), device_id_(device_id), stream_(stream) { @@ -71,15 +81,69 @@ Status HybridModelExecutor::Execute(HybridModelExecutor::ExecuteArgs &args) { return SUCCESS; } +Status HybridModelExecutor::ProfileStepInfo(uint16_t tag_id) { + auto &prof_mgr = ProfilingManager::Instance(); + if (prof_mgr.ProfilingModelExecuteOn()) { + uint64_t index_id = context_.iteration + 1; + uint64_t model_id = static_cast(model_->GetModelId()); + GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", + index_id, model_id, tag_id); + rtError_t rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream_); + if (rt_ret != RT_ERROR_NONE) { + GELOGE(RT_FAILED, "[Call][rtProfilerTraceEx] failed, ret: 0x%X", rt_ret); + return RT_ERROR_TO_GE_STATUS(rt_ret); + } + GELOGD("Profiling Step Info TraceTask execute async success. index_id = %lu, model_id = %u, tag_id = %u", + index_id, model_id, tag_id); + + mmTimespec timespec = mmGetTickCount(); + // 1000 ^ 3 converts second to nanosecond + int64_t time = timespec.tv_sec * 1000 * 1000 * 1000 + timespec.tv_nsec; + uint32_t task_id = 0; + uint32_t stream_id = 0; + rt_ret = rtGetTaskIdAndStreamID(&task_id, &stream_id); + if (rt_ret != RT_ERROR_NONE) { + GELOGE(RT_FAILED, "[Get][RtsInfo] task_id and stream_id failed, ret: 0x%X.", rt_ret); + return RT_ERROR_TO_GE_STATUS(rt_ret); + } + GELOGD("Get profiling args, task_id[%u], stream_id[%u]", task_id, stream_id); + + Json step_info; + step_info[kIndexId] = index_id; + step_info[kModeleId] = model_id; + step_info[kTimeStamp] = time; + step_info[kTagId] = tag_id; + step_info[kTaskId] = task_id; + step_info[kStreamId] = stream_id; + step_info[kThreadId] = mmGetTid(); + + std::string reported_data; + try { + reported_data = step_info.dump(kInteval, ' ', false, Json::error_handler_t::ignore); + } catch (std::exception &e) { + GELOGE(FAILED, "Failed to convert JSON to string, reason: %s.", e.what()); + } catch (...) { + GELOGE(FAILED, "Failed to convert JSON to string."); + } + reported_data.append(",") + .append("\n"); + prof_mgr.ReportData(device_id_, reported_data, "step_info"); + } + return SUCCESS; +} + Status HybridModelExecutor::ExecuteGraphInternal(SubgraphExecutor &executor, HybridModelExecutor::ExecuteArgs &args) { RECORD_MODEL_EXECUTION_EVENT(&context_, "[InitContext] Start"); GE_CHK_STATUS_RET_NOLOG(ResetExecutionContext(context_)); RECORD_MODEL_EXECUTION_EVENT(&context_, "[InitContext] End"); + // tag_id 0 means step begin, 1 meas step end. + GE_CHK_STATUS_RET_NOLOG(ProfileStepBegin(0)); HYBRID_CHK_STATUS_RET(executor.ExecuteAsync(args.inputs, args.input_desc, args.outputs), "Failed to execute partitioned call."); RECORD_MODEL_EXECUTION_EVENT(&context_, "[ExecuteAsync] End"); + GE_CHK_STATUS_RET_NOLOG(ProfileStepEnd(1)); HYBRID_CHK_STATUS_RET(executor.Synchronize(), "Failed to sync root graph."); RECORD_MODEL_EXECUTION_EVENT(&context_, "[Synchronize] End"); diff --git a/ge/hybrid/executor/hybrid_model_executor.h b/ge/hybrid/executor/hybrid_model_executor.h index 0b2cd1ed..af0bd536 100644 --- a/ge/hybrid/executor/hybrid_model_executor.h +++ b/ge/hybrid/executor/hybrid_model_executor.h @@ -51,6 +51,8 @@ class HybridModelExecutor { Status ExecuteGraphInternal(SubgraphExecutor &executor, ExecuteArgs &args); Status Cleanup(); Status InitExecutionContext(); + Status ProfileStepInfo(uint16_t tag_id); + static Status ResetExecutionContext(GraphExecutionContext &context); HybridModel *model_; diff --git a/tests/depends/runtime/src/runtime_stub.cc b/tests/depends/runtime/src/runtime_stub.cc index 440b98e7..735ec29d 100644 --- a/tests/depends/runtime/src/runtime_stub.cc +++ b/tests/depends/runtime/src/runtime_stub.cc @@ -313,6 +313,8 @@ rtError_t rtFlushCache(uint64_t base, uint32_t len) { return RT_ERROR_NONE; } rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream_) { return RT_ERROR_NONE; } +rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_) { return RT_ERROR_NONE; } + rtError_t rtMemSetRC(const void *dev_ptr, uint64_t size, uint32_t read_count) { return RT_ERROR_NONE; } rtError_t rtStreamSwitch(void *ptr, rtCondition_t condition, int64_t value, rtStream_t true_stream, rtStream_t stream) { diff --git a/tests/ut/ge/CMakeLists.txt b/tests/ut/ge/CMakeLists.txt index 9e870a64..2a1ca397 100755 --- a/tests/ut/ge/CMakeLists.txt +++ b/tests/ut/ge/CMakeLists.txt @@ -845,6 +845,7 @@ target_link_libraries(ge_ut_common PRIVATE ascend_protobuf json ge_ut_graph + runtime_stub ) # build common format diff --git a/tests/ut/ge/graph/load/davinci_model_unittest.cc b/tests/ut/ge/graph/load/davinci_model_unittest.cc index 18cc622b..457c3b2e 100644 --- a/tests/ut/ge/graph/load/davinci_model_unittest.cc +++ b/tests/ut/ge/graph/load/davinci_model_unittest.cc @@ -898,6 +898,12 @@ TEST_F(UtestDavinciModel, Sink_time_profile) { model.SinkTimeProfile(current_data); } +TEST_F(UtestDavinciModel, Step_info_profile) { + ProfilingManager::Instance().prof_cb_.msprofReporterCallback = MsprofReport; + DavinciModel model(0, nullptr); + EXPECT_EQ(DavinciModel::ProfileStepInfo(&model, 0), SUCCESS); +} + class ClassTest { public: virtual ~ClassTest() {} diff --git a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc index 3b5d19e6..81801d76 100644 --- a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc +++ b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc @@ -37,6 +37,7 @@ #include "hybrid/common/npu_memory_allocator.h" #include "graph/types.h" #include "graph/utils/tensor_utils.h" +#include "common/profiling/profiling_manager.h" #undef private #undef protected @@ -46,6 +47,11 @@ using namespace testing; using namespace ge; using namespace hybrid; +namespace { +int32_t MsprofReport(uint32_t moduleId, uint32_t type, void *data, uint32_t len) { + return 0; +} +} // namespace class UtestGeHybrid : public testing::Test { protected: @@ -245,7 +251,7 @@ TEST_F(UtestGeHybrid, init_weight_success) { ASSERT_EQ(ret,PARAM_INVALID); } - TEST_F(UtestGeHybrid, hybrid_model_executor) { +TEST_F(UtestGeHybrid, hybrid_model_executor) { ComputeGraphPtr compute_graph = MakeShared("abc"); GeRootModelPtr root_model = MakeShared(compute_graph); HybridModel model(root_model); @@ -256,3 +262,12 @@ TEST_F(UtestGeHybrid, init_weight_success) { HybridModelExecutor executor(model_ptr, device_id, stream); executor.Init(); } + +TEST_F(UtestGeHybrid, Step_info_profile) { + ProfilingManager::Instance().prof_cb_.msprofReporterCallback = MsprofReport; + auto graph = make_shared("graph"); + auto root_model = make_shared(graph); + HybridModel model(root_model); + HybridModelExecutor executor(&model, 0, nullptr); + ASSERT_EQ(executor.ProfileStepInfo(0), SUCCESS): +} diff --git a/third_party/fwkacllib/inc/runtime/base.h b/third_party/fwkacllib/inc/runtime/base.h index 5b246eed..2c62b0dd 100644 --- a/third_party/fwkacllib/inc/runtime/base.h +++ b/third_party/fwkacllib/inc/runtime/base.h @@ -154,6 +154,12 @@ RTS_API rtError_t rtProfilerStop(uint64_t profConfig, int32_t numsDev, uint32_t */ RTS_API rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream); +/** + * @ingroup profiling_base + * @brief ts send keypoint profiler log. + */ +RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_); + /** * @ingroup profiling_base * @brief ts set profiling reporter callback. From c0f8247985404638e1ec06e0fa354b4fd2ad9dc4 Mon Sep 17 00:00:00 2001 From: unknown Date: Sat, 20 Mar 2021 10:58:47 +0800 Subject: [PATCH 02/13] For step profiling. --- ge/hybrid/executor/hybrid_model_executor.cc | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index ad295abf..3a729139 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -28,7 +28,7 @@ const int kIntBase = 10; const char *const kEnvProfilingLevel = "HYBRID_PROFILING_LEVEL"; const char *const kIndexId = "index_id"; const char *const kModeleId = "model_id"; -const char *const kTimeStamp = "time_stamp"; +const char *const kTimeStamp = "time_stamp"; const char *const kStreamId = "stream_id"; const char *const kTaskId = "task_id"; const char *const kTagId = "tag_id"; @@ -93,7 +93,7 @@ Status HybridModelExecutor::ProfileStepInfo(uint16_t tag_id) { GELOGE(RT_FAILED, "[Call][rtProfilerTraceEx] failed, ret: 0x%X", rt_ret); return RT_ERROR_TO_GE_STATUS(rt_ret); } - GELOGD("Profiling Step Info TraceTask execute async success. index_id = %lu, model_id = %u, tag_id = %u", + GELOGD("Profiling Step Info TraceTask execute async success. index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); mmTimespec timespec = mmGetTickCount(); @@ -139,11 +139,11 @@ Status HybridModelExecutor::ExecuteGraphInternal(SubgraphExecutor &executor, RECORD_MODEL_EXECUTION_EVENT(&context_, "[InitContext] End"); // tag_id 0 means step begin, 1 meas step end. - GE_CHK_STATUS_RET_NOLOG(ProfileStepBegin(0)); + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(0)); HYBRID_CHK_STATUS_RET(executor.ExecuteAsync(args.inputs, args.input_desc, args.outputs), "Failed to execute partitioned call."); RECORD_MODEL_EXECUTION_EVENT(&context_, "[ExecuteAsync] End"); - GE_CHK_STATUS_RET_NOLOG(ProfileStepEnd(1)); + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(1)); HYBRID_CHK_STATUS_RET(executor.Synchronize(), "Failed to sync root graph."); RECORD_MODEL_EXECUTION_EVENT(&context_, "[Synchronize] End"); From 8288f6e512aba1d84fa466380aa06699080ed11b Mon Sep 17 00:00:00 2001 From: unknown Date: Sat, 20 Mar 2021 11:05:06 +0800 Subject: [PATCH 03/13] For step profiling. --- ge/hybrid/executor/hybrid_model_executor.cc | 2 +- tests/depends/runtime/src/runtime_stub.cc | 2 +- tests/ut/ge/hybrid/ge_hybrid_unittest.cc | 2 +- third_party/fwkacllib/inc/runtime/base.h | 2 +- 4 files changed, 4 insertions(+), 4 deletions(-) diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index 3a729139..49e56cbb 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -93,7 +93,7 @@ Status HybridModelExecutor::ProfileStepInfo(uint16_t tag_id) { GELOGE(RT_FAILED, "[Call][rtProfilerTraceEx] failed, ret: 0x%X", rt_ret); return RT_ERROR_TO_GE_STATUS(rt_ret); } - GELOGD("Profiling Step Info TraceTask execute async success. index_id = %lu, model_id = %lu, tag_id = %u", + GELOGD("Profiling Step Info TraceTask execute async success, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); mmTimespec timespec = mmGetTickCount(); diff --git a/tests/depends/runtime/src/runtime_stub.cc b/tests/depends/runtime/src/runtime_stub.cc index 735ec29d..1bcd2a5c 100644 --- a/tests/depends/runtime/src/runtime_stub.cc +++ b/tests/depends/runtime/src/runtime_stub.cc @@ -311,7 +311,7 @@ rtError_t rtStreamCreateWithFlags(rtStream_t *stream, int32_t priority, uint32_t rtError_t rtFlushCache(uint64_t base, uint32_t len) { return RT_ERROR_NONE; } -rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream_) { return RT_ERROR_NONE; } +rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream) { return RT_ERROR_NONE; } rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_) { return RT_ERROR_NONE; } diff --git a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc index 81801d76..241b0b2e 100644 --- a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc +++ b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc @@ -269,5 +269,5 @@ TEST_F(UtestGeHybrid, Step_info_profile) { auto root_model = make_shared(graph); HybridModel model(root_model); HybridModelExecutor executor(&model, 0, nullptr); - ASSERT_EQ(executor.ProfileStepInfo(0), SUCCESS): + EXPECT_EQ(executor.ProfileStepInfo(0), SUCCESS): } diff --git a/third_party/fwkacllib/inc/runtime/base.h b/third_party/fwkacllib/inc/runtime/base.h index 2c62b0dd..6f21d21b 100644 --- a/third_party/fwkacllib/inc/runtime/base.h +++ b/third_party/fwkacllib/inc/runtime/base.h @@ -158,7 +158,7 @@ RTS_API rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtSt * @ingroup profiling_base * @brief ts send keypoint profiler log. */ -RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_); +RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream); /** * @ingroup profiling_base From 98ab9b7320bb6c8142508c3fc0f0f6169922f622 Mon Sep 17 00:00:00 2001 From: unknown Date: Sat, 20 Mar 2021 11:31:23 +0800 Subject: [PATCH 04/13] For step profiling. --- tests/depends/runtime/src/runtime_stub.cc | 2 +- third_party/fwkacllib/inc/runtime/base.h | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/depends/runtime/src/runtime_stub.cc b/tests/depends/runtime/src/runtime_stub.cc index 1bcd2a5c..4758cfea 100644 --- a/tests/depends/runtime/src/runtime_stub.cc +++ b/tests/depends/runtime/src/runtime_stub.cc @@ -313,7 +313,7 @@ rtError_t rtFlushCache(uint64_t base, uint32_t len) { return RT_ERROR_NONE; } rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream) { return RT_ERROR_NONE; } -rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_) { return RT_ERROR_NONE; } +// rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_) { return RT_ERROR_NONE; } rtError_t rtMemSetRC(const void *dev_ptr, uint64_t size, uint32_t read_count) { return RT_ERROR_NONE; } diff --git a/third_party/fwkacllib/inc/runtime/base.h b/third_party/fwkacllib/inc/runtime/base.h index 6f21d21b..38c1945f 100644 --- a/third_party/fwkacllib/inc/runtime/base.h +++ b/third_party/fwkacllib/inc/runtime/base.h @@ -158,7 +158,9 @@ RTS_API rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtSt * @ingroup profiling_base * @brief ts send keypoint profiler log. */ -RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream); +RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { + return RT_ERROR_NONE; +} /** * @ingroup profiling_base From 1b2c5dca94533aa08f618aff4b8e306bf79232b8 Mon Sep 17 00:00:00 2001 From: unknown Date: Sat, 20 Mar 2021 11:48:49 +0800 Subject: [PATCH 05/13] rts stub. --- ge/graph/load/model_manager/davinci_model.cc | 4 ++++ ge/hybrid/executor/hybrid_model_executor.cc | 4 ++++ third_party/fwkacllib/inc/runtime/base.h | 8 -------- 3 files changed, 8 insertions(+), 8 deletions(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index 14c48014..5ce3b314 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -155,6 +155,10 @@ inline bool IsNoTaskAndDumpNeeded(const OpDescPtr &op_desc) { (void)ge::AttrUtils::GetBool(op_desc, ATTR_NO_TASK_AND_DUMP_NEEDED, save_dump_info); return save_dump_info; } + +RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { + return RT_ERROR_NONE; +} } // namespace std::mutex DavinciModel::tvm_bin_mutex_; diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index 49e56cbb..a5361d3e 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -34,6 +34,10 @@ const char *const kTaskId = "task_id"; const char *const kTagId = "tag_id"; const char *const kThreadId = "thread_id"; const uint32_t kInteval = 2; + +RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { + return RT_ERROR_NONE; +} } // namespace HybridModelExecutor::HybridModelExecutor(HybridModel *model, uint32_t device_id, rtStream_t stream) : model_(model), device_id_(device_id), stream_(stream) { diff --git a/third_party/fwkacllib/inc/runtime/base.h b/third_party/fwkacllib/inc/runtime/base.h index 38c1945f..5b246eed 100644 --- a/third_party/fwkacllib/inc/runtime/base.h +++ b/third_party/fwkacllib/inc/runtime/base.h @@ -154,14 +154,6 @@ RTS_API rtError_t rtProfilerStop(uint64_t profConfig, int32_t numsDev, uint32_t */ RTS_API rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream); -/** - * @ingroup profiling_base - * @brief ts send keypoint profiler log. - */ -RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { - return RT_ERROR_NONE; -} - /** * @ingroup profiling_base * @brief ts set profiling reporter callback. From cf05593f6a4b251d7382f2e3892920a5e93bdb5a Mon Sep 17 00:00:00 2001 From: unknown Date: Sat, 20 Mar 2021 13:49:14 +0800 Subject: [PATCH 06/13] Fix bug --- tests/ut/ge/hybrid/ge_hybrid_unittest.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc index 241b0b2e..075c5f52 100644 --- a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc +++ b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc @@ -269,5 +269,5 @@ TEST_F(UtestGeHybrid, Step_info_profile) { auto root_model = make_shared(graph); HybridModel model(root_model); HybridModelExecutor executor(&model, 0, nullptr); - EXPECT_EQ(executor.ProfileStepInfo(0), SUCCESS): + EXPECT_EQ(executor.ProfileStepInfo(0), SUCCESS); } From 9d1d3583c01cf7303ae08785b95962b94c44a44f Mon Sep 17 00:00:00 2001 From: zhaozhixuan Date: Tue, 23 Mar 2021 10:29:20 +0800 Subject: [PATCH 07/13] Add ut. --- tests/ut/ge/graph/load/davinci_model_unittest.cc | 1 + tests/ut/ge/hybrid/ge_hybrid_unittest.cc | 1 + 2 files changed, 2 insertions(+) diff --git a/tests/ut/ge/graph/load/davinci_model_unittest.cc b/tests/ut/ge/graph/load/davinci_model_unittest.cc index 457c3b2e..fa531010 100644 --- a/tests/ut/ge/graph/load/davinci_model_unittest.cc +++ b/tests/ut/ge/graph/load/davinci_model_unittest.cc @@ -900,6 +900,7 @@ TEST_F(UtestDavinciModel, Sink_time_profile) { TEST_F(UtestDavinciModel, Step_info_profile) { ProfilingManager::Instance().prof_cb_.msprofReporterCallback = MsprofReport; + ProfilingManager::Instance().device_id_.emplace_back(0); DavinciModel model(0, nullptr); EXPECT_EQ(DavinciModel::ProfileStepInfo(&model, 0), SUCCESS); } diff --git a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc index 075c5f52..e377ca66 100644 --- a/tests/ut/ge/hybrid/ge_hybrid_unittest.cc +++ b/tests/ut/ge/hybrid/ge_hybrid_unittest.cc @@ -265,6 +265,7 @@ TEST_F(UtestGeHybrid, hybrid_model_executor) { TEST_F(UtestGeHybrid, Step_info_profile) { ProfilingManager::Instance().prof_cb_.msprofReporterCallback = MsprofReport; + ProfilingManager::Instance().device_id_.emplace_back(0); auto graph = make_shared("graph"); auto root_model = make_shared(graph); HybridModel model(root_model); From 2f88cf26ba89156d54203686b6f6138a54084363 Mon Sep 17 00:00:00 2001 From: zhaozhixuan Date: Tue, 23 Mar 2021 21:42:39 +0800 Subject: [PATCH 08/13] For step profiling. --- ge/graph/load/model_manager/davinci_model.cc | 9 ++++----- ge/hybrid/executor/hybrid_model_executor.cc | 9 ++++----- tests/depends/runtime/src/runtime_stub.cc | 4 ++-- 3 files changed, 10 insertions(+), 12 deletions(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index 5ce3b314..5b2d7a00 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -155,10 +155,6 @@ inline bool IsNoTaskAndDumpNeeded(const OpDescPtr &op_desc) { (void)ge::AttrUtils::GetBool(op_desc, ATTR_NO_TASK_AND_DUMP_NEEDED, save_dump_info); return save_dump_info; } - -RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { - return RT_ERROR_NONE; -} } // namespace std::mutex DavinciModel::tvm_bin_mutex_; @@ -2317,16 +2313,19 @@ Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { if (prof_mgr.ProfilingModelExecuteOn()) { uint64_t index_id = model->iterator_count_ + 1; uint64_t model_id = static_cast(model->Id()); + rtError_t rt_ret = RT_ERROR_NONE; +#ifdef ONLY_COMPILE_OPEN_SRC rtStream_t stream = model->rt_model_stream_; GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); - rtError_t rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream); + rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream); if (rt_ret != RT_ERROR_NONE) { GELOGE(RT_FAILED, "[Call][rtProfilerTraceEx] failed, ret: 0x%X", rt_ret); return RT_ERROR_TO_GE_STATUS(rt_ret); } GELOGD("Profiling Step Info TraceTask execute async success, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); +#endif mmTimespec timespec = mmGetTickCount(); // 1000 ^ 3 converts second to nanosecond diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index a5361d3e..3c438513 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -34,10 +34,6 @@ const char *const kTaskId = "task_id"; const char *const kTagId = "tag_id"; const char *const kThreadId = "thread_id"; const uint32_t kInteval = 2; - -RTS_API rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { - return RT_ERROR_NONE; -} } // namespace HybridModelExecutor::HybridModelExecutor(HybridModel *model, uint32_t device_id, rtStream_t stream) : model_(model), device_id_(device_id), stream_(stream) { @@ -90,15 +86,18 @@ Status HybridModelExecutor::ProfileStepInfo(uint16_t tag_id) { if (prof_mgr.ProfilingModelExecuteOn()) { uint64_t index_id = context_.iteration + 1; uint64_t model_id = static_cast(model_->GetModelId()); + rtError_t rt_ret = RT_ERROR_NONE; +#ifdef ONLY_COMPILE_OPEN_SRC GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); - rtError_t rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream_); + rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream_); if (rt_ret != RT_ERROR_NONE) { GELOGE(RT_FAILED, "[Call][rtProfilerTraceEx] failed, ret: 0x%X", rt_ret); return RT_ERROR_TO_GE_STATUS(rt_ret); } GELOGD("Profiling Step Info TraceTask execute async success, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); +#endif mmTimespec timespec = mmGetTickCount(); // 1000 ^ 3 converts second to nanosecond diff --git a/tests/depends/runtime/src/runtime_stub.cc b/tests/depends/runtime/src/runtime_stub.cc index 4758cfea..97f2a21d 100644 --- a/tests/depends/runtime/src/runtime_stub.cc +++ b/tests/depends/runtime/src/runtime_stub.cc @@ -311,9 +311,9 @@ rtError_t rtStreamCreateWithFlags(rtStream_t *stream, int32_t priority, uint32_t rtError_t rtFlushCache(uint64_t base, uint32_t len) { return RT_ERROR_NONE; } -rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream) { return RT_ERROR_NONE; } +rtError_t rtProfilerTrace(uint64_t id, bool notify, uint32_t flags, rtStream_t stream_) { return RT_ERROR_NONE; } -// rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream_) { return RT_ERROR_NONE; } +rtError_t rtProfilerTraceEx(uint64_t id, uint64_t modelId, uint16_t tagId, rtStream_t stream) { return RT_ERROR_NONE; } rtError_t rtMemSetRC(const void *dev_ptr, uint64_t size, uint32_t read_count) { return RT_ERROR_NONE; } From 06eb77c6c900edf5a89bf9481c7e66f44f8ac69f Mon Sep 17 00:00:00 2001 From: unknown Date: Wed, 24 Mar 2021 21:18:48 +0800 Subject: [PATCH 09/13] Fix bug. --- ge/graph/load/model_manager/davinci_model.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index 5b2d7a00..fd2d059f 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -3754,18 +3754,18 @@ Status DavinciModel::NnExecute(rtStream_t stream, bool async_mode, const InputDa GELOGD("current_data.index=%u", input_data.index); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_PRE_PROC_END)); - // tag_id 0 means step begin, 1 meas step end. - GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 0)); if (!task_list_.empty()) { + // tag_id 0 means step begin, 1 meas step end. + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 0)); GELOGD("rtModelExecute do"); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_INFER_START)); rtError_t rt_ret = rtModelExecute(rt_model_handle_, rt_model_stream_, 0); GE_CHK_RT_EXEC(rt_ret, return RT_ERROR_TO_GE_STATUS(rt_ret)); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_INFER_END)); GELOGD("rtModelExecute end"); + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 1)); iterator_count_++; } - GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 1)); if (!is_async_mode_) { GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_AFTER_PROC_START)); From 54a2f6b92a2b052006645c1c791ea592ef0b19e6 Mon Sep 17 00:00:00 2001 From: unknown Date: Wed, 24 Mar 2021 21:22:44 +0800 Subject: [PATCH 10/13] Fix bug. --- ge/graph/load/model_manager/davinci_model.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index fd2d059f..d9015911 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -3763,7 +3763,7 @@ Status DavinciModel::NnExecute(rtStream_t stream, bool async_mode, const InputDa GE_CHK_RT_EXEC(rt_ret, return RT_ERROR_TO_GE_STATUS(rt_ret)); GE_IF_BOOL_EXEC(ProfilingManager::Instance().ProfilingModelExecuteOn(), SetProfileTime(MODEL_INFER_END)); GELOGD("rtModelExecute end"); - GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 1)); + GE_CHK_STATUS_RET_NOLOG(ProfileStepInfo(this, 1)); iterator_count_++; } From 3123755f285d448b352ba55e7bb4e34c63084735 Mon Sep 17 00:00:00 2001 From: unknown Date: Thu, 25 Mar 2021 14:12:21 +0800 Subject: [PATCH 11/13] Fix sc. --- ge/graph/load/model_manager/davinci_model.cc | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index d9015911..5303ad53 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -2309,8 +2309,7 @@ Status DavinciModel::SinkTimeProfile(const InputData ¤t_data) { } Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { - auto &prof_mgr = ProfilingManager::Instance(); - if (prof_mgr.ProfilingModelExecuteOn()) { + if (ProfilingManager::Instance().ProfilingModelExecuteOn()) { uint64_t index_id = model->iterator_count_ + 1; uint64_t model_id = static_cast(model->Id()); rtError_t rt_ret = RT_ERROR_NONE; @@ -2338,7 +2337,7 @@ Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { return RT_ERROR_TO_GE_STATUS(rt_ret); } GELOGD("Get profiling args, task_id[%u], stream_id[%u]", task_id, stream_id); - uint32_t device_id = model->GetDeviceId(); + int32_t device_id = static_cast(model->GetDeviceId()); Json step_info; step_info[kIndexId] = index_id; @@ -2359,7 +2358,7 @@ Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { } reported_data.append(",") .append("\n"); - prof_mgr.ReportData(device_id, reported_data, "step_info"); + ProfilingManager::Instance().ReportData(device_id, reported_data, "step_info"); } return SUCCESS; } From 0da536a15b3c88eaac0693e7d8be47cdbf6be7b9 Mon Sep 17 00:00:00 2001 From: unknown Date: Thu, 25 Mar 2021 15:47:15 +0800 Subject: [PATCH 12/13] Fix bug. --- ge/graph/load/model_manager/davinci_model.cc | 2 +- ge/hybrid/executor/hybrid_model_executor.cc | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index 5303ad53..f15c9f49 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -2313,7 +2313,7 @@ Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { uint64_t index_id = model->iterator_count_ + 1; uint64_t model_id = static_cast(model->Id()); rtError_t rt_ret = RT_ERROR_NONE; -#ifdef ONLY_COMPILE_OPEN_SRC +#ifdef ENABLE_OPEN_SRC rtStream_t stream = model->rt_model_stream_; GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index 3c438513..2d729e17 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -87,7 +87,7 @@ Status HybridModelExecutor::ProfileStepInfo(uint16_t tag_id) { uint64_t index_id = context_.iteration + 1; uint64_t model_id = static_cast(model_->GetModelId()); rtError_t rt_ret = RT_ERROR_NONE; -#ifdef ONLY_COMPILE_OPEN_SRC +#ifdef ENABLE_OPEN_SRC GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream_); From a9b0c286713acf50b04beb047c2ec280c978bfed Mon Sep 17 00:00:00 2001 From: unknown Date: Thu, 25 Mar 2021 19:02:45 +0800 Subject: [PATCH 13/13] Fix error. --- ge/graph/load/model_manager/davinci_model.cc | 2 +- ge/hybrid/executor/hybrid_model_executor.cc | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/ge/graph/load/model_manager/davinci_model.cc b/ge/graph/load/model_manager/davinci_model.cc index f15c9f49..d7b8e443 100755 --- a/ge/graph/load/model_manager/davinci_model.cc +++ b/ge/graph/load/model_manager/davinci_model.cc @@ -2313,7 +2313,7 @@ Status DavinciModel::ProfileStepInfo(DavinciModel *model, uint16_t tag_id) { uint64_t index_id = model->iterator_count_ + 1; uint64_t model_id = static_cast(model->Id()); rtError_t rt_ret = RT_ERROR_NONE; -#ifdef ENABLE_OPEN_SRC +#ifndef ONLY_COMPILE_OPEN_SRC rtStream_t stream = model->rt_model_stream_; GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); diff --git a/ge/hybrid/executor/hybrid_model_executor.cc b/ge/hybrid/executor/hybrid_model_executor.cc index 2d729e17..3e65b5c1 100755 --- a/ge/hybrid/executor/hybrid_model_executor.cc +++ b/ge/hybrid/executor/hybrid_model_executor.cc @@ -87,7 +87,7 @@ Status HybridModelExecutor::ProfileStepInfo(uint16_t tag_id) { uint64_t index_id = context_.iteration + 1; uint64_t model_id = static_cast(model_->GetModelId()); rtError_t rt_ret = RT_ERROR_NONE; -#ifdef ENABLE_OPEN_SRC +#ifndef ONLY_COMPILE_OPEN_SRC GELOGD("Profiling Step Info TraceTask execute async start, index_id = %lu, model_id = %lu, tag_id = %u", index_id, model_id, tag_id); rt_ret = rtProfilerTraceEx(index_id, model_id, tag_id, stream_);