Add changes to record kernel start and end timestamps

Signed-off-by: rbramand <[email protected]>

src/runtime_src/core/common/api/hw_context_int.h

@@ -32,9 +32,12 @@ get_core_device_raw(const xrt::hw_context& ctx);
 void
 set_exclusive(xrt::hw_context& ctx);
 
+// Get xclbin uuid associated with this context
 xrt::uuid
 get_xclbin_uuid(const xrt::hw_context& hwctx);
 
+// Get underlying hw ctx handle, this is used to uniquely identify
+// hw ctx when logging info related to it
 xrt_core::hwctx_handle*
 get_hwctx_handle(const xrt::hw_context& hwctx);
 

src/runtime_src/core/common/api/kernel_int.h

@@ -86,6 +86,7 @@ get_regmap_size(const xrt::kernel& kernel);
 std::string
 get_kernel_name(const xrt::kernel& kernel);
 
+// Get hw ctx using which this kernel is created
 xrt::hw_context
 get_hw_ctx(const xrt::kernel& kernel);
 

src/runtime_src/core/common/api/xrt_bo.cpp

@@ -170,6 +170,12 @@ class device_type
 
 } // namespace
 
+namespace xrt_core {
+buffer_handle::buffer_handle()
+  : m_usage_logger(usage_metrics::get_usage_metrics_logger())
+{}
+} // namespace xrt_core
+
 namespace xrt {
 
 // class bo_impl - Base class for buffer objects
@@ -1003,9 +1009,7 @@ alloc_bo(const device_type& device, void* userptr, size_t sz, xrtBufferFlags fla
     ? hwctx->alloc_bo(userptr, sz, xflags.all)
     : device->alloc_bo(userptr, sz, xflags.all);
 
-  auto logger = xrt_core::usage_metrics::get_usage_metrics_logger();
-  bo->set_usage_logger(logger);
-  logger->log_buffer_info_construct(device->get_device_id(), sz, hwctx);
+  bo->get_usage_logger()->log_buffer_info_construct(device->get_device_id(), sz, hwctx);
 
   return bo;
 }
@@ -1024,10 +1028,8 @@ alloc_bo(const device_type& device, size_t sz, xrtBufferFlags flags, xrtMemoryGr
     auto bo = hwctx
       ? hwctx->alloc_bo(sz, xflags.all)
       : device->alloc_bo(sz, xflags.all);
-
-    auto logger = xrt_core::usage_metrics::get_usage_metrics_logger();
-    bo->set_usage_logger(logger);
-    logger->log_buffer_info_construct(device->get_device_id(), sz, hwctx);
+
+    bo->get_usage_logger()->log_buffer_info_construct(device->get_device_id(), sz, hwctx);
 
     return bo;
   }

src/runtime_src/core/common/api/xrt_hw_context.cpp

@@ -119,7 +119,7 @@ class hw_context_impl : public std::enable_shared_from_this<hw_context_impl>
     return m_hdl.get();
   }
 
-  inline std::shared_ptr<xrt_core::usage_metrics::base_logger>
+  std::shared_ptr<xrt_core::usage_metrics::base_logger>
   get_usage_logger()
   {
     return m_usage_logger;

src/runtime_src/core/common/api/xrt_kernel.cpp

@@ -2348,7 +2348,7 @@ class run_impl
     // This is in critical path, we need to reduce log overhead 
     // as much as possible, passing kernel impl pointer instead of 
     // constructing args in place
-    m_usage_logger->log_kernel_start_info(kernel.get(), this);
+    m_usage_logger->log_kernel_run_info(kernel.get(), this, true, ERT_CMD_STATE_NEW);
     cmd->run();
   }
 
@@ -2429,14 +2429,21 @@ class run_impl
   ert_cmd_state
   wait(const std::chrono::milliseconds& timeout_ms) const
   {
+    ert_cmd_state state {ERT_CMD_STATE_NEW}; // initial value doesn't matter
     if (timeout_ms.count()) {
       auto [ert_state, cv_status] = cmd->wait(timeout_ms);
-      return (cv_status == std::cv_status::timeout)
-        ? ERT_CMD_STATE_TIMEOUT
-        : ert_state;
+      if (cv_status == std::cv_status::timeout)
+        return ERT_CMD_STATE_TIMEOUT;
+
+      state = ert_state;
+    }
+    else {
+      state = cmd->wait();
     }
 
-    return cmd->wait();
+    m_usage_logger->log_kernel_run_info(kernel.get(), this, false, state);
+
+    return state;
   }
 
 
@@ -2459,8 +2466,10 @@ class run_impl
       state = cmd->wait();
     }
 
-    if (state == ERT_CMD_STATE_COMPLETED)
+    if (state == ERT_CMD_STATE_COMPLETED) {
+      m_usage_logger->log_kernel_run_info(kernel.get(), this, false, state);
       return std::cv_status::no_timeout;
+    }
 
     std::string msg = "Command failed to complete successfully (" + cmd_state_to_string(state) + ")";
     throw xrt::run::command_error(state, msg);

src/runtime_src/core/common/device.cpp

@@ -37,7 +37,8 @@ namespace xrt_core {
 
 device::
 device(id_type device_id)
-  : m_device_id(device_id), m_usage_logger(usage_metrics::get_usage_metrics_logger())
+  : m_device_id(device_id)
+  , m_usage_logger(usage_metrics::get_usage_metrics_logger())
 {
   XRT_DEBUGF("xrt_core::device::device(0x%x) idx(%d)\n", this, device_id);
 }

src/runtime_src/core/common/device.h

@@ -467,7 +467,7 @@ class device : public ishim
   /**
    * get_usage_logger() - get usage metrics logger
    */
-  inline std::shared_ptr<usage_metrics::base_logger>
+  std::shared_ptr<usage_metrics::base_logger>
   get_usage_logger()
   {
     return m_usage_logger;

src/runtime_src/core/common/shim/buffer_handle.h

@@ -40,6 +40,9 @@ class buffer_handle
   };
 
 public:
+  XCL_DRIVER_DLLESPEC
+  buffer_handle();
+
   virtual ~buffer_handle()
   {}
 
@@ -79,20 +82,14 @@ class buffer_handle
     return XRT_NULL_BO;
   }
 
-  inline void
-  set_usage_logger(std::shared_ptr<xrt_core::usage_metrics::base_logger> logger)
-  {
-    m_usage_logger = logger;
-  }
-
-  inline std::shared_ptr<xrt_core::usage_metrics::base_logger>
+  std::shared_ptr<usage_metrics::base_logger>
   get_usage_logger()
   {
     return m_usage_logger;
   }
 
 private:
-  std::shared_ptr<xrt_core::usage_metrics::base_logger> m_usage_logger; 
+  std::shared_ptr<usage_metrics::base_logger> m_usage_logger; 
 };
 
 } // xrt_core