From ddcb68d0a82e2284dbaf9552571efd8c2e65f807 Mon Sep 17 00:00:00 2001 From: Evgeny Date: Tue, 11 Aug 2020 04:44:08 -0500 Subject: [PATCH] optimized tool stats Change-Id: Ia9c06879f6e2e195e589c53299c2cafe96a4bfe5 --- src/core/roctracer.cpp | 12 +-- src/core/trace_buffer.h | 21 ++++- src/proxy/intercept_queue.h | 4 +- test/CMakeLists.txt | 2 +- test/tool/tracer_tool.cpp | 163 ++++++++++++++++++++++++++++++------ 5 files changed, 166 insertions(+), 36 deletions(-) diff --git a/src/core/roctracer.cpp b/src/core/roctracer.cpp index 2d15bbba38..dd47bb0f0a 100644 --- a/src/core/roctracer.cpp +++ b/src/core/roctracer.cpp @@ -218,11 +218,12 @@ template<> bool act_en_functor_t::fun(const act_en_functor_t::record_t& record) void hsa_async_copy_handler(::proxy::Tracker::entry_t* entry); void hsa_kernel_handler(::proxy::Tracker::entry_t* entry); -TraceBuffer::flush_prm_t trace_buffer_prm[] = { +constexpr TraceBuffer::flush_prm_t trace_buffer_prm[] = { {COPY_ENTRY_TYPE, hsa_async_copy_handler}, {KERNEL_ENTRY_TYPE, hsa_kernel_handler} }; -TraceBuffer trace_buffer("HSA GPU", 0x200000, trace_buffer_prm, 2); +TraceBuffer* trace_buffer = NULL; +//TraceBuffer trace_buffer("HSA GPU", 0x200000, trace_buffer_prm, 2); namespace hsa_support { // callbacks table @@ -567,7 +568,7 @@ hsa_status_t hsa_amd_memory_async_copy_interceptor( { hsa_status_t status = HSA_STATUS_SUCCESS; if (hsa_support::async_copy_callback_enabled) { - trace_entry_t* entry = trace_buffer.GetEntry(); + trace_entry_t* entry = trace_buffer->GetEntry(); ::proxy::Tracker::Enable(COPY_ENTRY_TYPE, hsa_agent_t{}, completion_signal, entry); status = hsa_amd_memory_async_copy_fn(dst, dst_agent, src, src_agent, size, num_dep_signals, @@ -591,7 +592,7 @@ hsa_status_t hsa_amd_memory_async_copy_rect_interceptor( { hsa_status_t status = HSA_STATUS_SUCCESS; if (hsa_support::async_copy_callback_enabled) { - trace_entry_t* entry = trace_buffer.GetEntry(); + trace_entry_t* entry = trace_buffer->GetEntry(); ::proxy::Tracker::Enable(COPY_ENTRY_TYPE, hsa_agent_t{}, completion_signal, entry); status = hsa_amd_memory_async_copy_rect_fn(dst, dst_offset, src, src_offset, range, copy_agent, @@ -1289,13 +1290,14 @@ PUBLIC_API void roctracer_unload() { PUBLIC_API void roctracer_flush_buf() { ONLOAD_TRACE_BEG(); - roctracer::trace_buffer.Flush(); + roctracer::trace_buffer->Flush(); ONLOAD_TRACE_END(); } CONSTRUCTOR_API void constructor() { ONLOAD_TRACE_BEG(); roctracer::util::Logger::Create(); + roctracer::trace_buffer = new roctracer::TraceBuffer("HSA GPU", 0x200000, roctracer::trace_buffer_prm, 2); roctracer_load(); ONLOAD_TRACE_END(); } diff --git a/src/core/trace_buffer.h b/src/core/trace_buffer.h index cd62dda735..8d99404631 100644 --- a/src/core/trace_buffer.h +++ b/src/core/trace_buffer.h @@ -124,7 +124,7 @@ class TraceBuffer : protected TraceBufferBase { callback_t fun; }; - TraceBuffer(const char* name, uint32_t size, flush_prm_t* flush_prm_arr, uint32_t flush_prm_count) : + TraceBuffer(const char* name, uint32_t size, const flush_prm_t* flush_prm_arr, uint32_t flush_prm_count, uint32_t prior = 0) : is_flushed_(false), work_thread_started_(false) { @@ -139,12 +139,14 @@ class TraceBuffer : protected TraceBufferBase { flush_prm_arr_ = flush_prm_arr; flush_prm_count_ = flush_prm_count; + priority_ = prior; + TraceBufferBase::Push(this); } ~TraceBuffer() { StopWorkerThread(); - Flush(); + FlushAll(); } void StartWorkerThread() { @@ -176,14 +178,24 @@ class TraceBuffer : protected TraceBufferBase { } void Flush() { flush_buf(); } + void Flush(const bool& b) { + DisableFlushing(!b); + flush_buf(); + } + void DisableFlushing(const bool& b) { is_flushed_.exchange(b, std::memory_order_acquire); } private: void flush_buf() { std::lock_guard lck(mutex_); const bool is_flushed = is_flushed_.exchange(true, std::memory_order_acquire); + if (priority_ != 0) { + priority_ -= 1; + return; + } + if (is_flushed == false) { - for (flush_prm_t* prm = flush_prm_arr_; prm < flush_prm_arr_ + flush_prm_count_; prm++) { + for (const flush_prm_t* prm = flush_prm_arr_; prm < flush_prm_arr_ + flush_prm_count_; prm++) { // Flushed entries type uint32_t type = prm->type; // Flushing function @@ -253,8 +265,9 @@ class TraceBuffer : protected TraceBufferBase { volatile std::atomic end_pointer_; std::list buf_list_; - flush_prm_t* flush_prm_arr_; + const flush_prm_t* flush_prm_arr_; uint32_t flush_prm_count_; + uint32_t priority_; volatile std::atomic is_flushed_; pthread_t work_thread_; diff --git a/src/proxy/intercept_queue.h b/src/proxy/intercept_queue.h index f92f1ce6bc..000c7e8810 100644 --- a/src/proxy/intercept_queue.h +++ b/src/proxy/intercept_queue.h @@ -39,7 +39,7 @@ THE SOFTWARE. #include "util/hsa_rsrc_factory.h" #include "util/exception.h" -namespace roctracer { extern TraceBuffer trace_buffer; } +namespace roctracer { extern TraceBuffer* trace_buffer; } namespace rocprofiler { extern decltype(hsa_queue_create)* hsa_queue_create_fn; @@ -160,7 +160,7 @@ class InterceptQueue { const char* kernel_name = GetKernelName(kernel_symbol); // Adding kernel timing tracker - ::proxy::Tracker::entry_t* entry = roctracer::trace_buffer.GetEntry(); + ::proxy::Tracker::entry_t* entry = roctracer::trace_buffer->GetEntry(); entry->kernel.tid = syscall(__NR_gettid); entry->kernel.name = kernel_name; ::proxy::Tracker::Enable(roctracer::KERNEL_ENTRY_TYPE, obj->agent_info_->dev_id, completion_signal, entry); diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 3e3b9654f3..6a6d7d17d9 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -44,7 +44,7 @@ endif () ## Path to HSA test set ( HSA_TEST_DIR "${TEST_DIR}/hsa/test" ) -set ( HSA_REV "5b47aae" ) +set ( HSA_REV "a657002" ) ## test run script set ( RUN_SCRIPT "${TEST_DIR}/run.sh" ) diff --git a/test/tool/tracer_tool.cpp b/test/tool/tracer_tool.cpp index df2530a510..db87d04d8f 100644 --- a/test/tool/tracer_tool.cpp +++ b/test/tool/tracer_tool.cpp @@ -42,6 +42,7 @@ THE SOFTWARE. #include "src/core/loader.h" #include "src/core/trace_buffer.h" +#include "util/evt_stats.h" #include "util/hsa_rsrc_factory.h" #include "util/xml.h" @@ -96,6 +97,12 @@ std::vector kfd_api_vec; LOADER_INSTANTIATE(); TRACE_BUFFER_INSTANTIATE(); +typedef EvtStatsT EvtStatsA; +// HIP stats +EvtStats* hip_api_stats = NULL; +EvtStatsA* hip_kernel_stats = NULL; +EvtStatsA* hip_memcpy_stats = NULL; + // Global output file handle FILE* begin_ts_file_handle = NULL; FILE* roctx_file_handle = NULL; @@ -137,7 +144,7 @@ static inline const char* cxx_demangle(const char* symbol) { size_t funcnamesize; int status; const char* ret = (symbol != NULL) ? abi::__cxa_demangle(symbol, NULL, &funcnamesize, &status) : symbol; - return (ret != NULL) ? ret : symbol; + return (ret != NULL) ? ret : strdup(symbol); } // Tracing control thread @@ -208,8 +215,9 @@ struct roctx_trace_entry_t { }; void roctx_flush_cb(roctx_trace_entry_t* entry); -roctracer::TraceBuffer::flush_prm_t roctx_flush_prm[1] = {{0, roctx_flush_cb}}; -roctracer::TraceBuffer roctx_trace_buffer("rocTX API", 0x200000, roctx_flush_prm, 1); +constexpr roctracer::TraceBuffer::flush_prm_t roctx_flush_prm[1] = {{0, roctx_flush_cb}}; +roctracer::TraceBuffer* roctx_trace_buffer = NULL; +//roctracer::TraceBuffer roctx_trace_buffer("rocTX API", 0x200000, roctx_flush_prm, 1); // rocTX callback function static inline void roctx_callback_fun( @@ -224,7 +232,7 @@ static inline void roctx_callback_fun( #else const timestamp_t time = timer->timestamp_fn_ns(); #endif - roctx_trace_entry_t* entry = roctx_trace_buffer.GetEntry(); + roctx_trace_entry_t* entry = roctx_trace_buffer->GetEntry(); entry->valid = roctracer::TRACE_ENTRY_COMPL; entry->type = 0; entry->cid = cid; @@ -286,8 +294,9 @@ struct hsa_api_trace_entry_t { }; void hsa_api_flush_cb(hsa_api_trace_entry_t* entry); -roctracer::TraceBuffer::flush_prm_t hsa_flush_prm[1] = {{0, hsa_api_flush_cb}}; -roctracer::TraceBuffer hsa_api_trace_buffer("HSA API", 0x200000, hsa_flush_prm, 1); +constexpr roctracer::TraceBuffer::flush_prm_t hsa_flush_prm[1] = {{0, hsa_api_flush_cb}}; +roctracer::TraceBuffer* hsa_api_trace_buffer = NULL; +//roctracer::TraceBuffer hsa_api_trace_buffer("HSA API", 0x200000, hsa_flush_prm, 1); // HSA API callback function void hsa_api_callback( @@ -302,7 +311,7 @@ void hsa_api_callback( hsa_begin_timestamp = timer->timestamp_fn_ns(); } else { const timestamp_t end_timestamp = (cid == HSA_API_ID_hsa_shut_down) ? hsa_begin_timestamp : timer->timestamp_fn_ns(); - hsa_api_trace_entry_t* entry = hsa_api_trace_buffer.GetEntry(); + hsa_api_trace_entry_t* entry = hsa_api_trace_buffer->GetEntry(); entry->valid = roctracer::TRACE_ENTRY_COMPL; entry->type = 0; entry->cid = cid; @@ -348,8 +357,9 @@ struct hip_api_trace_entry_t { }; void hip_api_flush_cb(hip_api_trace_entry_t* entry); -roctracer::TraceBuffer::flush_prm_t hip_flush_prm[1] = {{0, hip_api_flush_cb}}; -roctracer::TraceBuffer hip_api_trace_buffer("HIP", 0x200000, hip_flush_prm, 1); +constexpr roctracer::TraceBuffer::flush_prm_t hip_api_flush_prm[1] = {{0, hip_api_flush_cb}}; +roctracer::TraceBuffer* hip_api_trace_buffer = NULL; +//roctracer::TraceBuffer hip_api_trace_buffer("HIP API", 0x200000, hip_api_flush_prm, 1); static inline bool is_hip_kernel_launch_api(const uint32_t& cid) { bool ret = @@ -379,7 +389,7 @@ void hip_api_callback( hipApiArgsInit((hip_api_id_t)cid, const_cast(data)); const timestamp_t end_timestamp = timer->timestamp_fn_ns(); - hip_api_trace_entry_t* entry = hip_api_trace_buffer.GetEntry(); + hip_api_trace_entry_t* entry = hip_api_trace_buffer->GetEntry(); entry->valid = roctracer::TRACE_ENTRY_COMPL; entry->type = 0; entry->cid = cid; @@ -440,7 +450,7 @@ void mark_api_callback( const char* name = reinterpret_cast(callback_data); const timestamp_t timestamp = timer->timestamp_fn_ns(); - hip_api_trace_entry_t* entry = hip_api_trace_buffer.GetEntry(); + hip_api_trace_entry_t* entry = hip_api_trace_buffer->GetEntry(); entry->valid = roctracer::TRACE_ENTRY_COMPL; entry->type = 0; entry->cid = 0; @@ -454,7 +464,14 @@ void mark_api_callback( entry->ptr = NULL; } +typedef std::map hip_kernel_map_t; +hip_kernel_map_t* hip_kernel_map = NULL; +std::mutex hip_kernel_mutex; + void hip_api_flush_cb(hip_api_trace_entry_t* entry) { + static uint64_t correlation_id = 0; + correlation_id += 1; + const uint32_t domain = entry->domain; const uint32_t cid = entry->cid; const hip_api_data_t* data = &(entry->data); @@ -469,12 +486,22 @@ void hip_api_flush_cb(hip_api_trace_entry_t* entry) { if (domain == ACTIVITY_DOMAIN_HIP_API) { #if HIP_PROF_HIP_API_STRING - const char* str = hipApiString((hip_api_id_t)cid, data); - rec_ss << " " << str; - if (is_hip_kernel_launch_api(cid)) { - if (entry->name) rec_ss << " kernel=" << cxx_demangle(entry->name); + if (hip_api_stats != NULL) { + hip_api_stats->add_event(cid, end_timestamp - begin_timestamp); + if (is_hip_kernel_launch_api(cid)) { + hip_kernel_mutex.lock(); + (*hip_kernel_map)[correlation_id] = entry->name; + hip_kernel_mutex.unlock(); + } + } else { + const char* str = hipApiString((hip_api_id_t)cid, data); + rec_ss << " " << str; + if (is_hip_kernel_launch_api(cid) && entry->name) { + const char* kernel_name = cxx_demangle(entry->name); + rec_ss << " kernel=" << kernel_name; + } + fprintf(hip_api_file_handle, "%s\n", rec_ss.str().c_str()); } - fprintf(hip_api_file_handle, "%s\n", rec_ss.str().c_str()); #else // !HIP_PROF_HIP_API_STRING switch (cid) { case HIP_API_ID_hipMemcpy: @@ -536,6 +563,47 @@ void hip_api_flush_cb(hip_api_trace_entry_t* entry) { fflush(hip_api_file_handle); } +/////////////////////////////////////////////////////////////////////////////////////////////////////// +// HSA API tracing + +struct hip_act_trace_entry_t { + uint32_t valid; + uint32_t type; + uint32_t kind; + timestamp_t dur; + uint64_t correlation_id; +}; + +void hip_act_flush_cb(hip_act_trace_entry_t* entry); +constexpr roctracer::TraceBuffer::flush_prm_t hip_act_flush_prm[1] = {{0, hip_act_flush_cb}}; +roctracer::TraceBuffer* hip_act_trace_buffer = NULL; +//roctracer::TraceBuffer hip_act_trace_buffer("HIP ACT", 0x200000, hip_act_flush_prm, 1); + +// HIP ACT trace buffer flush callback +void hip_act_flush_cb(hip_act_trace_entry_t* entry) { + const uint32_t domain = ACTIVITY_DOMAIN_HCC_OPS; + const uint32_t op = 0; + const char * name = roctracer_op_string(domain, op, entry->kind); + if (name == NULL) { + printf("hip_act_flush_cb name is NULL\n"); fflush(stdout); + abort(); + } + + if (strncmp("Kernel", name, 6) == 0) { + hip_kernel_mutex.lock(); + if (hip_kernel_stats == NULL) { + printf("hip_act_flush_cb hip_kernel_stats is NULL\n"); fflush(stdout); + abort(); + } + name = (*hip_kernel_map)[entry->correlation_id]; + hip_kernel_mutex.unlock(); + const char* kernel_name = cxx_demangle(name); + hip_kernel_stats->add_event(kernel_name, entry->dur); + } else { + hip_memcpy_stats->add_event(name, entry->dur); + } +} + // Activity tracing callback // hipMalloc id(3) correlation_id(1): begin_ns(1525888652762640464) end_ns(1525888652762877067) void pool_activity_callback(const char* begin, const char* end, void* arg) { @@ -546,11 +614,20 @@ void pool_activity_callback(const char* begin, const char* end, void* arg) { const char * name = roctracer_op_string(record->domain, record->op, record->kind); switch(record->domain) { case ACTIVITY_DOMAIN_HCC_OPS: - fprintf(hcc_activity_file_handle, "%lu:%lu %d:%lu %s:%lu:%u\n", - record->begin_ns, record->end_ns, - record->device_id, record->queue_id, - name, record->correlation_id, my_pid); - fflush(hcc_activity_file_handle); + if (hip_memcpy_stats != NULL) { + hip_act_trace_entry_t* entry = hip_act_trace_buffer->GetEntry(); + entry->valid = roctracer::TRACE_ENTRY_COMPL; + entry->type = 0; + entry->kind = record->kind; + entry->dur = record->end_ns - record->begin_ns; + entry->correlation_id = record->correlation_id; + } else { + fprintf(hcc_activity_file_handle, "%lu:%lu %d:%lu %s:%lu:%u\n", + record->begin_ns, record->end_ns, + record->device_id, record->queue_id, + name, record->correlation_id, my_pid); + fflush(hcc_activity_file_handle); + } break; case ACTIVITY_DOMAIN_HSA_OPS: if (record->op == HSA_OP_ID_RESERVED1) { @@ -639,8 +716,10 @@ int get_xml_array(const xml::Xml::level_t* node, const std::string& field, const } // Open output file -FILE* open_output_file(const char* prefix, const char* name) { +FILE* open_output_file(const char* prefix, const char* name, const char** path = NULL) { FILE* file_handle = NULL; + if (path != NULL) *path = NULL; + if (prefix != NULL) { std::ostringstream oss; oss << prefix << "/" << GetPid() << "_" << name; @@ -651,6 +730,8 @@ FILE* open_output_file(const char* prefix, const char* name) { perror(errmsg.str().c_str()); abort(); } + + if (path != NULL) *path = strdup(oss.str().c_str()); } else file_handle = stdout; return file_handle; } @@ -720,6 +801,7 @@ void tool_unload() { // Flush tracing pool close_tracing_pool(); roctracer::TraceBufferBase::FlushAll(); + hip_act_trace_buffer->Flush(true); close_file_handles(); ONLOAD_TRACE_END(); @@ -979,15 +1061,40 @@ extern "C" PUBLIC_API bool OnLoad(HsaApiTable* table, uint64_t runtime_version, roctracer_set_properties(ACTIVITY_DOMAIN_HIP_API, (void*)mark_api_callback); // Allocating tracing pool open_tracing_pool(); + + // Check for optimized stats + const bool is_stats_opt = (getenv("ROCP_STATS_OPT") != NULL); + + // HIP kernel ma pinstantiation + if (is_stats_opt) hip_kernel_map = new hip_kernel_map_t; + // Enable tracing if (trace_hip_api) { hip_api_file_handle = open_output_file(output_prefix, "hip_api_trace.txt"); ROCTRACER_CALL(roctracer_enable_domain_callback(ACTIVITY_DOMAIN_HIP_API, hip_api_callback, NULL)); - ROCTRACER_CALL(roctracer_enable_domain_activity(ACTIVITY_DOMAIN_HIP_API)); + + if (is_stats_opt) { + const char* path = NULL; + FILE* f = open_output_file(output_prefix, "hip_api_stats.csv", &path); + hip_api_stats = new EvtStats(f, path); + for (uint32_t id = 0; id < HIP_API_ID_NUMBER; id += 1) { + const char* label = roctracer_op_string(ACTIVITY_DOMAIN_HIP_API, id, 0); + hip_api_stats->set_label(id, label); + } + } } if (trace_hip_activity) { hcc_activity_file_handle = open_output_file(output_prefix, "hcc_ops_trace.txt"); ROCTRACER_CALL(roctracer_enable_domain_activity(ACTIVITY_DOMAIN_HCC_OPS)); + + if (is_stats_opt) { + FILE* f = NULL; + const char* path = NULL; + f = open_output_file(output_prefix, "hip_kernel_stats.csv", &path); + hip_kernel_stats = new EvtStatsA(f, path); + f = open_output_file(output_prefix, "hip_memcpy_stats.csv", &path); + hip_memcpy_stats = new EvtStatsA(f, path); + } } } @@ -1010,6 +1117,10 @@ extern "C" PUBLIC_API void OnUnload() { extern "C" CONSTRUCTOR_API void constructor() { ONLOAD_TRACE_BEG(); + roctx_trace_buffer = new roctracer::TraceBuffer("rocTX API", 0x200000, roctx_flush_prm, 1); + hip_api_trace_buffer = new roctracer::TraceBuffer("HIP API", 0x200000, hip_api_flush_prm, 1); + hip_act_trace_buffer = new roctracer::TraceBuffer("HIP ACT", 0x200000, hip_act_flush_prm, 1, 1); + hsa_api_trace_buffer = new roctracer::TraceBuffer("HSA API", 0x200000, hsa_flush_prm, 1); roctracer_load(); tool_load(); ONLOAD_TRACE_END(); @@ -1018,7 +1129,11 @@ extern "C" DESTRUCTOR_API void destructor() { ONLOAD_TRACE_BEG(); roctracer_flush_buf(); tool_unload(); + + if (hip_api_stats) hip_api_stats->dump(); + if (hip_kernel_stats) hip_kernel_stats->dump(); + if (hip_memcpy_stats) hip_memcpy_stats->dump(); + roctracer_unload(); ONLOAD_TRACE_END(); } -