diff --git a/cmake_modules/env.cmake b/cmake_modules/env.cmake index 41f6253afc..405f2665cf 100644 --- a/cmake_modules/env.cmake +++ b/cmake_modules/env.cmake @@ -61,8 +61,11 @@ if ( "$ENV{CXX}" STREQUAL "/usr/bin/clang++" ) endif() ## Enable debug trace +if ( DEFINED CMAKE_DEBUG_TRACE ) + add_definitions ( -DDEBUG_TRACE_ON=1 ) +endif() if ( DEFINED ENV{CMAKE_DEBUG_TRACE} ) - add_definitions ( -DDEBUG_TRACE=1 ) + add_definitions ( -DDEBUG_TRACE_ON=1 ) endif() if ( NOT DEFINED LIBRARY_TYPE ) diff --git a/src/core/roctracer.cpp b/src/core/roctracer.cpp index 52f1e28bf4..21f4b6674d 100644 --- a/src/core/roctracer.cpp +++ b/src/core/roctracer.cpp @@ -95,6 +95,7 @@ THE SOFTWARE. static inline uint32_t GetPid() { return syscall(__NR_getpid); } +static inline uint32_t GetTid() { return syscall(__NR_gettid); } /////////////////////////////////////////////////////////////////////////////////////////////////// // Mark callback @@ -294,13 +295,19 @@ static inline void CorrelationIdRegistr(const activity_correlation_id_t& correla if (correlation_id_map == NULL) correlation_id_map = new correlation_id_map_t; const auto ret = correlation_id_map->insert({correlation_id, correlation_id_tls}); if (ret.second == false) EXC_ABORT(ROCTRACER_STATUS_ERROR, "HCC activity id is not unique(" << correlation_id << ")"); + + DEBUG_TRACE("CorrelationIdRegistr id(%lu) id_tls(%lu)\n", correlation_id, correlation_id_tls); } static inline activity_correlation_id_t CorrelationIdLookup(const activity_correlation_id_t& correlation_id) { auto it = correlation_id_map->find(correlation_id); if (correlation_id_wait) while (it == correlation_id_map->end()) it = correlation_id_map->find(correlation_id); if (it == correlation_id_map->end()) EXC_ABORT(ROCTRACER_STATUS_ERROR, "HCC activity id lookup failed(" << correlation_id << ")"); - return it->second; + const activity_correlation_id_t ret_val = it->second; + + DEBUG_TRACE("CorrelationIdLookup id(%lu) ret(%lu)\n", correlation_id, ret_val); + + return ret_val; } typedef std::mutex hip_activity_mutex_t; @@ -341,6 +348,7 @@ void* HIP_SyncApiDataCallback( const void* callback_data, void* arg) { + void* ret = NULL; const hip_api_data_t* data = reinterpret_cast(callback_data); hip_api_data_t* data_ptr = const_cast(data); MemoryPool* pool = reinterpret_cast(arg); @@ -375,16 +383,20 @@ void* HIP_SyncApiDataCallback( // Passing correlatin ID correlation_id_tls = correlation_id; - return data_ptr; + ret = data_ptr; } else { // popping the record entry if (!record_pair_stack.empty()) record_pair_stack.pop(); // Clearing correlatin ID correlation_id_tls = 0; - - return NULL; } + + 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); + + return ret; } void* HIP_SyncActivityCallback( @@ -395,6 +407,7 @@ void* HIP_SyncActivityCallback( { 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); MemoryPool* pool = reinterpret_cast(arg); @@ -436,7 +449,7 @@ void* HIP_SyncActivityCallback( // Passing correlatin ID correlation_id_tls = correlation_id; - return data_ptr; + ret = data_ptr; } else { if (pool == NULL) EXC_ABORT(ROCTRACER_STATUS_ERROR, "ActivityCallback exit: pool is NULL"); @@ -469,9 +482,13 @@ void* HIP_SyncActivityCallback( // Clearing correlatin ID correlation_id_tls = 0; - - return NULL; } + + 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); + + return ret; } void HCC_ActivityIdCallback(activity_correlation_id_t correlation_id) { @@ -484,6 +501,10 @@ void HCC_AsyncActivityCallback(uint32_t op_id, void* record, void* arg) { record_ptr->domain = ACTIVITY_DOMAIN_HCC_OPS; record_ptr->correlation_id = CorrelationIdLookup(record_ptr->correlation_id); 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); } // Open output file @@ -673,6 +694,8 @@ PUBLIC_API const char* roctracer_op_string( return roctracer::HipLoader::Instance().ApiName(op); case ACTIVITY_DOMAIN_KFD_API: return roctracer::kfd_support::GetApiName(op); + case ACTIVITY_DOMAIN_EXT_API: + return "EXT_API"; default: EXC_RAISING(ROCTRACER_STATUS_BAD_DOMAIN, "invalid domain ID(" << domain << ")"); } diff --git a/src/util/logger.h b/src/util/logger.h index cd8dd470c3..8e525f68ea 100644 --- a/src/util/logger.h +++ b/src/util/logger.h @@ -100,10 +100,10 @@ class Logger { return *obj; } - private: static uint32_t GetPid() { return syscall(__NR_getpid); } static uint32_t GetTid() { return syscall(__NR_gettid); } + private: Logger() : file_(NULL), dirty_(false), streaming_(false), messaging_(false) { const char* path = getenv("ROCTRACER_LOG"); if (path != NULL) { @@ -198,4 +198,20 @@ class Logger { } while(0) #endif +#if DEBUG_TRACE_ON +inline static void DEBUG_TRACE(const char* fmt, ...) { + constexpr int size = 256; + char buf[size]; + + va_list valist; + va_start(valist, fmt); + vsnprintf(buf, size, fmt, valist); + printf("%u:%u %s", + roctracer::util::Logger::GetPid(), roctracer::util::Logger::GetTid(), buf); fflush(stdout); + va_end(valist); +} +#else +inline static void DEBUG_TRACE(const char* fmt, ...) {} +#endif + #endif // SRC_UTIL_LOGGER_H_ diff --git a/test/tool/tracer_tool.cpp b/test/tool/tracer_tool.cpp index 4aa1b68210..d6be6f4fc0 100644 --- a/test/tool/tracer_tool.cpp +++ b/test/tool/tracer_tool.cpp @@ -26,6 +26,7 @@ THE SOFTWARE. #include /* names denangle */ #include #include +#include #include #include #include /* SYS_xxx definitions */ @@ -78,6 +79,24 @@ 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); } + +#if DEBUG_TRACE_ON +inline static void DEBUG_TRACE(const char* fmt, ...) { + constexpr int size = 256; + char buf[size]; + + va_list valist; + va_start(valist, fmt); + vsnprintf(buf, size, fmt, valist); + printf("%u:%u %s", GetPid(), GetTid(), buf); fflush(stdout); + va_end(valist); +} +#else +inline static void DEBUG_TRACE(const char* fmt, ...) {} +#endif + typedef hsa_rt_utils::Timer::timestamp_t timestamp_t; hsa_rt_utils::Timer* timer = NULL; thread_local timestamp_t hsa_begin_timestamp = 0; @@ -125,9 +144,6 @@ void close_file_handles() { if (pc_sample_file_handle) close_output_file(pc_sample_file_handle); } -static inline uint32_t GetPid() { return syscall(__NR_getpid); } -static inline uint32_t GetTid() { return syscall(__NR_gettid); } - static const uint32_t my_pid = GetPid(); // Error handler @@ -378,19 +394,20 @@ void hip_api_callback( { (void)arg; const hip_api_data_t* data = reinterpret_cast(callback_data); + const timestamp_t timestamp = timer->timestamp_fn_ns(); + hip_api_trace_entry_t* entry = NULL; if (data->phase == ACTIVITY_API_PHASE_ENTER) { - hip_begin_timestamp = timer->timestamp_fn_ns(); + hip_begin_timestamp = timestamp; } else { // Post onit of HIP APU args 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(); + entry = hip_api_trace_buffer->GetEntry(); entry->cid = cid; entry->domain = domain; entry->begin = hip_begin_timestamp; - entry->end = end_timestamp; + entry->end = timestamp; entry->pid = GetPid(); entry->tid = GetTid(); entry->data = *data; @@ -435,6 +452,10 @@ void hip_api_callback( entry->valid.store(roctracer::TRACE_ENTRY_COMPL, std::memory_order_release); } + + 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); } void mark_api_callback( @@ -465,12 +486,10 @@ 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); + const uint64_t correlation_id = data->correlation_id; const timestamp_t begin_timestamp = entry->begin; const timestamp_t end_timestamp = entry->end; std::ostringstream rec_ss; @@ -480,6 +499,10 @@ void hip_api_flush_cb(hip_api_trace_entry_t* entry) { rec_ss << std::dec << begin_timestamp << ":" << end_timestamp << " " << entry->pid << ":" << entry->tid; 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); + if (domain == ACTIVITY_DOMAIN_HIP_API) { #if HIP_PROF_HIP_API_STRING if (hip_api_stats != NULL) { @@ -496,6 +519,7 @@ void hip_api_flush_cb(hip_api_trace_entry_t* entry) { const char* kernel_name = cxx_demangle(entry->name); rec_ss << " kernel=" << kernel_name; } + rec_ss<< " :" << correlation_id; fprintf(hip_api_file_handle, "%s\n", rec_ss.str().c_str()); } #else // !HIP_PROF_HIP_API_STRING @@ -607,6 +631,9 @@ 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); + switch(record->domain) { case ACTIVITY_DOMAIN_HCC_OPS: if (hip_memcpy_stats != NULL) {