[Logging][Hexagon] Improve logging on Hexagon

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

@@ -92,13 +92,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();
       }
@@ -150,7 +154,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