From 03a0e9bec0176a560bd87b7cdb24eb761bb8a12b Mon Sep 17 00:00:00 2001 From: Ammar ELWazir Date: Thu, 20 Apr 2023 12:49:32 +0000 Subject: [PATCH] Fixing Performance Issue with API Tracing V2 Records right now will report basic raw data, no pre-processing in API anymore, and it will be left to the tool to process data from the output of synchronous callbacks of the API tracing records output Change-Id: I8e5845e49e1228cb2fb60ca188ee748745b6a1af [ROCm/rocprofiler commit: 4a33787c019b462434560a35c44ad193e4d1d1f1] --- projects/rocprofiler/inc/rocprofiler.h | 19 +++ projects/rocprofiler/plugin/file/file.cpp | 37 ++++-- .../rocprofiler/plugin/perfetto/perfetto.cpp | 85 ++++++++++--- .../src/core/session/tracer/src/roctracer.cpp | 4 + .../src/core/session/tracer/tracer.cpp | 117 +++++++++++------- 5 files changed, 188 insertions(+), 74 deletions(-) diff --git a/projects/rocprofiler/inc/rocprofiler.h b/projects/rocprofiler/inc/rocprofiler.h index df144485c4..dfde58b21c 100644 --- a/projects/rocprofiler/inc/rocprofiler.h +++ b/projects/rocprofiler/inc/rocprofiler.h @@ -1476,6 +1476,21 @@ typedef struct { uint64_t id; } rocprofiler_tracer_external_id_t; +typedef enum { + /** + * No phase, it is an activity record or asynchronous output data + */ + ROCPROFILER_PHASE_NONE = 0, + /** + * Enter phase for API calls + */ + ROCPROFILER_PHASE_ENTER = 1, + /** + * Exit phase for API calls + */ + ROCPROFILER_PHASE_EXIT = 2 +} rocprofiler_api_tracing_phase_t; + /** * Tracing record, this will represent all the information reported by the * tracer regarding APIs and their data that were traced and collected @@ -1530,6 +1545,10 @@ typedef struct { * Thread id */ rocprofiler_thread_id_t thread_id; + /** + * API Tracing phase (Enter/Exit/None(Activity Records/Asynchronous Output Records)) + */ + rocprofiler_api_tracing_phase_t phase; } rocprofiler_record_tracer_t; /** diff --git a/projects/rocprofiler/plugin/file/file.cpp b/projects/rocprofiler/plugin/file/file.cpp index 8a09da8faf..4411289dc6 100644 --- a/projects/rocprofiler/plugin/file/file.cpp +++ b/projects/rocprofiler/plugin/file/file.cpp @@ -278,16 +278,33 @@ class file_plugin_t { } } output_file_t* output_file = get_output_file(output_type_t::TRACER, tracer_record.domain); - *output_file << "Record [" << tracer_record.header.id.handle << "], Domain(" - << GetDomainName(tracer_record.domain) << "), Begin(" - << tracer_record.timestamps.begin.value; - if (tracer_record.domain != ACTIVITY_DOMAIN_ROCTX) - *output_file << "), End(" << tracer_record.timestamps.end.value; - *output_file << "), Correlation ID( " << tracer_record.correlation_id.value << ")"; - if (tracer_record.domain == ACTIVITY_DOMAIN_ROCTX && roctx_id >= 0) *output_file << ", ROCTX ID(" << roctx_id << ")"; - if (tracer_record.domain == ACTIVITY_DOMAIN_ROCTX && roctx_message.size() > 1) *output_file << ", ROCTX Message(" << roctx_message << ")"; - if (function_name.size() > 1) *output_file << ", Function(" << function_name << ")"; - if (kernel_name.size() > 1) *output_file << ", Kernel Name(" << kernel_name.c_str() << ")"; + *output_file << "Record(" << tracer_record.header.id.handle << "), Domain(" + << GetDomainName(tracer_record.domain) << "),"; + if (tracer_record.domain == ACTIVITY_DOMAIN_ROCTX && roctx_id >= 0) *output_file << " ROCTX_ID(" << roctx_id << "),"; + if (tracer_record.domain == ACTIVITY_DOMAIN_ROCTX && roctx_message.size() > 1) *output_file << " ROCTX_Message(" << roctx_message << "),"; + if (function_name.size() > 1) *output_file << " Function(" << function_name << "),"; + if (kernel_name.size() > 1) *output_file << " Kernel_Name(" << kernel_name.c_str() << "),"; + if (tracer_record.phase == ROCPROFILER_PHASE_NONE) { + *output_file << " Begin(" << tracer_record.timestamps.begin.value + << "), End(" << tracer_record.timestamps.end.value << ")"; + } else { + if(tracer_record.phase == ROCPROFILER_PHASE_ENTER && tracer_record.domain != ACTIVITY_DOMAIN_ROCTX){ + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); + *output_file << " Begin(" << timestamp.value << "),"; + } + if(tracer_record.phase == ROCPROFILER_PHASE_ENTER && tracer_record.domain == ACTIVITY_DOMAIN_ROCTX) { + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); + *output_file << " timestamp(" << timestamp.value << "),"; + } + if (tracer_record.phase == ROCPROFILER_PHASE_EXIT) { + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); + *output_file << " End(" << timestamp.value << "),"; + } + } + *output_file << " Correlation_ID(" << tracer_record.correlation_id.value << ")"; *output_file << std::endl; } diff --git a/projects/rocprofiler/plugin/perfetto/perfetto.cpp b/projects/rocprofiler/plugin/perfetto/perfetto.cpp index 3ecaa358d9..8492a22438 100644 --- a/projects/rocprofiler/plugin/perfetto/perfetto.cpp +++ b/projects/rocprofiler/plugin/perfetto/perfetto.cpp @@ -452,17 +452,33 @@ class perfetto_plugin_t { } } - if (tracer_record.operation_id.id == 1) { + if(tracer_record.phase == ROCPROFILER_PHASE_NONE) { + if (tracer_record.operation_id.id == 1) { + perfetto::StaticString roctx_message_pft( + (!roctx_message.empty() ? roctx_message.c_str() : "")); + TRACE_EVENT_BEGIN("ROCTX_API", roctx_message_pft, roctx_track, + tracer_record.timestamps.begin.value, "Timestamp(ns)", + tracer_record.timestamps.begin.value, "RocTx ID", roctx_id); + roctx_track_entries_++; + } else { + TRACE_EVENT_END("ROCTX_API", roctx_track, tracer_record.timestamps.begin.value); + roctx_track_entries_--; + } + } else { + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); + if (tracer_record.operation_id.id == 1) { perfetto::StaticString roctx_message_pft( (!roctx_message.empty() ? roctx_message.c_str() : "")); TRACE_EVENT_BEGIN("ROCTX_API", roctx_message_pft, roctx_track, - tracer_record.timestamps.begin.value, "Timestamp(ns)", - tracer_record.timestamps.begin.value, "RocTx ID", roctx_id); + timestamp.value, "Timestamp(ns)", + timestamp.value, "RocTx ID", roctx_id); roctx_track_entries_++; } else { - TRACE_EVENT_END("ROCTX_API", roctx_track, tracer_record.timestamps.begin.value); + TRACE_EVENT_END("ROCTX_API", roctx_track, timestamp.value); roctx_track_entries_--; } + } break; } case ACTIVITY_DOMAIN_HSA_API: { @@ -499,10 +515,14 @@ class perfetto_plugin_t { session_id, ROCPROFILER_HSA_FUNCTION_NAME, tracer_record.api_data_handle, tracer_record.operation_id, &function_name)); } - TRACE_EVENT_BEGIN("HSA_API", perfetto::StaticString(function_name), hsa_track, - tracer_record.timestamps.begin.value, + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); + if(tracer_record.phase == ROCPROFILER_PHASE_ENTER) + TRACE_EVENT_BEGIN("HSA_API", perfetto::StaticString(function_name), hsa_track, + timestamp.value, perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); - TRACE_EVENT_END("HSA_API", hsa_track, tracer_record.timestamps.end.value); + if(tracer_record.phase == ROCPROFILER_PHASE_EXIT) + TRACE_EVENT_END("HSA_API", hsa_track, timestamp.value); break; } case ACTIVITY_DOMAIN_HIP_API: { @@ -555,16 +575,34 @@ class perfetto_plugin_t { free(kernel_name_str); } } - if (kernel_name.size() > 0) { - TRACE_EVENT_BEGIN("HIP_API", perfetto::StaticString(function_name), hip_track, - tracer_record.timestamps.begin.value, "Kernel Name", kernel_name, - perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); - } else { - TRACE_EVENT_BEGIN("HIP_API", perfetto::StaticString(function_name), hip_track, - tracer_record.timestamps.begin.value, - perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); + if(tracer_record.phase == ROCPROFILER_PHASE_ENTER) { + if (kernel_name.size() > 0) { + TRACE_EVENT_BEGIN("HIP_API", perfetto::StaticString(function_name), hip_track, + timestamp.value, "Kernel Name", kernel_name, + perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); + } else { + TRACE_EVENT_BEGIN("HIP_API", perfetto::StaticString(function_name), hip_track, + timestamp.value, + perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); + } + } + if(tracer_record.phase == ROCPROFILER_PHASE_EXIT) { + TRACE_EVENT_END("HIP_API", hip_track, timestamp.value); + } + if(tracer_record.phase == ROCPROFILER_PHASE_NONE) { + if (kernel_name.size() > 0) { + TRACE_EVENT_BEGIN("HIP_API", perfetto::StaticString(function_name), hip_track, + tracer_record.timestamps.begin.value, "Kernel Name", kernel_name, + perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); + } else { + TRACE_EVENT_BEGIN("HIP_API", perfetto::StaticString(function_name), hip_track, + tracer_record.timestamps.begin.value, + perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); + } + TRACE_EVENT_END("HIP_API", hip_track, tracer_record.timestamps.end.value); } - TRACE_EVENT_END("HIP_API", hip_track, tracer_record.timestamps.end.value); break; } case ACTIVITY_DOMAIN_EXT_API: { @@ -607,6 +645,8 @@ class perfetto_plugin_t { } } auto& stream_track = stream_track_it->second; + rocprofiler_timestamp_t timestamp; + rocprofiler_get_timestamp(×tamp); if (tracer_record.api_data_handle.handle && tracer_record.api_data_handle.size > 1) { kernel_name = rocmtools::cxx_demangle( strdup(reinterpret_cast(tracer_record.api_data_handle.handle))); @@ -629,12 +669,21 @@ class perfetto_plugin_t { } else { activity_name = const_cast(std::string("N/A").c_str()); } - TRACE_EVENT_BEGIN("HIP_OPS", perfetto::StaticString(activity_name), stream_track, + if(tracer_record.phase == ROCPROFILER_PHASE_NONE) + TRACE_EVENT_BEGIN("HIP_OPS", perfetto::StaticString(activity_name), stream_track, tracer_record.timestamps.begin.value, "Agent ID", tracer_record.agent_id.handle, "Process ID", GetPid(), perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); + else if(tracer_record.phase == ROCPROFILER_PHASE_ENTER) + TRACE_EVENT_BEGIN("HIP_OPS", perfetto::StaticString(activity_name), stream_track, + timestamp.value, "Agent ID", + tracer_record.agent_id.handle, "Process ID", GetPid(), + perfetto::Flow::ProcessScoped(tracer_record.correlation_id.value)); } - TRACE_EVENT_END("HIP_OPS", stream_track, tracer_record.timestamps.end.value); + if(tracer_record.phase == ROCPROFILER_PHASE_NONE) + TRACE_EVENT_END("HIP_OPS", stream_track, tracer_record.timestamps.end.value); + else if(tracer_record.phase == ROCPROFILER_PHASE_EXIT) + TRACE_EVENT_END("HIP_OPS", stream_track, timestamp.value); break; } case ACTIVITY_DOMAIN_HSA_OPS: { diff --git a/projects/rocprofiler/src/core/session/tracer/src/roctracer.cpp b/projects/rocprofiler/src/core/session/tracer/src/roctracer.cpp index 13999f3803..6f8973c4fd 100644 --- a/projects/rocprofiler/src/core/session/tracer/src/roctracer.cpp +++ b/projects/rocprofiler/src/core/session/tracer/src/roctracer.cpp @@ -265,6 +265,7 @@ template struct ApiTracer { rocprofiler_timestamp_t{trace_data->phase_enter_timestamp}, hsa_support::timestamp_ns()}; record.thread_id = rocprofiler_thread_id_t{GetTid()}; + record.phase = ROCPROFILER_PHASE_NONE; if (auto external_id = ExternalCorrelationId()) { rocprofiler_record_tracer_t ext_record{}; @@ -275,6 +276,7 @@ template struct ApiTracer { ext_record.correlation_id = rocprofiler_tracer_activity_correlation_id_t{record.correlation_id}; ext_record.external_id = rocprofiler_tracer_external_id_t{*external_id}; + ext_record.phase = ROCPROFILER_PHASE_NONE; // Write the external correlation id record directly followed by the // activity record. rocmtools::GetROCMToolObj() @@ -400,6 +402,7 @@ int TracerCallback(activity_domain_t domain, uint32_t operation_id, void* data) rocprofiler_record.agent_id = rocprofiler_agent_id_t{(uint64_t)record->device_id}; rocprofiler_record.queue_id = rocprofiler_queue_id_t{record->queue_id}; rocprofiler_record.thread_id = rocprofiler_thread_id_t{GetTid()}; + rocprofiler_record.phase = ROCPROFILER_PHASE_NONE; if (operation_id == HIP_OP_ID_DISPATCH && record->kernel_name != nullptr) { rocprofiler_record.api_data_handle.handle = strdup(record->kernel_name); rocprofiler_record.api_data_handle.size = (strlen(record->kernel_name) + 1); @@ -462,6 +465,7 @@ int TracerCallback(activity_domain_t domain, uint32_t operation_id, void* data) rocprofiler_record.agent_id = rocprofiler_agent_id_t{(uint64_t)record->device_id}; rocprofiler_record.queue_id = rocprofiler_queue_id_t{record->queue_id}; rocprofiler_record.thread_id = rocprofiler_thread_id_t{GetTid()}; + rocprofiler_record.phase = ROCPROFILER_PHASE_NONE; if (record->kernel_name != nullptr && record->op == HSA_OP_ID_DISPATCH) { rocprofiler_record.api_data_handle.handle = strdup(record->kernel_name); rocprofiler_record.api_data_handle.size = strlen(record->kernel_name) + 1; diff --git a/projects/rocprofiler/src/core/session/tracer/tracer.cpp b/projects/rocprofiler/src/core/session/tracer/tracer.cpp index c8c9e89b24..9907f61358 100644 --- a/projects/rocprofiler/src/core/session/tracer/tracer.cpp +++ b/projects/rocprofiler/src/core/session/tracer/tracer.cpp @@ -183,11 +183,12 @@ size_t Tracer::GetHIPApiDataInfoSize(rocprofiler_tracer_hip_api_data_info_t kind return strlen(roctracer_op_string(ACTIVITY_DOMAIN_HIP_OPS, operation_id.id)) + 1; } case ROCPROFILER_HIP_STREAM_ID: { - std::lock_guard lock(stream_ids_map_lock); - if (!stream_ids.empty() && stream_ids.find(operation_id.id) != stream_ids.end()) - return std::to_string(stream_ids.at(operation_id.id).second).size() + 1; - else - return 0; + // std::lock_guard lock(stream_ids_map_lock); + // if (!stream_ids.empty() && stream_ids.find(operation_id.id) != stream_ids.end()) + // return std::to_string(stream_ids.at(operation_id.id).second).size() + 1; + // else + // return 0; + warning("Stream ID is not supported!"); } case ROCPROFILER_HIP_API_DATA: { return api_data_id.size; @@ -258,12 +259,13 @@ char* Tracer::GetHIPApiDataInfo(rocprofiler_tracer_hip_api_data_info_t kind, return const_cast(roctracer_op_string(ACTIVITY_DOMAIN_HIP_OPS, operation_id.id)); } case ROCPROFILER_HIP_STREAM_ID: { - std::lock_guard lock(stream_ids_map_lock); - if (!stream_ids.empty() && stream_ids.find(operation_id.id) != stream_ids.end()) - return strdup( - const_cast(std::to_string(stream_ids.at(operation_id.id).second).c_str())); - else - return nullptr; + // std::lock_guard lock(stream_ids_map_lock); + // if (!stream_ids.empty() && stream_ids.find(operation_id.id) != stream_ids.end()) + // return strdup( + // const_cast(std::to_string(stream_ids.at(operation_id.id).second).c_str())); + // else + // return nullptr; + warning("Stream ID is not supported!"); } case ROCPROFILER_HIP_API_DATA: { return const_cast(reinterpret_cast(api_data_id.handle)); @@ -284,7 +286,6 @@ void api_callback(activity_domain_t domain, uint32_t cid, const void* callback_d switch (domain) { case ACTIVITY_DOMAIN_ROCTX: { const roctx_api_data_t* data = reinterpret_cast(callback_data); - // if (data->args.message) roctx_labels.emplace(data->args.id, data->args.message); args_data->user_sync_callback( rocprofiler_record_tracer_t{ rocprofiler_record_header_t{ @@ -296,7 +297,7 @@ void api_callback(activity_domain_t domain, uint32_t cid, const void* callback_d rocprofiler_tracer_activity_correlation_id_t{0}, rocprofiler_record_header_timestamp_t{roctracer::hsa_support::timestamp_ns(), rocprofiler_timestamp_t{0}}, - 0, 0, GetTid()}, + 0, 0, GetTid(), ROCPROFILER_PHASE_ENTER}, args_data->session_id); break; } @@ -304,7 +305,18 @@ void api_callback(activity_domain_t domain, uint32_t cid, const void* callback_d hsa_api_data_t* data = const_cast(reinterpret_cast(callback_data)); if (data->phase == ACTIVITY_API_PHASE_ENTER) { - *(data->phase_data) = roctracer::hsa_support::timestamp_ns().value; + args_data->user_sync_callback( + rocprofiler_record_tracer_t{ + rocprofiler_record_header_t{ + ROCPROFILER_TRACER_RECORD, + rocprofiler_record_id_t{rocmtools::GetROCMToolObj()->GetUniqueRecordId()}}, + rocprofiler_tracer_external_id_t{0}, ACTIVITY_DOMAIN_HSA_API, + rocprofiler_tracer_operation_id_t{cid}, + rocprofiler_tracer_api_data_handle_t{callback_data, sizeof(*data)}, + rocprofiler_tracer_activity_correlation_id_t{data->correlation_id}, + rocprofiler_record_header_timestamp_t{rocprofiler_timestamp_t{0}, rocprofiler_timestamp_t{0}}, + 0, 0, GetTid(), ROCPROFILER_PHASE_ENTER}, + args_data->session_id); } else { args_data->user_sync_callback( rocprofiler_record_tracer_t{ @@ -315,9 +327,9 @@ void api_callback(activity_domain_t domain, uint32_t cid, const void* callback_d rocprofiler_tracer_operation_id_t{cid}, rocprofiler_tracer_api_data_handle_t{callback_data, sizeof(*data)}, rocprofiler_tracer_activity_correlation_id_t{data->correlation_id}, - rocprofiler_record_header_timestamp_t{rocprofiler_timestamp_t{*(data->phase_data)}, - roctracer::hsa_support::timestamp_ns()}, - 0, 0, GetTid()}, + rocprofiler_record_header_timestamp_t{rocprofiler_timestamp_t{0}, + rocprofiler_timestamp_t{0}}, + 0, 0, GetTid(), ROCPROFILER_PHASE_EXIT}, args_data->session_id); } break; @@ -326,32 +338,6 @@ void api_callback(activity_domain_t domain, uint32_t cid, const void* callback_d hip_api_data_t* data = const_cast(reinterpret_cast(callback_data)); if (data->phase == ACTIVITY_API_PHASE_ENTER) { - *(data->phase_data) = roctracer::hsa_support::timestamp_ns().value; - } else { - hipApiArgsInit((hip_api_id_t)cid, data); - std::string hip_api_data_string = hipApiString((hip_api_id_t)cid, data); - std::string start_str = "stream="; - int start = hip_api_data_string.find(start_str); - uint64_t stream_id = 0; - if (start >= 0) { - int end = hip_api_data_string.find(",", start); - std::string stream_id_str = hip_api_data_string.substr(start + start_str.length(), end); - std::stringstream ss; - ss << std::hex << stream_id_str; - ss >> stream_id; - } - { - std::lock_guard lock(stream_ids_map_lock); - if (used_stream_ids.find(stream_id) == used_stream_ids.end()) { - uint64_t stream_generated_id = stream_count.fetch_add(1, std::memory_order_release); - used_stream_ids.emplace(stream_id, stream_generated_id); - stream_ids.emplace(data->correlation_id, - std::make_pair(stream_id, stream_generated_id)); - } else { - stream_ids.emplace(data->correlation_id, - std::make_pair(stream_id, used_stream_ids.at(stream_id))); - } - } args_data->user_sync_callback( rocprofiler_record_tracer_t{ rocprofiler_record_header_t{ @@ -361,9 +347,48 @@ void api_callback(activity_domain_t domain, uint32_t cid, const void* callback_d rocprofiler_tracer_operation_id_t{cid}, rocprofiler_tracer_api_data_handle_t{callback_data, sizeof(*data)}, rocprofiler_tracer_activity_correlation_id_t{data->correlation_id}, - rocprofiler_record_header_timestamp_t{rocprofiler_timestamp_t{*(data->phase_data)}, - roctracer::hsa_support::timestamp_ns()}, - 0, 0, GetTid()}, + rocprofiler_record_header_timestamp_t{rocprofiler_timestamp_t{0}, + rocprofiler_timestamp_t{0}}, + 0, 0, GetTid(), ROCPROFILER_PHASE_ENTER}, + args_data->session_id); + } else { + // TODO(aelwazir): STREAM ID GET need to be removed + // hipApiArgsInit((hip_api_id_t)cid, data); + // std::string hip_api_data_string = hipApiString((hip_api_id_t)cid, data); + // std::string start_str = "stream="; + // int start = hip_api_data_string.find(start_str); + // uint64_t stream_id = 0; + // if (start >= 0) { + // int end = hip_api_data_string.find(",", start); + // std::string stream_id_str = hip_api_data_string.substr(start + start_str.length(), end); + // std::stringstream ss; + // ss << std::hex << stream_id_str; + // ss >> stream_id; + // } + // { + // std::lock_guard lock(stream_ids_map_lock); + // if (used_stream_ids.find(stream_id) == used_stream_ids.end()) { + // uint64_t stream_generated_id = stream_count.fetch_add(1, std::memory_order_release); + // used_stream_ids.emplace(stream_id, stream_generated_id); + // stream_ids.emplace(data->correlation_id, + // std::make_pair(stream_id, stream_generated_id)); + // } else { + // stream_ids.emplace(data->correlation_id, + // std::make_pair(stream_id, used_stream_ids.at(stream_id))); + // } + // } + args_data->user_sync_callback( + rocprofiler_record_tracer_t{ + rocprofiler_record_header_t{ + ROCPROFILER_TRACER_RECORD, + rocprofiler_record_id_t{rocmtools::GetROCMToolObj()->GetUniqueRecordId()}}, + rocprofiler_tracer_external_id_t{0}, ACTIVITY_DOMAIN_HIP_API, + rocprofiler_tracer_operation_id_t{cid}, + rocprofiler_tracer_api_data_handle_t{callback_data, sizeof(*data)}, + rocprofiler_tracer_activity_correlation_id_t{data->correlation_id}, + rocprofiler_record_header_timestamp_t{rocprofiler_timestamp_t{0}, + rocprofiler_timestamp_t{0}}, + 0, 0, GetTid(), ROCPROFILER_PHASE_EXIT}, args_data->session_id); } break;