[Debugging] Add log verbose mode for debugging.
authorDongju Chae <dongju.chae@samsung.com>
Fri, 19 Jun 2020 07:41:37 +0000 (16:41 +0900)
committer송욱/On-Device Lab(SR)/Staff Engineer/삼성전자 <wook16.song@samsung.com>
Wed, 24 Jun 2020 07:16:44 +0000 (16:16 +0900)
This patch adds log verbose mode for debugging.

When it's enabled, npu-engine prints log message to stderr
as well as log file, and also dumps the emulated layer data.

Signed-off-by: Dongju Chae <dongju.chae@samsung.com>
README.md
doc/how_to_debug.md [new file with mode: 0644]
meson.build
meson_options.txt
npu-engine.ini.in
src/core/npu/NPUdrvAPI_emul.cc
src/core/utils/ne-conf.cc
src/core/utils/ne-conf.h
src/core/utils/ne-utils.cc

index bff6c4e..2f97c78 100644 (file)
--- a/README.md
+++ b/README.md
@@ -29,6 +29,7 @@ NPU_SystemService/    Root directory
 - How to setup your own FastModel enviornment (in Ubuntu 16.04 running on your host PC): press [here](https://github.sec.samsung.net/AIP/NPU_bootstrap/blob/master/README.md)
 - How to build the NPU Engine library (FastModel or Ubuntu): press [here](/doc/how_to_build.md)
 - How to use the NPU Engine library in user apps: press [here](/doc/how_to_use.md)
+- How to debug your apps using the NPU Engine library: press [here](/doc/how_to_debug.md)
 - Usage examples using the NPU Engine library: press [here](/doc/usage_examples.md)
 - NPU Engine-enabled bootable images for an FPGA board: press [here](https://github.sec.samsung.net/AIP/meta-trinity/blob/linux-xlnx-fpga-v4.19/README.md)
 
diff --git a/doc/how_to_debug.md b/doc/how_to_debug.md
new file mode 100644 (file)
index 0000000..4791f1e
--- /dev/null
@@ -0,0 +1,51 @@
+# How to debug your apps using NPU Engine library
+
+First of all, this guide describe how to quickly debug your apps in host PC (i.e., Ubuntu 16.04), before testing on the FastModel Simulator or FPGA boards.
+
+We currently provide two methods to configure the npu-engine library
+- .ini file (`/opt/trinity/etc/npu-engine.ini` in Ubuntu 16.04)
+- enviroment variables
+
+## Log messages
+Basically, the log messages (especially errors) are printed to a log file. The default log file path is `/tmp/npu-engine.log`. Of course, you can configure this using the two methods.
+
+After modifying .ini file
+``` bash
+$ sudo sed -i "s|log_dir=.*|log_dir=/home/test/log_dir|" /opt/trinity/etc/npu-engine.ini
+$ ... [run your apps] ...
+```
+
+After setting the env variable
+``` bash
+$ export NE_LOG_DIR=/home/test/log_dir
+$ ... [run your apps] ...
+```
+
+Note that envionment variables have higher priority and we recommend to use them.
+
+## Layer-level data dump
+To check the intermediate input and output data of each layer, you can set `log_verbose` mode
+
+After modifying .ini file
+``` bash
+$ sudo sed -i "s|log_verbose=.*|log_verbose=true|" /opt/trinity/etc/npu-engine.ini
+$ ... [run your apps] ...
+```
+
+After setting the env variable
+``` bash
+$ export NE_LOG_VERBOSE=true
+$ ... [run your apps] ...
+```
+
+Then, you can find out the dumped input and output data for each layer.
+``` bash
+$ ls [log_dir]/layer_dump
+layer_0  layer_1  layer_2  layer_3  layer_4 ...
+$
+$ ls [log_dir]/layer_dump/layer_1
+input_fmap.bin  output_fmap.bin
+$ ...
+```
+
+Note that, in `log_verbose` mode, the log messages are printed to `stderr` as well as a log file.
index 21a6d58..831adef 100644 (file)
@@ -138,6 +138,7 @@ ne_install_conf.set('INCLUDE_INSTALL_DIR', ne_includedir)
 ne_install_conf.set('RESV_MEM_SIZE', get_option('resv_mem_size'))
 ne_install_conf.set('NUM_THREADS', get_option('num_threads'))
 ne_install_conf.set('LOG_DIR', get_option('log_dir'))
+ne_install_conf.set('LOG_VERBOSE', get_option('log_verbose'))
 
 # Install .ini
 configure_file(input: 'npu-engine.ini.in', output: 'npu-engine.ini',
index 77cdeaa..c671f18 100644 (file)
@@ -2,6 +2,7 @@ option('comm_opt', type : 'string', value : 'ip')
 option('resv_mem_size', type : 'string', value : '0')
 option('num_threads', type : 'string', value : '8')
 option('log_dir', type : 'string', value : '/tmp/')
+option('log_verbose', type : 'boolean', value : false)
 option('enable_npu_emul', type : 'boolean', value : false)
 option('enable_data_manip', type : 'boolean', value : false)
 option('enable_buffering', type : 'boolean', value : false)
index 30487d8..57369cc 100644 (file)
@@ -2,3 +2,4 @@
 resv_mem_size=@RESV_MEM_SIZE@
 num_threads=@NUM_THREADS@
 log_dir=@LOG_DIR@
+log_verbose=@LOG_VERBOSE@
index e922546..0219bfa 100644 (file)
@@ -19,6 +19,7 @@
 
 #include <NPUemul.h>
 #include <npubinfmt.h>
+#include <ne-conf.h>
 
 #define MAX_EMUL_DEVICES (100)
 
@@ -404,6 +405,10 @@ TrinityEmulAPI::runInput (input_config_t *input_config) const
       segment_table[i] = static_cast<char *>(elem->getAddr ()) + offset;
     }
 
+    set_triv2_debug (
+        Conf::getInstance().getLogVerbose(),
+        Conf::getInstance().getLogDir());
+
     status = run_triv2_emul (addr_model + model->program_offset_addr, model->program_size,
         segment_table, num_segs);
     delete [] segment_table;
index 165709c..3738735 100644 (file)
@@ -100,6 +100,7 @@ Conf::reset ()
   setResvMemSize (std::to_string (default_resv_mem_size).c_str());
   setNumThreads (std::to_string (default_num_threads).c_str());
   setLogDir (dafault_log_dir);
+  setLogVerbose (default_log_verbose);
 }
 
 /**
@@ -151,6 +152,26 @@ Conf::setLogDir (const char *log_dir)
 }
 
 /**
+ * @brief Set the log verbose mode for debugging
+ * @param[in] log_verbose turning on/off verbose mode
+ */
+void
+Conf::setLogVerbose (const char *log_verbose)
+{
+  if (log_verbose && strlen (log_verbose) > 0) {
+    char first_char = log_verbose[0];
+
+    /* let's check the first character only */
+    if (first_char == 'y' || first_char == 'Y' ||
+        first_char == 't' || first_char == 'T' ||
+        first_char == '1')
+      log_verbose_ = true;
+    else
+      log_verbose_ = false;
+  }
+}
+
+/**
  * @brief Set the configuration of # threads in thread pool
  * @param[in] num_threads config string for a number of threads
  */
@@ -179,10 +200,12 @@ Conf::loadConfIni(dictionary *ini)
   const char *log_dir = iniparser_getstring(ini, "main:log_dir", nullptr);
   const char *resv_mem_size = iniparser_getstring(ini, "main:resv_mem_size", nullptr);
   const char *num_threads = iniparser_getstring (ini, "main:num_threads", nullptr);
+  const char *log_verbose = iniparser_getstring (ini, "main:log_verbose", nullptr);
 
   setLogDir (log_dir);
   setResvMemSize (resv_mem_size);
   setNumThreads (num_threads);
+  setLogVerbose (log_verbose);
 }
 
 /**
@@ -194,8 +217,10 @@ Conf::loadConfEnvvar()
   const char *log_dir = getenv (ENV_LOG_DIR);
   const char *resv_mem_size = getenv (ENV_RESV_MEM_SIZE);
   const char *num_threads = getenv (ENV_NUM_THREADS);
+  const char *log_verbose = getenv (ENV_LOG_VERBOSE);
 
   setLogDir (log_dir);
   setResvMemSize (resv_mem_size);
   setNumThreads (num_threads);
+  setLogVerbose (log_verbose);
 }
index 3d5a4a5..792013e 100644 (file)
 #define MAX_DIR_LEN 256
 
 #define ENV_LOG_DIR             "NE_LOG_DIR"
+#define ENV_LOG_VERBOSE         "NE_LOG_VERBOSE"
 #define ENV_RESV_MEM_SIZE       "NE_RESV_MEM_SIZE"
 #define ENV_NUM_THREADS         "NE_NUM_THREADS"
 
 static const size_t default_resv_mem_size = 0; /* default mode is the CMA allocation */
 static const uint32_t default_num_threads = 8;
 static const char dafault_log_dir[] = "/tmp/";
+static const char default_log_verbose[] = "false";
 
 /** @brief Configuration for NPU-Engine components */
 class Conf {
@@ -41,6 +43,7 @@ class Conf {
     size_t getResvMemSize() { return reserved_mem_size_; }
     uint32_t getNumThreads() { return num_threads_; }
     const char * getLogDir() { return log_dir_; }
+    bool getLogVerbose() { return log_verbose_; }
 
     void reset();
 
@@ -58,6 +61,7 @@ class Conf {
     void setResvMemSize (const char *str);
     void setNumThreads (const char *str);
     void setLogDir (const char *str);
+    void setLogVerbose (const char *str);
 
     size_t reserved_mem_size_;
       /**< NE_RESV_MEM_SIZE, [main] resv_mem_size, the size of memory reserved */
@@ -65,6 +69,8 @@ class Conf {
       /**< NE_NUM_THREADS, [main] num_threads, the number of threads in thread pool */
     char log_dir_[MAX_DIR_LEN];
       /**< NE_LOG_DIR, [main] log_dir, the path where log files are created */
+    bool log_verbose_;
+      /**< NE_LOG_VERBOSE, [main] log_verbose, verbose mode for debugging */
 };
 
 #endif /* __NE_CONF_H__ */
index 2e40620..647a92b 100644 (file)
@@ -21,7 +21,8 @@
 /********************************************************************
  * Logging utilities                                                *
  ********************************************************************/
-#define logfilename "npu-engine.log"
+#define LOG_FILENAME "npu-engine.log"
+#define MAX_LOG_MSG  512
 
 /**
  * @brief Log Level String in 5 characters
@@ -88,12 +89,6 @@ Logger::getInstance ()
 void
 Logger::logwrite (loglevel l, module m, const char *format, ...)
 {
-  std::unique_lock<std::mutex> lock (m_);
-
-  time_t ltime = time (NULL);
-  char* time_str;
-  va_list args;
-
   if (l < LOG_INFO || l >= LOG_END)
     return;
 
@@ -103,15 +98,14 @@ Logger::logwrite (loglevel l, module m, const char *format, ...)
   if (format == nullptr)
     return;
 
-  if (fp_ == NULL) {
-    char filename[FILENAME_MAX];
+  std::unique_lock<std::mutex> lock (m_);
 
-    snprintf(filename, FILENAME_MAX, "%s%s",
-        Conf::getInstance().getLogDir(), logfilename);
-    fp_ = fopen (filename, "a");
-  }
+  char log_msg[MAX_LOG_MSG];
+  size_t log_len;
 
-  assert (fp_ != NULL);
+  time_t ltime = time (nullptr);
+  char* time_str;
+  va_list args;
 
   /**
    * localtime() and asctime() are not MT-safe. There are alternatives,
@@ -119,12 +113,31 @@ Logger::logwrite (loglevel l, module m, const char *format, ...)
    * need critical section here.
    */
   time_str = asctime (localtime (&ltime));
-
   time_str[strcspn (time_str, "\n")] = '\x00';
-  fprintf (fp_, "[%s][%s][%s] ", loglevelstr[l], modulestr[m], time_str);
+
+  log_len = snprintf (log_msg, MAX_LOG_MSG,
+      "[%s][%s][%s] ", loglevelstr[l], modulestr[m], time_str);
+
   va_start (args, format);
-  vfprintf (fp_, format, args);
+  log_len += vsnprintf (log_msg + log_len, MAX_LOG_MSG - log_len,
+      format, args);
   va_end (args);
 
+  if (Conf::getInstance().getLogVerbose()) {
+    fprintf (stderr, "%s\n", log_msg);
+    fflush (stderr);
+  }
+
+  if (fp_ == nullptr) {
+    char filename[FILENAME_MAX];
+
+    snprintf(filename, FILENAME_MAX, "%s/%s",
+        Conf::getInstance().getLogDir(), LOG_FILENAME);
+    fp_ = fopen (filename, "a");
+    if (fp_ == nullptr)
+      return;
+  }
+
+  fprintf (fp_, "%s\n", log_msg);
   fflush (fp_);
 }