[Utils] Add trace feature
authorJiho Chu <jiho.chu@samsung.com>
Fri, 23 Dec 2022 07:01:20 +0000 (16:01 +0900)
committerMyungJoo Ham <myungjoo.ham@samsung.com>
Fri, 27 Jan 2023 01:09:58 +0000 (10:09 +0900)
Trace feature enables easily trace information through training
step. It can include memory and time tracing, and futher informations
could be included.
The memory trace is defaultly written to memory_trace_$PID.log,
while time trace is written to time_trace_$PID.log.

Signed-off-by: Jiho Chu <jiho.chu@samsung.com>
meson.build
meson_options.txt
nntrainer/layers/layer_node.cpp
nntrainer/utils/meson.build
nntrainer/utils/tracer.cpp [new file with mode: 0644]
nntrainer/utils/tracer.h [new file with mode: 0644]

index 711165d..d0ba3a6 100644 (file)
@@ -183,6 +183,10 @@ if get_option('enable-profile')
   extra_defines += '-DPROFILE=1'
 endif
 
+if get_option('enable-trace')
+  extra_defines += '-DTRACE=1'
+endif
+
 if get_option('enable-debug')
   extra_defines += '-DDEBUG=1'
 endif
index 88f5d8e..992b85a 100644 (file)
@@ -10,6 +10,7 @@ option('enable-tizen-feature-check', type: 'boolean', value: true)
 option('enable-nnstreamer-backbone', type: 'boolean', value: false)
 option('enable-tflite-backbone', type: 'boolean', value: true)
 option('enable-profile', type: 'boolean', value: false)
+option('enable-trace', type: 'boolean', value: false)
 option('enable-debug', type: 'boolean', value: false)
 option('enable-tflite-interpreter', type: 'boolean', value: true)
 option('enable-memory-swap', type: 'boolean', value: false)
index 527b8de..fbc0dc4 100644 (file)
@@ -27,6 +27,7 @@
 #include <node_exporter.h>
 #include <profiler.h>
 #include <time_dist.h>
+#include <tracer.h>
 #include <util_func.h>
 
 namespace nntrainer {
@@ -588,6 +589,8 @@ InitLayerContext LayerNode::finalize(const std::vector<TensorDim> &input_dims) {
  */
 void LayerNode::forwarding(bool training) {
   loss->set(run_context->getRegularizationLoss());
+  TRACE_MEMORY() << getName() + ": F";
+  TRACE_TIME() << getName() + ": F";
   PROFILE_TIME_START(forward_event_key);
   layer->forwarding(*run_context, training);
   PROFILE_TIME_END(forward_event_key);
@@ -607,6 +610,8 @@ void LayerNode::forwarding(bool training) {
  * @brief     calc the derivative to be passed to the previous layer
  */
 void LayerNode::calcDerivative() {
+  TRACE_MEMORY() << getName() + ": CD";
+  TRACE_TIME() << getName() + ": CD";
   PROFILE_TIME_START(calc_deriv_event_key);
   layer->calcDerivative(*run_context);
   PROFILE_TIME_END(calc_deriv_event_key);
@@ -623,8 +628,11 @@ void LayerNode::calcDerivative() {
  */
 void LayerNode::calcGradient() {
   PROFILE_TIME_START(calc_grad_event_key);
-  if (needs_calc_gradient)
+  if (needs_calc_gradient) {
+    TRACE_MEMORY() << getName() + ": CG";
+    TRACE_TIME() << getName() + ": CG";
     layer->calcGradient(*run_context);
+  }
   PROFILE_TIME_END(calc_grad_event_key);
 
 #ifdef DEBUG
index 20d95bd..22791e1 100644 (file)
@@ -15,6 +15,11 @@ util_headers = [
   'nntr_threads.h'
 ]
 
+if get_option('enable-trace')
+  util_sources += 'tracer.cpp'
+  util_headers += 'tracer.h'
+endif
+
 foreach s : util_sources
   nntrainer_sources += meson.current_source_dir() / s
 endforeach
diff --git a/nntrainer/utils/tracer.cpp b/nntrainer/utils/tracer.cpp
new file mode 100644 (file)
index 0000000..e437fd2
--- /dev/null
@@ -0,0 +1,122 @@
+// SPDX-License-Identifier: Apache-2.0
+/**
+ * Copyright (C) 2022 Jiho Chu <jjiho.chu@samsung.com>
+ *
+ * @file   trace.cpp
+ * @date   23 December 2022
+ * @brief  trace class
+ * @see    https://github.com/nnstreamer/nntrainer
+ * @author Jiho Chu <jiho.chu@samsung.com>
+ * @bug    No known bugs except for NYI items
+ *
+ */
+
+#include "tracer.h"
+
+#include <algorithm>
+#include <chrono>
+#include <fstream>
+#include <functional>
+#include <iterator>
+#include <list>
+#include <sys/types.h>
+#include <tuple>
+#include <unistd.h>
+
+namespace {
+
+const std::string memory_trace_tag = "memory_trace";
+const std::string time_trace_tag = "time_trace";
+
+auto outputFileName = [](std::string name) -> std::string {
+  return name + "_" + std::to_string(static_cast<int>(getpid())) + ".log";
+};
+
+unsigned long getMemoryUsage(void) {
+  std::ifstream ifs("/proc/self/smaps", std::ios::in);
+  std::istream_iterator<std::string> it(ifs);
+  unsigned long total = 0;
+
+  while (it != std::istream_iterator<std::string>()) {
+    if (*it == "Rss:") {
+      ++it;
+      total += std::stoul(*it);
+    }
+    ++it;
+  }
+
+  return total;
+}
+
+unsigned long getTimeStamp(void) {
+  static auto start = std::chrono::system_clock::now().time_since_epoch();
+  auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+              std::chrono::system_clock::now().time_since_epoch() - start)
+              .count();
+
+  return ms;
+}
+
+} // namespace
+
+namespace nntrainer {
+
+std::unique_ptr<MemoryTracer> &MemoryTracer::getInstance() {
+  static std::unique_ptr<MemoryTracer> instance;
+  static std::once_flag flag;
+
+  std::call_once(flag,
+                 []() { instance.reset(new MemoryTracer(memory_trace_tag)); });
+  return instance;
+}
+
+MemoryTracer::MemoryTracer(const std::string &name, bool flush) :
+  Tracer(name),
+  flush_(flush) {
+  std::ofstream ifs(outputFileName(name), std::fstream::trunc);
+  trace_info_.emplace_back(getMemoryUsage(), "start");
+  if (flush_)
+    writeToFile(outputFileName(name), trace_info_);
+}
+
+MemoryTracer::~MemoryTracer() {
+  writeToFile(outputFileName(name_), trace_info_);
+}
+
+Tracer &MemoryTracer::tracePoint(const std::string &msg) {
+  trace_info_.emplace_back(getMemoryUsage(), msg);
+  if (flush_)
+    writeToFile(outputFileName(name_), trace_info_);
+
+  return (*this);
+}
+
+std::unique_ptr<TimeTracer> &TimeTracer::getInstance() {
+  static std::unique_ptr<TimeTracer> instance;
+  static std::once_flag flag;
+
+  std::call_once(flag,
+                 []() { instance.reset(new TimeTracer(time_trace_tag)); });
+  return instance;
+}
+
+TimeTracer::TimeTracer(const std::string &name, bool flush_) :
+  Tracer(name),
+  flush_(flush_) {
+  std::ofstream ifs(outputFileName(name), std::fstream::trunc);
+  trace_info_.emplace_back(getTimeStamp(), "start");
+  if (flush_)
+    writeToFile(outputFileName(name), trace_info_);
+}
+
+TimeTracer::~TimeTracer() { writeToFile(outputFileName(name_), trace_info_); }
+
+Tracer &TimeTracer::tracePoint(const std::string &msg) {
+  trace_info_.emplace_back(getTimeStamp(), msg);
+  if (flush_)
+    writeToFile(outputFileName(name_), trace_info_);
+
+  return (*this);
+}
+
+} // namespace nntrainer
diff --git a/nntrainer/utils/tracer.h b/nntrainer/utils/tracer.h
new file mode 100644 (file)
index 0000000..36c992d
--- /dev/null
@@ -0,0 +1,222 @@
+// SPDX-License-Identifier: Apache-2.0
+/**
+ * Copyright (C) 2022 Jiho Chu <jiho.chu@samsung.com>
+ *
+ * @file   tracer.h
+ * @date   23 December 2022
+ * @brief  Trace abstract class
+ * @see    https://github.com/nnstreamer/nntrainer
+ * @author Jiho Chu <jiho.chu@samsung.com>
+ * @bug    No known bugs except for NYI items
+ *
+ */
+
+#ifndef __TRACER_H__
+#define __TRACER_H__
+
+#include <exception>
+#include <fstream>
+#include <list>
+#include <memory>
+#include <mutex>
+#include <string>
+#include <tuple>
+#include <type_traits>
+
+#ifdef TRACE
+
+namespace nntrainer {
+
+/**
+ * @class   Tracer
+ * @brief   Tracer class
+ */
+class Tracer {
+public:
+  /**
+   * @brief     Constructor of Tracer
+   */
+  Tracer(const std::string &name) : name_(name) {}
+
+  /**
+   * @brief     Destructor of Tracer
+   */
+  virtual ~Tracer() = default;
+
+  /**
+   * @brief     Start tracing
+   */
+  virtual Tracer &traceStart(const std::string &tag,
+                             const std::string &msg) = 0;
+
+  /**
+   * @brief     End tracing
+   */
+  virtual Tracer &traceEnd(const std::string &tag) = 0;
+
+  /**
+   * @brief     Trace point
+   */
+  virtual Tracer &tracePoint(const std::string &msg) = 0;
+
+protected:
+  /**
+   * @brief     Write trace message (final tuple)
+   */
+  template <std::size_t I = 0, typename... Tp>
+  inline typename std::enable_if<I == sizeof...(Tp), void>::type
+  write(std::ofstream &out, std::tuple<Tp...> &t) {}
+
+  /**
+   * @brief     Write trace message
+   * @param[in] out output stream
+   * @param[in] t tuple to write
+   */
+  template <std::size_t I = 0, typename... Tp>
+    inline typename std::enable_if <
+    I<sizeof...(Tp), void>::type write(std::ofstream &out,
+                                       std::tuple<Tp...> &t) {
+    out << std::get<I>(t) << "\t";
+    write<I + 1, Tp...>(out, t);
+  }
+
+  /**
+   * @brief     Write trace information to file
+   * @param[in] filename file name to write
+   * @param[in] trace_info trace information to write
+   */
+  template <typename T>
+  void writeToFile(std::string filename, std::list<T> &trace_info) {
+    std::ofstream file(filename, std::fstream::app);
+    if (!file.is_open()) {
+      throw std::runtime_error("Cannot open file: " + filename);
+    }
+
+    for (auto &i : trace_info) {
+      write(file, i);
+      file << std::endl;
+    }
+
+    trace_info.clear();
+  }
+
+  const std::string name_; /**< name of the tracer */
+};
+
+/**
+ * @class   MemoryTracer
+ * @brief   Memory Tracer class
+ */
+class MemoryTracer : public Tracer {
+public:
+  /**
+   * @brief     Destructor of Tracer
+   */
+  virtual ~MemoryTracer();
+
+  /**
+   * @brief     Get instance of MemoryTracer
+   */
+  static std::unique_ptr<MemoryTracer> &getInstance();
+
+  /**
+   * @brief     Start tracing
+   */
+  Tracer &traceStart(const std::string &tag, const std::string &msg) override {
+    return (*this);
+  }
+
+  /**
+   * @brief     End tracing
+   */
+  Tracer &traceEnd(const std::string &tag) override { return (*this); }
+
+  /**
+   * @brief     Trace point
+   */
+  Tracer &tracePoint(const std::string &msg) override;
+
+  /**
+   * @brief     Operator overload for << to trace point
+   */
+  Tracer &operator<<(const std::string &msg) { return tracePoint(msg); }
+
+private:
+  /**
+   * @brief     Constructor of MemoryTracer
+   */
+  MemoryTracer(const std::string &name, bool flush = false);
+
+  std::list<std::tuple<unsigned long, std::string>>
+    trace_info_; /**< memory usage, msg */
+  bool flush_;   /**< flush to file */
+};
+
+/**
+ * @class   TiemTracer
+ * @brief   Time Tracer class
+ */
+class TimeTracer : public Tracer {
+public:
+  /**
+   * @brief     Destructor of Tracer
+   */
+  virtual ~TimeTracer();
+
+  /**
+   * @brief     Get instance of TimeTracer
+   */
+  static std::unique_ptr<TimeTracer> &getInstance();
+
+  /**
+   * @brief     Start tracing
+   */
+  Tracer &traceStart(const std::string &tag, const std::string &msg) override {
+    return (*this);
+  }
+
+  /**
+   * @brief     End tracing
+   */
+  Tracer &traceEnd(const std::string &tag) override { return (*this); }
+
+  /**
+   * @brief     Trace point
+   */
+  Tracer &tracePoint(const std::string &msg) override;
+
+  /**
+   * @brief     Operator overload for << to trace point
+   */
+  Tracer &operator<<(const std::string &msg) { return tracePoint(msg); }
+
+private:
+  /**
+   * @brief     Constructor of TimeTracer
+   */
+  TimeTracer(const std::string &name, bool flush = false);
+
+  std::list<std::tuple<unsigned long, std::string>>
+    trace_info_; /**< time point (ms), msg */
+  bool flush_;   /**< flush to file */
+};
+
+} // namespace nntrainer
+
+#define TRACE_MEMORY_POINT(msg) \
+  nntrainer::MemoryTracer::getInstance()->tracePoint(msg)
+#define TRACE_MEMORY() *(nntrainer::MemoryTracer::getInstance())
+#define TRACE_TIME_POINT(msg) \
+  nntrainer::TimeTracer::getInstance()->tracePoint(msg)
+#define TRACE_TIME() *(nntrainer::TimeTracer::getInstance())
+
+#else
+
+#define TRACE_MEMORY_POINT(msg)
+#define TRACE_MEMORY() std::ostream(nullptr)
+#define TRACE_TIME_POINT(msg)
+#define TRACE_TIME() std::ostream(nullptr)
+
+#endif
+
+#endif /* __TRACER_H__ */