[RUNTIME] Add device specific timers

include/tvm/runtime/profiling.h

@@ -0,0 +1,150 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+/*!
+ * \file include/tvm/runtime/profiling.h
+ * \brief Runtime profiling including timers.
+ */
+#ifndef TVM_RUNTIME_PROFILING_H_
+#define TVM_RUNTIME_PROFILING_H_
+
+#include <dlpack/dlpack.h>
+#include <tvm/runtime/c_runtime_api.h>
+#include <tvm/runtime/device_api.h>
+#include <tvm/runtime/object.h>
+#include <tvm/runtime/registry.h>
+
+#include <chrono>
+#include <map>
+#include <string>
+
+namespace tvm {
+namespace runtime {
+
+/*! \brief Base class for all implementations.
+ *
+ * New implementations of this interface should make sure that `Start` and `Stop`
+ * are as lightweight as possible. Expensive state synchronization should be
+ * done in `SyncAndGetTime`.
+ */
+class TimerNode : public Object {
+ public:
+  /*! \brief Start the timer.
+   *
+   * Note: this function should only be called once per object.
+   */
+  virtual void Start() = 0;
+  /*! \brief Stop the timer.
+   *
+   * Note: this function should only be called once per object.
+   */
+  virtual void Stop() = 0;
+  /*! \brief Synchronize timer state and return elapsed time between `Start` and `Stop`.
+   * \return The time in nanoseconds between `Start` and `Stop`.
+   *
+   * This function is necessary because we want to avoid timing the overhead of
+   * doing timing. When using multiple timers, it is recommended to stop all of
+   * them before calling `SyncAndGetTime` on any of them.
+   *
+   * Note: this function should be only called once per object. It may incur
+   * a large synchronization overhead (for example, with GPUs).
+   */
+  virtual int64_t SyncAndGetTime() = 0;
+
+  virtual ~TimerNode() {}
+
+  static constexpr const char* _type_key = "TimerNode";
+  TVM_DECLARE_BASE_OBJECT_INFO(TimerNode, Object);
+};
+
+/*! \brief Timer for a specific device.
+ *
+ * You should not construct this class directly. Instead use `StartTimer`.
+ */
+class Timer : public ObjectRef {
+ public:
+  /*! \brief Start the timer.
+   *
+   * Note: this function should only be called once per object.
+   */
+  void Start() { operator->()->Start(); }
+  /*! \brief Stop the timer.
+   *
+   * Note: this function should only be called once per object.
+   */
+  void Stop() { operator->()->Stop(); }
+  /*! \brief Synchronize timer state and return elapsed time between `Start` and `Stop`.
+   * \return The time in nanoseconds between `Start` and `Stop`.
+   *
+   * This function is necessary because we want to avoid timing the overhead of
+   * doing timing. When using multiple timers, it is recommended to stop all of
+   * them before calling `SyncAndGetTime` on any of them.
+   *
+   * Note: this function should be only called once per object. It may incur
+   * a large synchronization overhead (for example, with GPUs).
+   */
+  int64_t SyncAndGetTime() { return operator->()->SyncAndGetTime(); }
+  TVM_DEFINE_MUTABLE_OBJECT_REF_METHODS(Timer, ObjectRef, TimerNode);
+};
+
+/*!
+ * \brief Default timer if one does not exist to the platform.
+ * \param ctx The context to time on.
+ *
+ * Note that this timer performs synchronization between the device and CPU,
+ * which can lead to overhead in the reported results.
+ */
+Timer DefaultTimer(TVMContext ctx);
+
+/*!
+ * \brief Get a device specific timer.
+ * \param ctx The device context to time.
+ * \return A `Timer` that has already been started.
+ *
+ * Example usage:
+ * \code{.cpp}
+ * Timer t = StartTimer(TVMContext::cpu());
+ * my_long_running_function();
+ * t.Stop();
+ * ... // some more computation
+ * int64_t nanosecs = t.SyncAndGetTime() // elapsed time in nanoseconds
+ * \endcode
+ *
+ * To add a new device-specific timer, register a new function
+ * "profiler.timer.my_device" (where `my_device` is the `DeviceName` of your
+ * device). This function should accept a `TVMContext` and return a new `Timer`
+ * that has already been started.
+ */
+inline Timer StartTimer(TVMContext ctx) {
+  auto f = Registry::Get(std::string("profiling.timer.") + DeviceName(ctx.device_type));
+  if (f == nullptr) {
+    Timer t = DefaultTimer(ctx);
+    t.Start();
+    return t;
+  } else {
+    Timer t = f->operator()(ctx);
+    t.Start();
+    return t;
+  }
+}
+
+}  // namespace runtime
+}  // namespace tvm
+
+#endif  // TVM_RUNTIME_PROFILING_H_

src/runtime/cuda/cuda_device_api.cc

@@ -25,6 +25,7 @@
 #include <cuda_runtime.h>
 #include <dmlc/thread_local.h>
 #include <tvm/runtime/device_api.h>
+#include <tvm/runtime/profiling.h>
 #include <tvm/runtime/registry.h>
 
 #include <cstring>
@@ -241,5 +242,38 @@ TVM_REGISTER_GLOBAL("device_api.cpu_pinned").set_body([](TVMArgs args, TVMRetVal
   *rv = static_cast<void*>(ptr);
 });
 
+class GPUTimerNode : public TimerNode {
+ public:
+  virtual void Start() { cudaEventRecord(start_, CUDAThreadEntry::ThreadLocal()->stream); }
+  virtual void Stop() { cudaEventRecord(stop_, CUDAThreadEntry::ThreadLocal()->stream); }
+  virtual int64_t SyncAndGetTime() {
+    cudaEventSynchronize(stop_);
+    float milliseconds = 0;
+    cudaEventElapsedTime(&milliseconds, start_, stop_);
+    return milliseconds * 1e6;
+  }
+  virtual ~GPUTimerNode() {
+    cudaEventDestroy(start_);
+    cudaEventDestroy(stop_);
+  }
+  GPUTimerNode() {
+    cudaEventCreate(&start_);
+    cudaEventCreate(&stop_);
+  }
+
+  static constexpr const char* _type_key = "GPUTimerNode";
+  TVM_DECLARE_FINAL_OBJECT_INFO(GPUTimerNode, TimerNode);
+
+ private:
+  cudaEvent_t start_;
+  cudaEvent_t stop_;
+};
+
+TVM_REGISTER_OBJECT_TYPE(GPUTimerNode);
+
+TVM_REGISTER_GLOBAL("profiling.timer.gpu").set_body_typed([](TVMContext ctx) {
+  return Timer(make_object<GPUTimerNode>());
+});
+
 }  // namespace runtime
 }  // namespace tvm

src/runtime/graph/debug/graph_runtime_debug.cc

@@ -23,6 +23,7 @@
 #include <tvm/runtime/container.h>
 #include <tvm/runtime/ndarray.h>
 #include <tvm/runtime/packed_func.h>
+#include <tvm/runtime/profiling.h>
 #include <tvm/runtime/registry.h>
 
 #include <chrono>
@@ -77,16 +78,25 @@ class GraphRuntimeDebug : public GraphRuntime {
                                                number * 1.618));  // 1.618 is chosen by random
           }
           tbegin = std::chrono::high_resolution_clock::now();
+          std::vector<std::vector<Timer>> op_timers;
+          for (size_t index = 0; index < op_execs_.size(); index++) {
+            op_timers.push_back({});
+          }
           for (int k = 0; k < number; k++) {
             for (size_t index = 0; index < op_execs_.size(); ++index) {
               if (op_execs_[index]) {
-                time_sec_per_op[index] += RunOpHost(index);
+                op_timers[index].push_back(RunOpHost(index));
               }
             }
           }
+          for (size_t index = 0; index < op_execs_.size(); ++index) {
+            for (auto t : op_timers[index]) {
+              time_sec_per_op[index] += t.SyncAndGetTime() / 1e9;
+            }
+          }
           tend = std::chrono::high_resolution_clock::now();
           duration_ms =
-              std::chrono::duration_cast<std::chrono::duration<double> >(tend - tbegin).count() *
+              std::chrono::duration_cast<std::chrono::duration<double>>(tend - tbegin).count() *
               1000;
         } while (duration_ms < min_repeat_ms);
 
@@ -147,15 +157,12 @@ class GraphRuntimeDebug : public GraphRuntime {
     return results_arr[0];
   }
 
-  double RunOpHost(int index) {
-    auto op_tbegin = std::chrono::high_resolution_clock::now();
-    op_execs_[index]();
+  Timer RunOpHost(int index) {
     const TVMContext& ctx = data_entry_[entry_id(index, 0)]->ctx;
-    TVMSynchronize(ctx.device_type, ctx.device_id, nullptr);
-    auto op_tend = std::chrono::high_resolution_clock::now();
-    double op_duration =
-        std::chrono::duration_cast<std::chrono::duration<double> >(op_tend - op_tbegin).count();
-    return op_duration;
+    Timer t = StartTimer(ctx);
+    op_execs_[index]();
+    t.Stop();
+    return t;
   }
 
   /*!

src/runtime/profiling.cc

@@ -0,0 +1,81 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+/*!
+ * \file src/runtime/profiling.cc
+ * \brief Runtime profiling including timers.
+ */
+
+#include <tvm/runtime/packed_func.h>
+#include <tvm/runtime/profiling.h>
+
+namespace tvm {
+namespace runtime {
+
+class DefaultTimerNode : public TimerNode {
+ public:
+  virtual void Start() {
+    TVMSynchronize(ctx_.device_type, ctx_.device_id, nullptr);
+    start_ = std::chrono::high_resolution_clock::now();
+  }
+  virtual void Stop() {
+    TVMSynchronize(ctx_.device_type, ctx_.device_id, nullptr);
+    duration_ = std::chrono::high_resolution_clock::now() - start_;
+  }
+  virtual int64_t SyncAndGetTime() { return duration_.count(); }
+  virtual ~DefaultTimerNode() {}
+
+  explicit DefaultTimerNode(TVMContext ctx) : ctx_(ctx) {}
+  static constexpr const char* _type_key = "DefaultTimerNode";
+  TVM_DECLARE_FINAL_OBJECT_INFO(DefaultTimerNode, TimerNode);
+
+ private:
+  std::chrono::high_resolution_clock::time_point start_;
+  std::chrono::duration<int64_t, std::nano> duration_;
+  TVMContext ctx_;
+};
+
+TVM_REGISTER_OBJECT_TYPE(DefaultTimerNode);
+TVM_REGISTER_OBJECT_TYPE(TimerNode);
+
+Timer DefaultTimer(TVMContext ctx) { return Timer(make_object<DefaultTimerNode>(ctx)); }
+
+class CPUTimerNode : public TimerNode {
+ public:
+  virtual void Start() { start_ = std::chrono::high_resolution_clock::now(); }
+  virtual void Stop() { duration_ = std::chrono::high_resolution_clock::now() - start_; }
+  virtual int64_t SyncAndGetTime() { return duration_.count(); }
+  virtual ~CPUTimerNode() {}
+
+  static constexpr const char* _type_key = "CPUTimerNode";
+  TVM_DECLARE_FINAL_OBJECT_INFO(CPUTimerNode, TimerNode);
+
+ private:
+  std::chrono::high_resolution_clock::time_point start_;
+  std::chrono::duration<int64_t, std::nano> duration_;
+};
+TVM_REGISTER_OBJECT_TYPE(CPUTimerNode);
+
+TVM_REGISTER_GLOBAL("profiling.timer.cpu").set_body_typed([](TVMContext ctx) {
+  return Timer(make_object<CPUTimerNode>());
+});
+
+TVM_REGISTER_GLOBAL("profiling.start_timer").set_body_typed(StartTimer);
+}  // namespace runtime
+}  // namespace tvm

src/runtime/rocm/rocm_device_api.cc

@@ -200,5 +200,39 @@ TVM_REGISTER_GLOBAL("device_api.rocm").set_body([](TVMArgs args, TVMRetValue* rv
   DeviceAPI* ptr = ROCMDeviceAPI::Global();
   *rv = static_cast<void*>(ptr);
 });
+
+class ROCMTimerNode : public TimerNode {
+ public:
+  virtual void Start() { hipEventRecord(start_, ROCMThreadEntry::ThreadLocal()->stream); }
+  virtual void Stop() { hipEventRecord(stop_, ROCMThreadEntry::ThreadLocal()->stream); }
+  virtual int64_t SyncAndGetTime() {
+    hipEventSynchronize(stop_);
+    float milliseconds = 0;
+    hipEventElapsedTime(&milliseconds, start_, stop_);
+    return milliseconds * 1e6;
+  }
+  virtual ~ROCMTimerNode() {
+    hipEventDestroy(start_);
+    hipEventDestroy(stop_);
+  }
+  ROCMTimerNode() {
+    hipEventCreate(&start_);
+    hipEventCreate(&stop_);
+  }
+
+  static constexpr const char* _type_key = "ROCMTimerNode";
+  TVM_DECLARE_FINAL_OBJECT_INFO(ROCMTimerNode, TimerNode);
+
+ private:
+  hipEvent_t start_;
+  hipEvent_t stop_;
+};
+
+TVM_REGISTER_OBJECT_TYPE(ROCMTimerNode);
+
+TVM_REGISTER_GLOBAL("profiling.timer.rocm").set_body_typed([](TVMContext ctx) {
+  return Timer(make_object<ROCMTimerNode>());
+});
+
 }  // namespace runtime
 }  // namespace tvm