From 2cf3f09aa36f783f0d9f95630ec0461718dc2101 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Thu, 13 Oct 2022 15:51:18 -0700 Subject: [PATCH 01/12] [Logging][Hexagon] Improve logging on Hexagon MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- include/tvm/runtime/logging.h | 30 ++++++++++++++++++++------- src/meta_schedule/utils.h | 15 +++++++++----- src/runtime/hexagon/hexagon_common.cc | 13 ++++++------ src/runtime/logging.cc | 7 +++++++ 4 files changed, 46 insertions(+), 19 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 7dbc6d810dc0..5930da5c56b5 100644 --- a/include/tvm/runtime/logging.h +++ b/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_; + 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)) \ diff --git a/src/meta_schedule/utils.h b/src/meta_schedule/utils.h index 824cfcd6aa5c..6766df3d692e 100644 --- a/src/meta_schedule/utils.h +++ b/src/meta_schedule/utils.h @@ -92,13 +92,17 @@ class PyLogMessage { logger_(static_cast(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(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"; } } diff --git a/src/runtime/hexagon/hexagon_common.cc b/src/runtime/hexagon/hexagon_common.cc index ec65dffebe51..79acbf8b99e2 100644 --- a/src/runtime/hexagon/hexagon_common.cc +++ b/src/runtime/hexagon/hexagon_common.cc @@ -32,6 +32,7 @@ #include #include "../library_module.h" +#include "HAP_debug.h" #include "HAP_perf.h" #include "hexagon_buffer.h" @@ -69,22 +70,22 @@ std::vector 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 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 diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index d62051f7cee0..6c9cb26ea328 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -212,6 +212,13 @@ namespace tvm { namespace runtime { namespace detail { +const char* 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::length(kSrcPrefix) but it is not From 60859251558f3cb6f96545efedb65a54f4b64703 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Thu, 13 Oct 2022 16:27:58 -0700 Subject: [PATCH 02/12] Adjust Hexagon rpc_server logging to use the DEBUG level --- src/runtime/hexagon/rpc/hexagon/rpc_server.cc | 22 +++++++++---------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/src/runtime/hexagon/rpc/hexagon/rpc_server.cc b/src/runtime/hexagon/rpc/hexagon/rpc_server.cc index f39944615bfd..8daeeff66284 100644 --- a/src/runtime/hexagon/rpc/hexagon/rpc_server.cc +++ b/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(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(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(static_cast(handle))); } From ca2497c155a6f015f63c4ad6985f106c4e9af04b Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Thu, 13 Oct 2022 16:28:57 -0700 Subject: [PATCH 03/12] Update hexagon_api launcher script to omit DEBUG-level logs --- src/runtime/hexagon/rpc/android_bash.sh.template | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/runtime/hexagon/rpc/android_bash.sh.template b/src/runtime/hexagon/rpc/android_bash.sh.template index d9f7613b0fc0..39d09b217011 100644 --- a/src/runtime/hexagon/rpc/android_bash.sh.template +++ b/src/runtime/hexagon/rpc/android_bash.sh.template @@ -20,7 +20,7 @@ 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 0x1e > tvm_rpc_android.farf ./tvm_rpc_android server --port= --tracker=: --key= >${PWD}/tvm_rpc_android.log 2>&1 & From e9d5b3b36dd3c2724dd7710eabadc67680e047c0 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Thu, 13 Oct 2022 19:43:57 -0700 Subject: [PATCH 04/12] Update WASM LogMessageImpl to accept explicit level --- web/emcc/wasm_runtime.cc | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/web/emcc/wasm_runtime.cc b/web/emcc/wasm_runtime.cc index addc3a3e0c11..2b0ee49d7edd 100644 --- a/web/emcc/wasm_runtime.cc +++ b/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 From c80d9c904e0c3d38296a758cdffa90e9bf33c3d1 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Fri, 14 Oct 2022 13:54:16 -0700 Subject: [PATCH 05/12] Update Android LogMessageImpl to accept and forward explicit log level --- apps/android_camera/app/src/main/jni/tvm_runtime.h | 6 +++--- apps/android_rpc/app/src/main/jni/tvm_runtime.h | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/apps/android_camera/app/src/main/jni/tvm_runtime.h b/apps/android_camera/app/src/main/jni/tvm_runtime.h index b20227b34db4..658534780130 100644 --- a/apps/android_camera/app/src/main/jni/tvm_runtime.h +++ b/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 diff --git a/apps/android_rpc/app/src/main/jni/tvm_runtime.h b/apps/android_rpc/app/src/main/jni/tvm_runtime.h index 95b793a985d1..543c9c85334e 100644 --- a/apps/android_rpc/app/src/main/jni/tvm_runtime.h +++ b/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 From 6e4fed61f8d28267094f38b354edad65dc1327ee Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Sat, 15 Oct 2022 21:31:44 -0700 Subject: [PATCH 06/12] Move LogMessage::level_strings_ out of some ifdefs --- src/runtime/logging.cc | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 6c9cb26ea328..6931ef85a2a6 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -21,6 +21,15 @@ #include #include +#if (TVM_LOG_CUSTOMIZE == 0) +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 +}; +#endif + #if TVM_LOG_STACK_TRACE #if TVM_USE_LIBBACKTRACE @@ -212,13 +221,6 @@ namespace tvm { namespace runtime { namespace detail { -const char* 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::length(kSrcPrefix) but it is not From 05b7b0adb0b5bbc576428f1861286a7887fa0d4f Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Sat, 15 Oct 2022 21:32:32 -0700 Subject: [PATCH 07/12] Update iOS LogMessageImpl to accept explicit log level --- apps/ios_rpc/tvmrpc/TVMRuntime.mm | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/apps/ios_rpc/tvmrpc/TVMRuntime.mm b/apps/ios_rpc/tvmrpc/TVMRuntime.mm index 3225b850befe..f7d72a092124 100644 --- a/apps/ios_rpc/tvmrpc/TVMRuntime.mm +++ b/apps/ios_rpc/tvmrpc/TVMRuntime.mm @@ -45,7 +45,8 @@ 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) { + // TODO: Output logging level NSLog(@"%s:%d: %s", file.c_str(), lineno, message.c_str()); } From 698d1d9dba4782a586ba5751fbad05887e95c168 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Sun, 16 Oct 2022 12:52:13 -0700 Subject: [PATCH 08/12] Attempt to fix Windows build --- include/tvm/runtime/logging.h | 2 +- src/runtime/logging.cc | 16 +++++++--------- 2 files changed, 8 insertions(+), 10 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 5930da5c56b5..9f59e3a7f628 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -391,7 +391,7 @@ class LogMessage { private: std::ostringstream stream_; - static const char* level_strings_[]; + TVM_DLL static const char* level_strings_[]; }; #endif diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 6931ef85a2a6..6be90464de8b 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -21,15 +21,6 @@ #include #include -#if (TVM_LOG_CUSTOMIZE == 0) -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 -}; -#endif - #if TVM_LOG_STACK_TRACE #if TVM_USE_LIBBACKTRACE @@ -221,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::length(kSrcPrefix) but it is not From c451ae19f9a580210ad89973ca25edb2cd1f0355 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Fri, 21 Oct 2022 12:36:22 -0700 Subject: [PATCH 09/12] Add comments about runtime hexagon log level encodings --- src/runtime/hexagon/rpc/android_bash.sh.template | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/src/runtime/hexagon/rpc/android_bash.sh.template b/src/runtime/hexagon/rpc/android_bash.sh.template index 39d09b217011..47bd86701708 100644 --- a/src/runtime/hexagon/rpc/android_bash.sh.template +++ b/src/runtime/hexagon/rpc/android_bash.sh.template @@ -20,6 +20,17 @@ export LD_LIBRARY_PATH=. # Enable FARF-based logging for Hexagon code invoked by 'tvm_rpc_android_server'. export ADSP_LIBRARY_PATH=`pwd` + +# 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 +# 0x02 - Hexagon MEDIUM / TVM INFO +# 0x04 - Hexagon HIGH / TVM WARN +# 0x08 - Hexagon ERROR / TVM ERROR +# 0x10 - Hexagon FATAL / TVM FATAL + echo 0x1e > tvm_rpc_android.farf ./tvm_rpc_android server --port= --tracker=: --key= >${PWD}/tvm_rpc_android.log 2>&1 & From eed8dfac210723e7149fcfa39c9acc3505cdb520 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Fri, 21 Oct 2022 12:49:44 -0700 Subject: [PATCH 10/12] Remove unneeded string processing in LogMessage --- include/tvm/runtime/logging.h | 2 +- src/runtime/logging.cc | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 9f59e3a7f628..2128fc485ba4 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -384,7 +384,7 @@ class LogMessage { 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]; + << level_strings_[level]; } TVM_NO_INLINE ~LogMessage() { std::cerr << stream_.str() << std::endl; } std::ostringstream& stream() { return stream_; } diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 6be90464de8b..d0ce77c931db 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -213,10 +213,10 @@ 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 + ": Debug: ", // TVM_LOG_LEVEL_DEBUG + ": ", // TVM_LOG_LEVEL_INFO + ": Warning: ", // TVM_LOG_LEVEL_WARNING + ": Error: ", // TVM_LOG_LEVEL_ERROR }; namespace { From c318b1576b5e9a4c7c08940a8d6567b2170dd888 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Thu, 27 Oct 2022 16:27:22 -0700 Subject: [PATCH 11/12] Remove TODO --- apps/ios_rpc/tvmrpc/TVMRuntime.mm | 1 - 1 file changed, 1 deletion(-) diff --git a/apps/ios_rpc/tvmrpc/TVMRuntime.mm b/apps/ios_rpc/tvmrpc/TVMRuntime.mm index f7d72a092124..baf5c8867a92 100644 --- a/apps/ios_rpc/tvmrpc/TVMRuntime.mm +++ b/apps/ios_rpc/tvmrpc/TVMRuntime.mm @@ -46,7 +46,6 @@ } void LogMessageImpl(const std::string& file, int lineno, int level, const std::string& message) { - // TODO: Output logging level NSLog(@"%s:%d: %s", file.c_str(), lineno, message.c_str()); } From fe1c5ba5073fbfd0cfdcdcc16dc89184157b4ba5 Mon Sep 17 00:00:00 2001 From: Karl Koscher Date: Thu, 27 Oct 2022 18:14:57 -0700 Subject: [PATCH 12/12] Update HexagonLauncherAndroid to accept runtime log filtering configuration --- python/tvm/contrib/hexagon/build.py | 50 ++++++++++++++++++- .../hexagon/rpc/android_bash.sh.template | 12 +---- 2 files changed, 50 insertions(+), 12 deletions(-) diff --git a/python/tvm/contrib/hexagon/build.py b/python/tvm/contrib/hexagon/build.py index bc3b065dd941..e67009829771 100644 --- a/python/tvm/contrib/hexagon/build.py +++ b/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( "", str(self._rpc_info["rpc_server_port"]) ) + if "" in line: + line = line.replace("", 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 ) diff --git a/src/runtime/hexagon/rpc/android_bash.sh.template b/src/runtime/hexagon/rpc/android_bash.sh.template index 47bd86701708..c45b03818fd3 100644 --- a/src/runtime/hexagon/rpc/android_bash.sh.template +++ b/src/runtime/hexagon/rpc/android_bash.sh.template @@ -21,17 +21,7 @@ export LD_LIBRARY_PATH=. # Enable FARF-based logging for Hexagon code invoked by 'tvm_rpc_android_server'. export ADSP_LIBRARY_PATH=`pwd` -# 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 -# 0x02 - Hexagon MEDIUM / TVM INFO -# 0x04 - Hexagon HIGH / TVM WARN -# 0x08 - Hexagon ERROR / TVM ERROR -# 0x10 - Hexagon FATAL / TVM FATAL - -echo 0x1e > tvm_rpc_android.farf +echo > tvm_rpc_android.farf ./tvm_rpc_android server --port= --tracker=: --key= >${PWD}/tvm_rpc_android.log 2>&1 &