From 7ea0e5b6575a3d43df484e8ad207ebc5f8359d84 Mon Sep 17 00:00:00 2001 From: Jiho Chu Date: Fri, 23 Dec 2022 16:01:20 +0900 Subject: [PATCH] [Utils] Add trace feature 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 --- meson.build | 4 + meson_options.txt | 1 + nntrainer/layers/layer_node.cpp | 10 +- nntrainer/utils/meson.build | 5 + nntrainer/utils/tracer.cpp | 122 ++++++++++++++++++++++ nntrainer/utils/tracer.h | 222 ++++++++++++++++++++++++++++++++++++++++ 6 files changed, 363 insertions(+), 1 deletion(-) create mode 100644 nntrainer/utils/tracer.cpp create mode 100644 nntrainer/utils/tracer.h diff --git a/meson.build b/meson.build index 711165d..d0ba3a6 100644 --- a/meson.build +++ b/meson.build @@ -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 diff --git a/meson_options.txt b/meson_options.txt index 88f5d8e..992b85a 100644 --- a/meson_options.txt +++ b/meson_options.txt @@ -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) diff --git a/nntrainer/layers/layer_node.cpp b/nntrainer/layers/layer_node.cpp index 527b8de..fbc0dc4 100644 --- a/nntrainer/layers/layer_node.cpp +++ b/nntrainer/layers/layer_node.cpp @@ -27,6 +27,7 @@ #include #include #include +#include #include namespace nntrainer { @@ -588,6 +589,8 @@ InitLayerContext LayerNode::finalize(const std::vector &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 diff --git a/nntrainer/utils/meson.build b/nntrainer/utils/meson.build index 20d95bd..22791e1 100644 --- a/nntrainer/utils/meson.build +++ b/nntrainer/utils/meson.build @@ -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 index 0000000..e437fd2 --- /dev/null +++ b/nntrainer/utils/tracer.cpp @@ -0,0 +1,122 @@ +// SPDX-License-Identifier: Apache-2.0 +/** + * Copyright (C) 2022 Jiho Chu + * + * @file trace.cpp + * @date 23 December 2022 + * @brief trace class + * @see https://github.com/nnstreamer/nntrainer + * @author Jiho Chu + * @bug No known bugs except for NYI items + * + */ + +#include "tracer.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +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(getpid())) + ".log"; +}; + +unsigned long getMemoryUsage(void) { + std::ifstream ifs("/proc/self/smaps", std::ios::in); + std::istream_iterator it(ifs); + unsigned long total = 0; + + while (it != std::istream_iterator()) { + 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::system_clock::now().time_since_epoch() - start) + .count(); + + return ms; +} + +} // namespace + +namespace nntrainer { + +std::unique_ptr &MemoryTracer::getInstance() { + static std::unique_ptr 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::getInstance() { + static std::unique_ptr 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 index 0000000..36c992d --- /dev/null +++ b/nntrainer/utils/tracer.h @@ -0,0 +1,222 @@ +// SPDX-License-Identifier: Apache-2.0 +/** + * Copyright (C) 2022 Jiho Chu + * + * @file tracer.h + * @date 23 December 2022 + * @brief Trace abstract class + * @see https://github.com/nnstreamer/nntrainer + * @author Jiho Chu + * @bug No known bugs except for NYI items + * + */ + +#ifndef __TRACER_H__ +#define __TRACER_H__ + +#include +#include +#include +#include +#include +#include +#include +#include + +#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 + inline typename std::enable_if::type + write(std::ofstream &out, std::tuple &t) {} + + /** + * @brief Write trace message + * @param[in] out output stream + * @param[in] t tuple to write + */ + template + inline typename std::enable_if < + I::type write(std::ofstream &out, + std::tuple &t) { + out << std::get(t) << "\t"; + write(out, t); + } + + /** + * @brief Write trace information to file + * @param[in] filename file name to write + * @param[in] trace_info trace information to write + */ + template + void writeToFile(std::string filename, std::list &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 &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> + 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 &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> + 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__ */ -- 2.7.4