From 9eeab1fb91a24c45ecd83057dcf3b1a370e62d36 Mon Sep 17 00:00:00 2001 From: Evgeny Date: Tue, 13 Oct 2020 16:43:18 -0500 Subject: [PATCH] SWDEV-254329 : extending debug trace with timestamps, cmake option '-DCMAKE_DEBUG_TRACE=1' Change-Id: Id16c01a6c00f6384c37fa9b5a9709a5e98e1fb57 [ROCm/roctracer commit: cb3643da05d7ede4e98414d2c0a1986455b70f29] --- projects/roctracer/src/core/roctracer.cpp | 23 ++++++++++++-------- projects/roctracer/test/tool/tracer_tool.cpp | 12 +++++----- 2 files changed, 20 insertions(+), 15 deletions(-) diff --git a/projects/roctracer/src/core/roctracer.cpp b/projects/roctracer/src/core/roctracer.cpp index 2754b97173..aa31c3997d 100644 --- a/projects/roctracer/src/core/roctracer.cpp +++ b/projects/roctracer/src/core/roctracer.cpp @@ -93,7 +93,6 @@ THE SOFTWARE. #define ONLOAD_TRACE_BEG() ONLOAD_TRACE("begin") #define ONLOAD_TRACE_END() ONLOAD_TRACE("end") - static inline uint32_t GetPid() { return syscall(__NR_getpid); } static inline uint32_t GetTid() { return syscall(__NR_gettid); } @@ -173,6 +172,9 @@ void RestoreHsaApi() { } namespace roctracer { +// timestamp definitino +typedef hsa_rt_utils::Timer::timestamp_t timestamp_t; + decltype(hsa_amd_memory_async_copy)* hsa_amd_memory_async_copy_fn; decltype(hsa_amd_memory_async_copy_rect)* hsa_amd_memory_async_copy_rect_fn; @@ -348,6 +350,8 @@ void* HIP_SyncApiDataCallback( const void* callback_data, void* arg) { + static hsa_rt_utils::Timer timer; + void* ret = NULL; const hip_api_data_t* data = reinterpret_cast(callback_data); hip_api_data_t* data_ptr = const_cast(data); @@ -393,8 +397,8 @@ void* HIP_SyncApiDataCallback( } const char * name = roctracer_op_string(ACTIVITY_DOMAIN_HIP_API, op_id, 0); - DEBUG_TRACE("HIP_SyncApiDataCallback(\"%s\") phase(%d): op(%u) record(%p) data(%p) pool(%p) depth(%d) correlation_id(%lu)\n", - name, phase, op_id, record, data, pool, (int)(record_pair_stack.size()), (data_ptr) ? data_ptr->correlation_id : 0); + DEBUG_TRACE("HIP_SyncApiDataCallback(\"%s\") phase(%d): op(%u) record(%p) data(%p) pool(%p) depth(%d) correlation_id(%lu) time_ns(%lu)\n", + name, phase, op_id, record, data, pool, (int)(record_pair_stack.size()), (data_ptr) ? data_ptr->correlation_id : 0, timer.timestamp_ns()); return ret; } @@ -406,6 +410,7 @@ void* HIP_SyncActivityCallback( void* arg) { static hsa_rt_utils::Timer timer; + const timestamp_t timestamp_ns = timer.timestamp_ns(); void* ret = NULL; const hip_api_data_t* data = reinterpret_cast(callback_data); @@ -436,7 +441,7 @@ void* HIP_SyncActivityCallback( // Filing record info record->domain = ACTIVITY_DOMAIN_HIP_API; record->op = op_id; - record->begin_ns = timer.timestamp_ns(); + record->begin_ns = timestamp_ns; // Correlation ID generating uint64_t correlation_id = data->correlation_id; @@ -461,7 +466,7 @@ void* HIP_SyncActivityCallback( } // Filing record info - record->end_ns = timer.timestamp_ns(); + record->end_ns = timestamp_ns; record->process_id = syscall(__NR_getpid); record->thread_id = syscall(__NR_gettid); @@ -485,8 +490,8 @@ void* HIP_SyncActivityCallback( } const char * name = roctracer_op_string(ACTIVITY_DOMAIN_HIP_API, op_id, 0); - DEBUG_TRACE("HIP_SyncActivityCallback(\"%s\") phase(%d): op(%u) record(%p) data(%p) pool(%p) depth(%d) correlation_id(%lu)\n", - name, phase, op_id, record, data, pool, (int)(record_pair_stack.size()), (data_ptr) ? data_ptr->correlation_id : 0); + DEBUG_TRACE("HIP_SyncActivityCallback(\"%s\") phase(%d): op(%u) record(%p) data(%p) pool(%p) depth(%d) correlation_id(%lu) beg_ns(%lu) end_ns(%lu)\n", + name, phase, op_id, record, data, pool, (int)(record_pair_stack.size()), (data_ptr) ? data_ptr->correlation_id : 0, timestamp_ns); return ret; } @@ -503,8 +508,8 @@ void HCC_AsyncActivityCallback(uint32_t op_id, void* record, void* arg) { pool->Write(*record_ptr); const char * name = roctracer_op_string(ACTIVITY_DOMAIN_HCC_OPS, record_ptr->op, record_ptr->kind); - DEBUG_TRACE("HCC_AsyncActivityCallback(\"%s\"): op(%u) kind(%u) record(%p) pool(%p) correlation_id(%d)\n", - name, record_ptr->op, record_ptr->kind, record, pool, record_ptr->correlation_id); + DEBUG_TRACE("HCC_AsyncActivityCallback(\"%s\"): op(%u) kind(%u) record(%p) pool(%p) correlation_id(%d) beg_ns(%lu) end_ns(%lu)\n", + name, record_ptr->op, record_ptr->kind, record, pool, record_ptr->correlation_id, record_ptr->begin_ns, record_ptr->end_ns); } // Open output file diff --git a/projects/roctracer/test/tool/tracer_tool.cpp b/projects/roctracer/test/tool/tracer_tool.cpp index d6be6f4fc0..1aeb75a301 100644 --- a/projects/roctracer/test/tool/tracer_tool.cpp +++ b/projects/roctracer/test/tool/tracer_tool.cpp @@ -454,8 +454,8 @@ void hip_api_callback( } const char * name = roctracer_op_string(domain, cid, 0); - DEBUG_TRACE("hip_api_callback(\"%s\") phase(%d): cid(%u) data(%p) entry(%p) name(\"%s\") correlation_id(%lu)\n", - name, data->phase, cid, data, entry, (entry) ? entry->name : NULL, data->correlation_id); + DEBUG_TRACE("hip_api_callback(\"%s\") phase(%d): cid(%u) data(%p) entry(%p) name(\"%s\") correlation_id(%lu) timestamp(%lu)\n", + name, data->phase, cid, data, entry, (entry) ? entry->name : NULL, data->correlation_id, timestamp); } void mark_api_callback( @@ -500,8 +500,8 @@ void hip_api_flush_cb(hip_api_trace_entry_t* entry) { oss << std::dec << rec_ss.str() << " " << str; const char * name = roctracer_op_string(entry->domain, entry->cid, 0); - DEBUG_TRACE("hip_api_flush_cb(\"%s\"): domain(%u) cid(%u) entry(%p) name(\"%s\" correlation_id(%lu))\n", - name, entry->domain, entry->cid, entry, entry->name, correlation_id); + DEBUG_TRACE("hip_api_flush_cb(\"%s\"): domain(%u) cid(%u) entry(%p) name(\"%s\" correlation_id(%lu) beg(%lu) end(%lu))\n", + name, entry->domain, entry->cid, entry, entry->name, correlation_id, begin_timestamp, end_timestamp); if (domain == ACTIVITY_DOMAIN_HIP_API) { #if HIP_PROF_HIP_API_STRING @@ -631,8 +631,8 @@ void pool_activity_callback(const char* begin, const char* end, void* arg) { while (record < end_record) { const char * name = roctracer_op_string(record->domain, record->op, record->kind); - DEBUG_TRACE("pool_activity_callback(\"%s\"): domain(%u) op(%u) kind(%u) record(%p) correlation_id(%lu)\n", - name, record->domain, record->op, record->kind, record, record->correlation_id); + DEBUG_TRACE("pool_activity_callback(\"%s\"): domain(%u) op(%u) kind(%u) record(%p) correlation_id(%lu) beg(%lu) end(%lu)\n", + name, record->domain, record->op, record->kind, record, record->correlation_id, record->begin_ns, record->end_ns); switch(record->domain) { case ACTIVITY_DOMAIN_HCC_OPS: