SWDEV-249924 : hip correlation id explicite propogation; tracer debug instrumentation;

Change-Id: Ibbc411541f5610ce739f3fc1efa1ab7f605220f5

initial commmit

Change-Id: I34b360be62c2083819dc5c3acc8268bd69f2f58a

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 )

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<const hip_api_data_t*>(callback_data);
   hip_api_data_t* data_ptr = const_cast<hip_api_data_t*>(data);
   MemoryPool* pool = reinterpret_cast<MemoryPool*>(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<const hip_api_data_t*>(callback_data);
   hip_api_data_t* data_ptr = const_cast<hip_api_data_t*>(data);
   MemoryPool* pool = reinterpret_cast<MemoryPool*>(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 << ")");
   }

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_

test/tool/tracer_tool.cpp

@@ -26,6 +26,7 @@ THE SOFTWARE.
 #include <cxxabi.h>  /* names denangle */
 #include <dirent.h>
 #include <pthread.h>
+#include <stdarg.h>
 #include <stdio.h>
 #include <string.h>
 #include <sys/syscall.h>  /* 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<const hip_api_data_t*>(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<hip_api_data_t*>(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) {