[Logging][Hexagon] Improve logging on Hexagon (apache#13072)

* [Logging][Hexagon] Improve logging on Hexagon

Currently Hexagon logging is done with a custom LogMessageImpl in
hexagon_common.cc. This ends up calling HexagonLog and HEXAGON_PRINT
which uses the HAP FARF API. Unfortunately, the TVM log level is lost
along the way, with logs being produced at FARF’s ALWAYS level. This
becomes especially noisy with RPC debug logging, which generates enough
noise to cause some log data to be dropped. It also introduces a lot of
useless noise, as the FARF API produces its own line number information,
which only points to where hexagon_common.cc calls HEXAGON_PRINT. Using
the HAP_debug_v2 API lets us pass the log level and file line
information directly, and enables runtime selection of logging levels.

This commit explicity passes the log level to LogMessage/LogMessageImpl
and updates Hexagon's custom LogMessageImpl to use the HAP_debug_v2 API.

* Adjust Hexagon rpc_server logging to use the DEBUG level

* Update hexagon_api launcher script to omit DEBUG-level logs

* Update WASM LogMessageImpl to accept explicit level

* Update Android LogMessageImpl to accept and forward explicit log level

* Move LogMessage::level_strings_ out of some ifdefs

* Update iOS LogMessageImpl to accept explicit log level

* Attempt to fix Windows build

* Add comments about runtime hexagon log level encodings

* Remove unneeded string processing in LogMessage

* Remove TODO

* Update HexagonLauncherAndroid to accept runtime log filtering configuration

apps/android_camera/app/src/main/jni/tvm_runtime.h

@@ -81,12 +81,12 @@ namespace detail {
 // Override logging mechanism
 [[noreturn]] void LogFatalImpl(const std::string& file, int lineno, const std::string& message) {
   std::string m = file + ":" + std::to_string(lineno) + ": " + message;
-  __android_log_write(ANDROID_LOG_DEBUG, "TVM_RUNTIME", m.c_str());
+  __android_log_write(ANDROID_LOG_FATAL, "TVM_RUNTIME", m.c_str());
   throw InternalError(file, lineno, message);
 }
-void LogMessageImpl(const std::string& file, int lineno, const std::string& message) {
+void LogMessageImpl(const std::string& file, int lineno, int level, const std::string& message) {
   std::string m = file + ":" + std::to_string(lineno) + ": " + message;
-  __android_log_write(ANDROID_LOG_DEBUG, "TVM_RUNTIME", m.c_str());
+  __android_log_write(ANDROID_LOG_DEBUG + level, "TVM_RUNTIME", m.c_str());
 }
 
 }  // namespace detail

apps/android_rpc/app/src/main/jni/tvm_runtime.h

@@ -95,12 +95,12 @@ namespace detail {
 // Override logging mechanism
 [[noreturn]] void LogFatalImpl(const std::string& file, int lineno, const std::string& message) {
   std::string m = file + ":" + std::to_string(lineno) + ": " + message;
-  __android_log_write(ANDROID_LOG_DEBUG, "TVM_RUNTIME", m.c_str());
+  __android_log_write(ANDROID_LOG_FATAL, "TVM_RUNTIME", m.c_str());
   throw InternalError(file, lineno, message);
 }
-void LogMessageImpl(const std::string& file, int lineno, const std::string& message) {
+void LogMessageImpl(const std::string& file, int lineno, int level, const std::string& message) {
   std::string m = file + ":" + std::to_string(lineno) + ": " + message;
-  __android_log_write(ANDROID_LOG_DEBUG, "TVM_RUNTIME", m.c_str());
+  __android_log_write(ANDROID_LOG_DEBUG + level, "TVM_RUNTIME", m.c_str());
 }
 
 }  // namespace detail

apps/ios_rpc/tvmrpc/TVMRuntime.mm

@@ -45,7 +45,7 @@
   throw tvm::runtime::InternalError(file, lineno, message);
 }
 
-void LogMessageImpl(const std::string& file, int lineno, const std::string& message) {
+void LogMessageImpl(const std::string& file, int lineno, int level, const std::string& message) {
   NSLog(@"%s:%d: %s", file.c_str(), lineno, message.c_str());
 }
 

include/tvm/runtime/logging.h

@@ -294,7 +294,8 @@ namespace detail {
  *
  * \sa TVM_LOG_CUSTOMIZE
  */
-TVM_DLL void LogMessageImpl(const std::string& file, int lineno, const std::string& message);
+TVM_DLL void LogMessageImpl(const std::string& file, int lineno, int level,
+                            const std::string& message);
 
 /*!
  * \brief Class to accumulate an error message and throw it. Do not use
@@ -325,13 +326,15 @@ class LogFatal {
  */
 class LogMessage {
  public:
-  LogMessage(const std::string& file, int lineno) : file_(file), lineno_(lineno) {}
-  ~LogMessage() { LogMessageImpl(file_, lineno_, stream_.str()); }
+  LogMessage(const std::string& file, int lineno, int level)
+      : file_(file), lineno_(lineno), level_(level) {}
+  ~LogMessage() { LogMessageImpl(file_, lineno_, level_, stream_.str()); }
   std::ostringstream& stream() { return stream_; }
 
  private:
   std::string file_;
   int lineno_;
+  int level_;
   std::ostringstream stream_;
 };
 
@@ -378,17 +381,19 @@ class LogFatal {
  */
 class LogMessage {
  public:
-  LogMessage(const std::string& file, int lineno) {
+  LogMessage(const std::string& file, int lineno, int level) {
     std::time_t t = std::time(nullptr);
     stream_ << "[" << std::put_time(std::localtime(&t), "%H:%M:%S") << "] " << file << ":" << lineno
-            << ": ";
+            << level_strings_[level];
   }
   TVM_NO_INLINE ~LogMessage() { std::cerr << stream_.str() << std::endl; }
   std::ostringstream& stream() { return stream_; }
 
  private:
   std::ostringstream stream_;
+  TVM_DLL static const char* level_strings_[];
 };
+
 #endif
 
 // Below is from dmlc-core
@@ -568,11 +573,20 @@ TVM_CHECK_FUNC(_NE, !=)
 
 }  // namespace detail
 
+#define TVM_LOG_LEVEL_DEBUG 0
+#define TVM_LOG_LEVEL_INFO 1
+#define TVM_LOG_LEVEL_WARNING 2
+#define TVM_LOG_LEVEL_ERROR 3
+#define TVM_LOG_LEVEL_FATAL 4
 #define LOG(level) LOG_##level
+#define LOG_DEBUG \
+  ::tvm::runtime::detail::LogMessage(__FILE__, __LINE__, TVM_LOG_LEVEL_DEBUG).stream()
 #define LOG_FATAL ::tvm::runtime::detail::LogFatal(__FILE__, __LINE__).stream()
-#define LOG_INFO ::tvm::runtime::detail::LogMessage(__FILE__, __LINE__).stream()
-#define LOG_ERROR (::tvm::runtime::detail::LogMessage(__FILE__, __LINE__).stream() << "Error: ")
-#define LOG_WARNING (::tvm::runtime::detail::LogMessage(__FILE__, __LINE__).stream() << "Warning: ")
+#define LOG_INFO ::tvm::runtime::detail::LogMessage(__FILE__, __LINE__, TVM_LOG_LEVEL_INFO).stream()
+#define LOG_ERROR \
+  ::tvm::runtime::detail::LogMessage(__FILE__, __LINE__, TVM_LOG_LEVEL_ERROR).stream()
+#define LOG_WARNING \
+  ::tvm::runtime::detail::LogMessage(__FILE__, __LINE__, TVM_LOG_LEVEL_WARNING).stream()
 
 #define TVM_CHECK_BINARY_OP(name, op, x, y)                                \
   if (auto __tvm__log__err = ::tvm::runtime::detail::LogCheck##name(x, y)) \

python/tvm/contrib/hexagon/build.py

@@ -19,6 +19,7 @@
 
 import abc
 import datetime
+import logging
 import multiprocessing as mp
 import os
 import pathlib
@@ -269,6 +270,7 @@ def __init__(
         hexagon_debug: bool = False,
         clear_logcat: bool = False,
         sysmon_profile: bool = False,
+        farf_config: str = "0x1e",
     ):
         """Configure a new HexagonLauncherAndroid
 
@@ -288,6 +290,10 @@ def __init__(
             Should the server clear logcat before running.
         sysmon_profile: bool, optional
             Should the server run sysmon profiler in the background.
+        farf_config: str, optional
+            Configuration string for runtime log level filtering.
+            Use farf_config_from_python_log_level to generate a bitmask
+            string from a Python logging level (e.g., logging.INFO)
         """
         if not rpc_info.get("workspace_base"):
             rpc_info["workspace_base"] = self.ANDROID_HEXAGON_TEST_BASE_DIR
@@ -301,6 +307,7 @@ def __init__(
         self._clear_logcat = clear_logcat
         self._sysmon_profile = sysmon_profile
         self._sysmon_process = None
+        self._farf_config = farf_config
         rpc_info["device_key"] = HEXAGON_REMOTE_DEVICE_KEY + "." + self._serial_number
 
         super(HexagonLauncherAndroid, self).__init__(rpc_info, workspace, self._serial_number)
@@ -342,6 +349,8 @@ def _copy_binaries(self):
                             line = line.replace(
                                 "<RPC_SERVER_PORT>", str(self._rpc_info["rpc_server_port"])
                             )
+                        if "<FARF_CONFIG>" in line:
+                            line = line.replace("<FARF_CONFIG>", str(self._farf_config))
                         dest_f.write(line)
 
                 # Make shell script executable
@@ -710,6 +719,44 @@ def _is_port_in_use(port: int) -> bool:
         return s.connect_ex(("localhost", port)) == 0
 
 
+def farf_config_from_python_log_level(level) -> str:
+    """Generates a FARF configuration string enabling logging at the specified level
+
+    Parameters
+    ----------
+    level : str or int
+        Minimum level to log at. Must be a known Python logging level or string
+        (e.g., logging.INFO or "INFO")
+    """
+
+    # Runtime log levels can be selectively enabled by computing a bitmask
+    # corresponding to the levels you want to enable. These get forwarded to
+    # logcat by the DSP RPC daemon. The bits for each level are:
+
+    # 0x01 - Hexagon LOW / TVM DEBUG / Python DEBUG
+    # 0x02 - Hexagon MEDIUM / TVM INFO / Python INFO
+    # 0x04 - Hexagon HIGH / TVM WARN / Python WARNING
+    # 0x08 - Hexagon ERROR / TVM ERROR / Python ERROR
+    # 0x10 - Hexagon FATAL / TVM FATAL / Python CRITICAL
+
+    # Runtime logging can also be filtered on filenames by appending a
+    # comma-separated list of filenames. For more information, see
+    # the Hexagon SDK documentation.
+
+    if level in (logging.DEBUG, "DEBUG"):
+        return "0x1F"
+    if level in (logging.INFO, "INFO"):
+        return "0x1E"
+    if level in (logging.WARNING, "WARNING"):
+        return "0x1C"
+    if level in (logging.ERROR, "ERROR"):
+        return "0x18"
+    if level in (logging.CRITICAL, "CRITICAL"):
+        return "0x10"
+
+    raise ValueError("Argument must be a known Python logging level or string")
+
+
 # pylint: disable=invalid-name
 def HexagonLauncher(
     serial_number: str,
@@ -718,10 +765,11 @@ def HexagonLauncher(
     hexagon_debug: bool = False,
     clear_logcat: bool = False,
     sysmon_profile: bool = False,
+    farf_config: str = farf_config_from_python_log_level(logging.INFO),
 ):
     """Creates a HexagonLauncher"""
     if serial_number == HEXAGON_SIMULATOR_NAME:
         return HexagonLauncherSimulator(rpc_info, workspace)
     return HexagonLauncherAndroid(
-        serial_number, rpc_info, workspace, hexagon_debug, clear_logcat, sysmon_profile
+        serial_number, rpc_info, workspace, hexagon_debug, clear_logcat, sysmon_profile, farf_config
     )

src/meta_schedule/utils.h

@@ -93,13 +93,17 @@ class PyLogMessage {
       logger_(static_cast<int>(logging_level_), std::string(filename_), lineno_, stream_.str());
     } else {
       if (logging_level_ == Level::INFO) {
-        runtime::detail::LogMessage(filename_, lineno_).stream() << stream_.str();
+        runtime::detail::LogMessage(filename_, lineno_, TVM_LOG_LEVEL_INFO).stream()
+            << stream_.str();
       } else if (logging_level_ == Level::WARNING) {
-        runtime::detail::LogMessage(filename_, lineno_).stream() << "Warning: " << stream_.str();
+        runtime::detail::LogMessage(filename_, lineno_, TVM_LOG_LEVEL_WARNING).stream()
+            << stream_.str();
       } else if (logging_level_ == Level::ERROR) {
-        runtime::detail::LogMessage(filename_, lineno_).stream() << "Error: " << stream_.str();
+        runtime::detail::LogMessage(filename_, lineno_, TVM_LOG_LEVEL_ERROR).stream()
+            << stream_.str();
       } else if (logging_level_ == Level::DEBUG) {
-        runtime::detail::LogMessage(filename_, lineno_).stream() << "Debug: " << stream_.str();
+        runtime::detail::LogMessage(filename_, lineno_, TVM_LOG_LEVEL_DEBUG).stream()
+            << stream_.str();
       } else {
         runtime::detail::LogFatal(filename_, lineno_).stream() << stream_.str();
       }
@@ -151,7 +155,8 @@ inline void clear_logging(const char* file, int lineno, PackedFunc logging_func)
     logging_func(static_cast<int>(PyLogMessage::Level::CLEAR), file, lineno, "");
   } else {
     // this would clear all logging output in the console
-    runtime::detail::LogMessage(file, lineno).stream() << "\033c\033[3J\033[2J\033[0m\033[H";
+    runtime::detail::LogMessage(file, lineno, TVM_LOG_LEVEL_INFO).stream()
+        << "\033c\033[3J\033[2J\033[0m\033[H";
   }
 }
 

src/runtime/hexagon/hexagon_common.cc

@@ -32,6 +32,7 @@
 #include <vector>
 
 #include "../library_module.h"
+#include "HAP_debug.h"
 #include "HAP_perf.h"
 #include "hexagon_buffer.h"
 
@@ -69,22 +70,22 @@ std::vector<std::string> SplitString(const std::string& str, char delim) {
   }
   return lines;
 }
-void HexagonLog(const std::string& file, int lineno, const std::string& message) {
-  HEXAGON_PRINT(ALWAYS, "INFO: %s:%d:", file.c_str(), lineno);
+void HexagonLog(const std::string& file, int lineno, int level, const std::string& message) {
   std::vector<std::string> err_lines = SplitString(message, '\n');
   for (auto& line : err_lines) {
-    HEXAGON_PRINT(ALWAYS, "INFO: %s", line.c_str());
+    // TVM log levels roughly map to HAP log levels
+    HAP_debug_runtime(level, file.c_str(), lineno, line.c_str());
   }
 }
 }  // namespace
 
 namespace detail {
 [[noreturn]] void LogFatalImpl(const std::string& file, int lineno, const std::string& message) {
-  HexagonLog(file, lineno, message);
+  HexagonLog(file, lineno, TVM_LOG_LEVEL_FATAL, message);
   throw InternalError(file, lineno, message);
 }
-void LogMessageImpl(const std::string& file, int lineno, const std::string& message) {
-  HexagonLog(file, lineno, message);
+void LogMessageImpl(const std::string& file, int lineno, int level, const std::string& message) {
+  HexagonLog(file, lineno, level, message);
 }
 }  // namespace detail
 

src/runtime/hexagon/rpc/android_bash.sh.template

@@ -20,7 +20,8 @@ export LD_LIBRARY_PATH=.
 
 # Enable FARF-based logging for Hexagon code invoked by 'tvm_rpc_android_server'.
 export ADSP_LIBRARY_PATH=`pwd`
-echo 0x1f > tvm_rpc_android.farf
+
+echo <FARF_CONFIG> > tvm_rpc_android.farf
 
 ./tvm_rpc_android server --port=<RPC_SERVER_PORT> --tracker=<RPC_TRACKER_HOST>:<RPC_TRACKER_PORT> --key=<HEXAGON_REMOTE_DEVICE_KEY> >${PWD}/tvm_rpc_android.log 2>&1 &
 

src/runtime/hexagon/rpc/hexagon/rpc_server.cc

@@ -64,7 +64,7 @@ class HexagonIOHandler {
   void MessageStart(size_t message_size_bytes) {}
 
   ssize_t PosixWrite(const uint8_t* buf, size_t write_len_bytes) {
-    LOG(INFO) << "HexagonIOHandler PosixWrite called, write_len_bytes(" << write_len_bytes << ")";
+    LOG(DEBUG) << "HexagonIOHandler PosixWrite called, write_len_bytes(" << write_len_bytes << ")";
     int32_t written_size = write_buffer_.sputn(reinterpret_cast<const char*>(buf), write_len_bytes);
     if (written_size != write_len_bytes) {
       LOG(ERROR) << "written_size(" << written_size << ") != write_len_bytes(" << write_len_bytes
@@ -74,11 +74,11 @@ class HexagonIOHandler {
     return (ssize_t)written_size;
   }
 
-  void MessageDone() { LOG(INFO) << "Message Done."; }
+  void MessageDone() { LOG(DEBUG) << "Message Done."; }
 
   ssize_t PosixRead(uint8_t* buf, size_t read_len_bytes) {
-    LOG(INFO) << "HexagonIOHandler PosixRead called, read_len_bytes(" << read_len_bytes
-              << "), read_buffer_index_(" << read_buffer_index_ << ")";
+    LOG(DEBUG) << "HexagonIOHandler PosixRead called, read_len_bytes(" << read_len_bytes
+               << "), read_buffer_index_(" << read_buffer_index_ << ")";
 
     uint32_t bytes_to_read = 0;
     if (read_buffer_index_ < read_len_bytes) {
@@ -101,9 +101,9 @@ class HexagonIOHandler {
    * \return The status
    */
   AEEResult SetReadBuffer(const uint8_t* data, size_t data_size_bytes) {
-    LOG(INFO) << "HexagonIOHandler SetReadBuffer: data_size_bytes(" << data_size_bytes
-              << "), read_buffer_index_(" << read_buffer_index_ << "), read_buffer_size_bytes_("
-              << read_buffer_size_bytes_ << ")";
+    LOG(DEBUG) << "HexagonIOHandler SetReadBuffer: data_size_bytes(" << data_size_bytes
+               << "), read_buffer_index_(" << read_buffer_index_ << "), read_buffer_size_bytes_("
+               << read_buffer_size_bytes_ << ")";
     if (data_size_bytes > read_buffer_size_bytes_) {
       LOG(ERROR) << "ERROR: data_size_bytes(" << data_size_bytes << ") > read_buffer_size_bytes_("
                  << read_buffer_size_bytes_ << ")";
@@ -123,8 +123,8 @@ class HexagonIOHandler {
    * \return The size of data that is read in bytes.
    */
   int64_t ReadFromWriteBuffer(uint8_t* buf, size_t read_size_bytes) {
-    LOG(INFO) << "HexagonIOHandler ReadFromWriteBuffer called, read_size_bytes: "
-              << read_size_bytes;
+    LOG(DEBUG) << "HexagonIOHandler ReadFromWriteBuffer called, read_size_bytes: "
+               << read_size_bytes;
     int64_t size = (int64_t)write_buffer_.sgetn(reinterpret_cast<char*>(buf), read_size_bytes);
     write_buffer_available_length_ -= size;
 
@@ -135,7 +135,7 @@ class HexagonIOHandler {
     return size;
   }
 
-  void Close() { LOG(INFO) << "HexagonIOHandler Close called"; }
+  void Close() { LOG(DEBUG) << "HexagonIOHandler Close called"; }
 
   void Exit(int code) { exit(code); }
 
@@ -264,7 +264,7 @@ int __QAIC_HEADER(hexagon_rpc_open)(const char* uri, remote_handle64* handle) {
 }
 
 int __QAIC_HEADER(hexagon_rpc_close)(remote_handle64 handle) {
-  LOG(INFO) << __func__;
+  LOG(DEBUG) << __func__;
   if (handle) {
     free(reinterpret_cast<void*>(static_cast<uintptr_t>(handle)));
   }

src/runtime/logging.cc

@@ -212,6 +212,13 @@ namespace tvm {
 namespace runtime {
 namespace detail {
 
+const char* ::tvm::runtime::detail::LogMessage::level_strings_[] = {
+    ": Debug: ",    // TVM_LOG_LEVEL_DEBUG
+    ": ",           // TVM_LOG_LEVEL_INFO
+    ": Warning: ",  // TVM_LOG_LEVEL_WARNING
+    ": Error: ",    // TVM_LOG_LEVEL_ERROR
+};
+
 namespace {
 constexpr const char* kSrcPrefix = "/src/";
 // Note: Better would be std::char_traits<const char>::length(kSrcPrefix) but it is not

web/emcc/wasm_runtime.cc

@@ -73,8 +73,14 @@ namespace detail {
   abort();
 }
 
-void LogMessageImpl(const std::string& file, int lineno, const std::string& message) {
-  std::cout << "[INFO] " << file << ":" << lineno << ": " << message << std::endl;
+void LogMessageImpl(const std::string& file, int lineno, int level, const std::string& message) {
+  static const char* level_strings_[] = {
+      "[DEBUG] ",
+      "[INFO] ",
+      "[WARNING] ",
+      "[ERROR] ",
+  };
+  std::cout << level_strings_[level] << file << ":" << lineno << ": " << message << std::endl;
 }
 
 }  // namespace detail