From 3fbce70a8ad7e032de8c402fb27e0396435c8eca Mon Sep 17 00:00:00 2001 From: Mark Shields <87091372+mbs-octoml@users.noreply.github.com> Date: Tue, 21 Sep 2021 17:07:54 -0700 Subject: [PATCH] [Relay] VLOG for finer grained control of hyper-detailed logging (#9012) * [Relay] VLOG for finer grained control of hyper-detailed logging I've been making very heavy use of DLOG and PrettyPrint to trace, understand and debug Relay transforms. I've found myself deleting log statements to reduce the output verbosity, only to have to re-add them a few days later. Better would be to support leaving all those statements in place but have finer control over when they are enabled. This PR introduces a 'VLOG(level)' macro to that end. The log is ignored unless TVM_LOG_DEBUG is enabled (both as #define and an environment var), and the the current verbosity level is >= level. The current verbosity level can be set globally and/or overridden per source file (see 'VerboseLoggingEnabled'). (Those familiar with the origin of the LOG and DLOG family will also recognize VLOG.) I also introduce a 'VLOG_CONTEXT' macro which pushes a string onto an internal per-thread stack. Each VLOG message includes that stack as its prefix, which is a very handy way to keep track of the (often recursive) program context in which each VLOG is executed. I've rejigged some existing DLOGs to VLOGs to illustrate, but left most of them alone for now. See the draft https://github.com/apache/tvm/pull/8788 for use in the wild. I noticed the DCHECK macros *disabled* instead enabled with TVM_LOG_DEBUG defined, so fixed that. I've also made changes to the Relay text printer to dump attributes in a human readable format rather than the indirect but machine readable 'meta' representation. This is gated by the show_meta_data_ flag, and I think this use is consistent with it's original purpose. * [checkpoint] lints * [checkpoint] missing \n lint Gotta get my docker setup going * [checkpoint] woops, we don't support gmock.h * [checkpoint] Address Hua Jiang's comments. * [checkpoint] strlen not avail on all toolchains? * [checkpoint] Rework TVM_LOG_DEBUG spec and parser * [checkpoint] woops, forgot the static modifier on map * [checkpoint] * -> DEFAULT for wildcard. Andrew pointed out *=9 suggests foo/*.cc=9 would work but it is not supported. * [checkpoint] constexpr length * [checkpoint] length is not constexpr on all targets, reverting * [checkpoint] minimize VLOG overhead when in legacy DLOG-only mode --- CMakeLists.txt | 2 +- include/tvm/runtime/logging.h | 185 ++++++++++++++++++++++++++---- src/ir/transform.cc | 12 +- src/parser/parser.cc | 51 ++++---- src/parser/tokenizer.h | 4 +- src/printer/relay_text_printer.cc | 19 ++- src/printer/text_printer.cc | 2 +- src/printer/text_printer.h | 1 + src/relay/ir/dataflow_matcher.cc | 4 + src/relay/ir/transform.cc | 7 +- src/runtime/logging.cc | 95 ++++++++++++++- tests/cpp/runtime/logging_test.cc | 70 +++++++++++ 12 files changed, 393 insertions(+), 59 deletions(-) create mode 100644 tests/cpp/runtime/logging_test.cc diff --git a/CMakeLists.txt b/CMakeLists.txt index 5a481d703ebe..87fa2e059abb 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -586,7 +586,7 @@ endif() # Create the `cpptest` target if we can find GTest. If not, we create dummy # targets that give the user an informative error message. if(GTEST_INCLUDE_DIR AND GTEST_LIB) - file(GLOB TEST_SRCS tests/cpp/*.cc) + file(GLOB_RECURSE TEST_SRCS tests/cpp/*.cc) add_executable(cpptest ${TEST_SRCS}) target_include_directories(cpptest SYSTEM PUBLIC ${GTEST_INCLUDE_DIR}) target_link_libraries(cpptest PRIVATE ${TVM_TEST_LIBRARY_NAME} ${GTEST_LIB} gtest_main pthread dl) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 704c2d94b8bb..a951264b9706 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -30,6 +30,7 @@ #define TVM_RUNTIME_LOGGING_H_ #include +#include #include #include @@ -38,6 +39,8 @@ #include #include #include +#include +#include /*! * \brief Macro helper to force a function not to be inlined. @@ -129,15 +132,16 @@ * a = ... * b = ... * // if quit_on_assertion is true, if a==b, continue, otherwise quit. - * // if quit_on_assertion is false, if a==b, continue, otherwise 'return false' (default - * behaviour) COND_CHECK_EQ(quit_on_assertion, a, b) << "some error message when quiting" + * // if quit_on_assertion is false, if a==b, continue, otherwise 'return false' + * // (default behaviour) + * COND_CHECK_EQ(quit_on_assertion, a, b) << "some error message when quiting" * ... * for (int i = 0; i < N; i++) { * a = ... * b = ... * // if quit_on_assertion is true, if a==b, continue, otherwise quit. - * // if quit_on_assertion is false, if a==b, continue, otherwise 'break' (non-default - * // behaviour, therefore, has to be explicitly specified) + * // if quit_on_assertion is false, if a==b, continue, otherwise 'break' + * // (non-default behaviour, therefore, has to be explicitly specified) * COND_CHECK_EQ(quit_on_assertion, a, b, break) << "some error message when quiting" * } * } @@ -391,24 +395,131 @@ class LogMessageVoidify { void operator&(std::ostream&) {} }; +/*! \brief Captures the state of the \p TVM_LOG_DEBUG environment flag. */ +class TvmLogDebugSettings { + public: + /*! + * \brief Parses the \p TVM_LOG_DEBUG environment flag as per the specification given by + * \p DebugLoggingEnabled and \p VerboseLoggingEnabled, and caches the result. + */ + inline static const TvmLogDebugSettings& FromFlag() { + // Parse and cache the verbosity level map. + static const auto* settings = + new TvmLogDebugSettings(TvmLogDebugSettings::ParseSpec(std::getenv("TVM_LOG_DEBUG"))); + return *settings; + } + + /*! + * \brief Parses \p opt_spec as per specification for \p TVM_LOG_DEBUG given by + * \p DebugLoggingEnabled and \p VerboseLoggingEnabled. Throws if specification is ill-formed. + */ + static TvmLogDebugSettings ParseSpec(const char* opt_spec); + + /*! + * \brief Implements \p VerboseLoggingEnabled below w.r.t. the already parsed \p TVM_LOG_DEBUG + * environment variable. + */ + inline bool VerboseEnabled(const char* opt_filename, int level) const { + if (opt_filename == nullptr || level < 0 || vlog_level_map_.empty()) { + return false; + } + return VerboseEnabledImpl(opt_filename, level); + } + + /*! \brief Returns true if \p DLOG statements should be executed. */ + bool dlog_enabled() const { return dlog_enabled_; } + + private: + // Slow path for VerboseEnabled. + bool VerboseEnabledImpl(const std::string& filename, int level) const; + + /*! \brief If true, DLOG statements are enabled. */ + bool dlog_enabled_ = false; + /*! + * \brief A map from canonicalized filenames to the maximum VLOG verbosity level for that file. + * May also contain the 'wildcard' entry \p "DEFAULT" representing the level for all other files. + */ + std::unordered_map vlog_level_map_; +}; + +/*! + * \brief Returns true if a DLOG statement is enabled by the \p TVM_LOG_DEBUG environment + * variable. Requires: + * \code + * TVM_LOG_DEBUG=1 + * \endcode + * or a valid setting as described by \p VerboseLoggingEnabled below. + */ // Also from dmlc-core inline bool DebugLoggingEnabled() { static int state = 0; if (state == 0) { - if (auto var = std::getenv("TVM_LOG_DEBUG")) { - if (std::string(var) == "1") { - state = 1; - } else { - state = -1; - } - } else { - // by default hide debug logging. - state = -1; - } + state = TvmLogDebugSettings::FromFlag().dlog_enabled() ? 1 : -1; } return state == 1; } +/*! + * \brief Returns true if a VLOG statement in \p filename is enabled by the \p TVM_LOG_DEBUG + * environment variable for logging at verbosity \p level. Levels should be non-negative. + * + * Filenames are canonicalized to be w.r.t. the src/ dir of the TVM tree. (VLOG's should not + * appear under include/). + * + * To enable file \p relay/foo.cc up to level 2 and \p ir/bar.cc for level 0 only set: + * \code + * TVM_LOG_DEBUG="relay/foo.cc=2;ir/bar.cc=0" + * \endcode + * + * To enable all files up to level 3 but disable \p ir/bar.cc set: + * \code + * TVM_LOG_DEBUG="DEFAULT=2;ir/bar.cc=-1" + * \endcode + * + * Any of these settings will also enable DLOG statements. + */ +inline bool VerboseLoggingEnabled(const char* opt_filename, int level) { + return TvmLogDebugSettings::FromFlag().VerboseEnabled(opt_filename, level); +} + +/*! + * \brief A stack of VLOG context messages. + * + * For use by \p VLOG_CONTEXT macro only. + */ +class VLogContext { + public: + void Push(std::stringstream* stream) { context_stack_.push_back(stream); } + void Pop() { + if (!context_stack_.empty()) { + context_stack_.pop_back(); + } + } + + std::string str() const; + + private: + std::vector context_stack_; +}; + +/*! \brief Thread local \p VLogContext for tracking a stack of VLOG context messages. */ +using ThreadLocalVLogContext = dmlc::ThreadLocalStore; + +/*! + * \brief A RAII class to push/pos a VLOG context message onto the thread-local stack. + * + * For use by \p VLOG_CONTEXT macro only. + */ +class VLogContextEntry { + public: + VLogContextEntry() { ThreadLocalVLogContext::Get()->Push(&sstream_); } + ~VLogContextEntry() { ThreadLocalVLogContext::Get()->Pop(); } + std::ostream& stream() { return sstream_; } + + private: + std::stringstream sstream_; +}; + constexpr const char* kTVM_INTERNAL_ERROR_MESSAGE = "\n" "---------------------------------------------------------------\n" @@ -447,6 +558,7 @@ TVM_CHECK_FUNC(_GE, >=) TVM_CHECK_FUNC(_EQ, ==) TVM_CHECK_FUNC(_NE, !=) #pragma GCC diagnostic pop + } // namespace detail #define LOG(level) LOG_##level @@ -487,6 +599,19 @@ TVM_CHECK_FUNC(_NE, !=) #define DLOG_IF(severity, condition) \ LOG_IF(severity, ::tvm::runtime::detail::DebugLoggingEnabled() && (condition)) +/*! + * \brief If the \p TVM_LOG_DEBUG build flag is enabled, push a context message onto an internal + * stack. All VLOG messages will include this stack in their prefix to help with debugging. E.g.: + * \code + * VLOG_CONTEXT << "my context"; + * VLOG(1) << "my log message"; + * \endcode + * Thread safe. No-op with no execution overhead if the \p TVM_LOG_DEBUG build flag is not enabled. + */ +#define VLOG_CONTEXT \ + ::tvm::runtime::detail::VLogContextEntry vlog_entry_; \ + vlog_entry_.stream() + #else #define LOG_DFATAL LOG_ERROR @@ -494,10 +619,33 @@ TVM_CHECK_FUNC(_NE, !=) #define DLOG(severity) true ? (void)0 : ::tvm::runtime::detail::LogMessageVoidify() & LOG(severity) #define DLOG_IF(severity, condition) \ (true || !(condition)) ? (void)0 : ::tvm::runtime::detail::LogMessageVoidify() & LOG(severity) +#define VLOG_CONTEXT true ? (void)0 : ::tvm::runtime::detail::LogMessageVoidify() & LOG(INFO) #endif +/*! + * \brief If the \p TVM_LOG_DEBUG build flag is enabled, and the containing file has been enabled + * at \p level or greater in the \p TVM_LOG_DEBUG environment variable, then log a message at + * \p INFO severity. + * + * See \p VerboseLoggingEnabled for the format of the \p TVM_LOG_DEBUG environment variable. + * Thread safe. No-op with no execution overhead if the \p TVM_LOG_DEBUG build flag is not enabled. + * No-op with some execution overhead if the \p TVM_LOG_DEBUG build flag is enabled but the + * containing file is not enabled. + */ +#define VLOG(level) \ + DLOG_IF(INFO, ::tvm::runtime::detail::VerboseLoggingEnabled(__FILE__, (level))) \ + << ::tvm::runtime::detail::ThreadLocalVLogContext::Get()->str() + #if TVM_LOG_DEBUG +#define DCHECK(x) CHECK(x) +#define DCHECK_LT(x, y) CHECK((x) < (y)) +#define DCHECK_GT(x, y) CHECK((x) > (y)) +#define DCHECK_LE(x, y) CHECK((x) <= (y)) +#define DCHECK_GE(x, y) CHECK((x) >= (y)) +#define DCHECK_EQ(x, y) CHECK((x) == (y)) +#define DCHECK_NE(x, y) CHECK((x) != (y)) +#else #define DCHECK(x) \ while (false) CHECK(x) #define DCHECK_LT(x, y) \ @@ -512,14 +660,6 @@ TVM_CHECK_FUNC(_NE, !=) while (false) CHECK((x) == (y)) #define DCHECK_NE(x, y) \ while (false) CHECK((x) != (y)) -#else -#define DCHECK(x) CHECK(x) -#define DCHECK_LT(x, y) CHECK((x) < (y)) -#define DCHECK_GT(x, y) CHECK((x) > (y)) -#define DCHECK_LE(x, y) CHECK((x) <= (y)) -#define DCHECK_GE(x, y) CHECK((x) >= (y)) -#define DCHECK_EQ(x, y) CHECK((x) == (y)) -#define DCHECK_NE(x, y) CHECK((x) != (y)) #endif #define TVM_ICHECK_INDENT " " @@ -552,5 +692,6 @@ TVM_CHECK_FUNC(_NE, !=) // Re-export error types using runtime::Error; using runtime::InternalError; + } // namespace tvm #endif // TVM_RUNTIME_LOGGING_H_ diff --git a/src/ir/transform.cc b/src/ir/transform.cc index 4c37f0f1a6e9..0e42b35349cd 100644 --- a/src/ir/transform.cc +++ b/src/ir/transform.cc @@ -409,8 +409,9 @@ IRModule ModulePassNode::operator()(IRModule mod, const PassContext& pass_ctx) c const PassInfo& pass_info = Info(); ICHECK(mod.defined()) << "The input module must be set."; - DLOG(INFO) << "Executing module pass : " << pass_info->name - << " with opt level: " << pass_info->opt_level; + VLOG_CONTEXT << pass_info->name; + VLOG(0) << "Executing module pass with opt level: " << pass_info->opt_level; + VLOG(1) << "Input module:" << std::endl << PrettyPrint(mod); mod = pass_func(std::move(mod), pass_ctx); @@ -422,6 +423,8 @@ IRModule ModulePassNode::operator()(IRModule mod, const PassContext& pass_ctx) c pass_ctx->diag_ctx.value().Render(); pass_ctx->diag_ctx = previous; + VLOG(1) << "Result module:" << std::endl << PrettyPrint(mod); + return mod; } @@ -473,7 +476,10 @@ IRModule SequentialNode::operator()(IRModule mod, const PassContext& pass_ctx) c for (const Pass& pass : passes) { ICHECK(pass.defined()) << "Found undefined pass for optimization."; const PassInfo& pass_info = pass->Info(); - if (!pass_ctx.PassEnabled(pass_info)) continue; + if (!pass_ctx.PassEnabled(pass_info)) { + VLOG(0) << "skipping disabled pass '" << pass_info->name << "'"; + continue; + } // resolve dependencies for (const auto& it : pass_info->required) { mod = GetPass(it)(std::move(mod), pass_ctx); diff --git a/src/parser/parser.cc b/src/parser/parser.cc index c6407e8909d9..93dc687d72f5 100644 --- a/src/parser/parser.cc +++ b/src/parser/parser.cc @@ -417,7 +417,7 @@ class Parser { * Useful for matching optional tokens, effectively looksahead by one. */ bool WhenMatch(const TokenType& token_type) { - DLOG(INFO) << "Parser::WhenMatch: Peek() == " << Peek(); + VLOG(1) << "Parser::WhenMatch: Peek() == " << Peek(); if (Peek()->token_type == token_type) { Consume(token_type); return true; @@ -594,7 +594,7 @@ class Parser { template R WithSpan(std::function parser) { auto start_span = Peek()->span; - DLOG(INFO) << "WithSpan: start_span = " << start_span; + VLOG(0) << "WithSpan: start_span = " << start_span; R ast = parser(); if (ast.defined()) { // The token at the head of the stream is now 1 past where we parsed. So we find its start @@ -608,7 +608,7 @@ class Parser { span_pos--; } auto end_token = tokens.at(span_pos); - DLOG(INFO) << "WithSpan: end_span = " << end_token->span; + VLOG(0) << "WithSpan: end_span = " << end_token->span; ast->span = start_span.Merge(end_token->span); } return ast; @@ -668,8 +668,8 @@ class Parser { template Array ParseSequence(TokenType start, TokenType sep, TokenType stop, std::function parse, std::function before_stop = nullptr) { - DLOG(INFO) << "Parser::ParseSequence: start=" << ToString(start) << " sep=" << ToString(sep) - << " stop=" << ToString(stop); + VLOG(0) << "Parser::ParseSequence: start=" << ToString(start) << " sep=" << ToString(sep) + << " stop=" << ToString(stop); Match(start); // This is for the empty arguments list case, if we have token stream @@ -686,7 +686,7 @@ class Parser { if (WhenMatch(stop)) { return Array(); } else { - DLOG(INFO) << "Parser::ParseSequence: parse first"; + VLOG(0) << "Parser::ParseSequence: parse first"; auto data = parse(); Array elements = {data}; @@ -695,7 +695,7 @@ class Parser { // parse '( expr ',' * ')' } else if (WhenMatch(sep)) { while (true) { - DLOG(INFO) << "Parser::ParseSequence: parse element"; + VLOG(0) << "Parser::ParseSequence: parse element"; if (WhenMatch(stop)) { break; } else { @@ -893,12 +893,12 @@ class Parser { /*! \brief Parse a single Relay expression. */ Expr ParseExpr() { - DLOG(INFO) << "Parser::ParseExpr"; + VLOG(0) << "Parser::ParseExpr"; return WithSpan([this] { std::vector exprs; while (true) { - DLOG(INFO) << "Parser::ParseExpr: parsing a single expression"; + VLOG(0) << "Parser::ParseExpr: parsing a single expression"; auto next = Peek(); switch (next->token_type) { // For graph or let, match first rhs, then invoke ParseBindingExpr @@ -1011,7 +1011,7 @@ class Parser { // This ensures for n sequential bindings // the call depth will be the same before // and after parsing the n bindings. - DLOG(INFO) << "Parser::ParseBindingExpr"; + VLOG(0) << "Parser::ParseBindingExpr"; std::vector> bindings; int scopes = 0; @@ -1085,7 +1085,7 @@ class Parser { * Handles things of the form [T1, ..., TN](arg1: U1, ..., argN : UN) -> Ret { body }. */ Function ParseFunctionDef() { - DLOG(INFO) << "Parser::ParseFunctionDef"; + VLOG(0) << "Parser::ParseFunctionDef"; return WithSpan([&]() { PushScope(); PushTypeScope(); @@ -1149,7 +1149,7 @@ class Parser { /*! \brief Parse an if-expression. */ Expr ParseIf() { return WithSpan([&]() { - DLOG(INFO) << "Parser::ParseIf"; + VLOG(0) << "Parser::ParseIf"; Consume(TokenType::kIf); auto guard = WithSpan([&] { return Parens([&] { return ParseExpr(); }); }); @@ -1188,7 +1188,7 @@ class Parser { * This function recursively parses a pattern. */ Pattern ParsePattern() { - DLOG(INFO) << "Parser::ParsePattern"; + VLOG(0) << "Parser::ParsePattern"; auto next = Peek(); switch (next->token_type) { case TokenType::kUnderscore: { @@ -1251,7 +1251,7 @@ class Parser { } Expr ParseExprBinOp() { - DLOG(INFO) << "Parser::ParseExprBinOp"; + VLOG(0) << "Parser::ParseExprBinOp"; return WithSpan([this] { // We must parse at least one expression, the default // case is that there is no operator and we will fall @@ -1335,7 +1335,7 @@ class Parser { } ObjectRef ParseAttributeValue() { - DLOG(INFO) << "Parser::ParseAttributeValue"; + VLOG(0) << "Parser::ParseAttributeValue"; auto next = Peek(); switch (next->token_type) { case TokenType::kFloat: @@ -1377,7 +1377,7 @@ class Parser { } Map ParseAttrs() { - DLOG(INFO) << "Parser::ParseAttrs"; + VLOG(0) << "Parser::ParseAttrs"; Map kwargs; while (Peek()->token_type == TokenType::kIdentifier) { auto key = GetHierarchicalName(ParseHierarchicalName().data); @@ -1389,14 +1389,14 @@ class Parser { kwargs.Set(key, value); WhenMatch(TokenType::kComma); } - DLOG(INFO) << "Parser::ParseAttrs: kwargs=" << kwargs; + VLOG(0) << "Parser::ParseAttrs: kwargs=" << kwargs; return kwargs; } Expr ParseCallArgs(Expr op) { ICHECK(op.defined()) << "the operator must be defined"; - DLOG(INFO) << "Parser::ParseCallArgs"; + VLOG(0) << "Parser::ParseCallArgs"; Attrs attrs; std::string op_key; bool is_op = false; @@ -1469,7 +1469,7 @@ class Parser { } Expr ParseCallExpr() { - DLOG(INFO) << "Parser::ParseCallExpr"; + VLOG(0) << "Parser::ParseCallExpr"; return WithSpan([this] { Expr expr = ParseAtomicExpr(); // Parse as many call args as possible, building up expression @@ -1498,7 +1498,7 @@ class Parser { } Expr GetOp(const std::string& op_name, const Span& span) { - DLOG(INFO) << "op_name=" << op_name << " span=" << span; + VLOG(0) << "op_name=" << op_name << " span=" << span; try { return Op::Get(op_name); } catch (const Error& e) { @@ -1511,7 +1511,7 @@ class Parser { } Expr ParseAtomicExpr() { - DLOG(INFO) << "Parser::ParseAtomicExpr"; + VLOG(0) << "Parser::ParseAtomicExpr"; Expr expr = WithSpan([this] { auto next = Peek(); switch (next->token_type) { @@ -1647,7 +1647,7 @@ class Parser { auto token = Match(TokenType::kInteger); auto index = token.ToNumber(); auto span = token->span.Merge(expr->span); - DLOG(INFO) << "Parser::ParseAtomicExpr: tuple get item"; + VLOG(0) << "Parser::ParseAtomicExpr: tuple get item"; return relay::TupleGetItem(expr, index, span); } else { return expr; @@ -1868,8 +1868,7 @@ class Parser { Parser InitParser(const std::string& file_name, const std::string& file_content, Optional init_module) { - DLOG(INFO) << "InitParser: file_name: " << file_name - << "file_content_size: " << file_content.size(); + VLOG(0) << "InitParser: file_name: " << file_name << "file_content_size: " << file_content.size(); SourceName src_name = SourceName::Get(file_name); Source source(src_name, file_content); @@ -1894,7 +1893,7 @@ Parser InitParser(const std::string& file_name, const std::string& file_content, IRModule ParseModule(std::string file_name, std::string file_content, Optional init_module) { - DLOG(INFO) << "ParseModule"; + VLOG(0) << "ParseModule"; auto parser = InitParser(file_name, file_content, init_module); auto mod = parser.ParseModule(); ICHECK(mod.defined()) << "The parser must return a non-null module."; @@ -1908,7 +1907,7 @@ IRModule ParseModule(std::string file_name, std::string file_content, } Expr ParseExpr(std::string file_name, std::string file_content) { - DLOG(INFO) << "ParseExpr"; + VLOG(0) << "ParseExpr"; auto parser = InitParser(file_name, file_content, Optional()); parser.ParseSemVer(false); parser.PushScope(); diff --git a/src/parser/tokenizer.h b/src/parser/tokenizer.h index d7b3b3f6f681..8f197db45318 100644 --- a/src/parser/tokenizer.h +++ b/src/parser/tokenizer.h @@ -339,7 +339,7 @@ struct Tokenizer { int line = this->line; int col = this->col; auto next = Peek(); - DLOG(INFO) << "tvm::parser::TokenizeOnce: next=" << next; + VLOG(1) << "tvm::parser::TokenizeOnce: next=" << next; if (next == '\n') { auto token = NewToken(TokenType::kNewline); Next(); @@ -550,7 +550,7 @@ struct Tokenizer { } void Tokenize() { - DLOG(INFO) << "tvm::parser::Tokenize"; + VLOG(0) << "tvm::parser::Tokenize"; while (this->More()) { auto token = TokenizeOnce(); ICHECK(token.defined()); diff --git a/src/printer/relay_text_printer.cc b/src/printer/relay_text_printer.cc index aad42fc9b0ea..ea97bb35a09f 100644 --- a/src/printer/relay_text_printer.cc +++ b/src/printer/relay_text_printer.cc @@ -34,6 +34,7 @@ */ #include #include +#include #include #include #include @@ -119,6 +120,9 @@ Doc RelayTextPrinter::Print(const ObjectRef& node, bool meta, bool try_inline) { return PrintPattern(Downcast(node), meta); } else if (node.as()) { return PrintMod(Downcast(node)); + } else if (!show_meta_data_ && node.as()) { + // Show attributes in readable form. + return PrintAttrs(Downcast(node)); } else { // default module. std::ostringstream os; @@ -769,6 +773,8 @@ Doc RelayTextPrinter::PrintAttr(const ObjectRef& value, bool meta) { printed_attr << "?"; } else if (auto str_obj = value.as()) { printed_attr << Doc::StrLiteral(GetRef(str_obj)); + } else if (const auto* on_device_attrs = value.as()) { + printed_attr << "device_type=" << on_device_attrs->device_type; } else if (meta) { printed_attr = meta_->GetMetaNode(Downcast(value)); } else { @@ -848,17 +854,28 @@ class RelayTextPrinter::AttrPrinter : public AttrVisitor { RelayTextPrinter* parent_; }; +Doc RelayTextPrinter::PrintAttrs(const Attrs& attrs) { + std::vector docs; + AttrPrinter printer(&docs, this); + const_cast(attrs.operator->())->VisitNonDefaultAttrs(&printer); + Doc doc; + doc << "{" << Doc::Concat(docs) << "}"; + + return doc; +} + std::vector RelayTextPrinter::PrintCallAttrs(const Attrs& attrs, const Expr& op) { std::vector docs; if (!attrs.defined()) return docs; const auto* op_node = op.as(); - if (op_node && (attrs->type_index() != op_node->attrs_type_index)) { + if (show_meta_data_ && op_node && (attrs->type_index() != op_node->attrs_type_index)) { // fallback Doc doc; doc << meta_->GetMetaNode(attrs); docs.push_back(doc); return docs; } else { + // Show attributes in readable form. AttrPrinter printer(&docs, this); const_cast(attrs.operator->())->VisitNonDefaultAttrs(&printer); if (!op_node) { diff --git a/src/printer/text_printer.cc b/src/printer/text_printer.cc index 1e882db1fd61..b8533a5d8801 100644 --- a/src/printer/text_printer.cc +++ b/src/printer/text_printer.cc @@ -67,7 +67,7 @@ Doc TextPrinter::PrintMod(const IRModule& mod) { String PrettyPrint(const ObjectRef& node) { Doc doc; - doc << TextPrinter(false, nullptr, false).PrintFinal(node); + doc << TextPrinter(/*show_meta_data=*/false, nullptr, false).PrintFinal(node); return doc.str(); } diff --git a/src/printer/text_printer.h b/src/printer/text_printer.h index 0332a2d539d2..7e4a56529ddc 100644 --- a/src/printer/text_printer.h +++ b/src/printer/text_printer.h @@ -77,6 +77,7 @@ class RelayTextPrinter : public ExprFunctor, // numbers to be reused and prevents hoisted vars from escaping too far Doc PrintScope(const ObjectRef& node); Doc PrintFinal(const ObjectRef& node); + Doc PrintAttrs(const Attrs& attrs); std::vector PrintCallAttrs(const Attrs& attrs, const Expr& op); std::vector PrintFuncAttrs(const Attrs& attrs); Doc PrintSpan(const Span& span); diff --git a/src/relay/ir/dataflow_matcher.cc b/src/relay/ir/dataflow_matcher.cc index 851a498377b2..89f22cfb25b2 100644 --- a/src/relay/ir/dataflow_matcher.cc +++ b/src/relay/ir/dataflow_matcher.cc @@ -771,6 +771,8 @@ TVM_REGISTER_GLOBAL("relay.dataflow_pattern.DFPatternCallback") }); Expr PatternRewriter::Rewrite(const Array& callbacks, const Expr& pre) { + VLOG_CONTEXT << "PatternRewriter"; + VLOG(1) << "rewriting:" << std::endl << PrettyPrint(pre); auto post = pre; auto last = post; // rewrite the graph until it stops changing to make sure all rewrites are complete @@ -789,7 +791,9 @@ Expr PatternRewriter::Rewrite(const Array& callbacks, const E groups_ = grouper.GroupMatches(callback_->pattern, post); gid_assignments_ = grouper.GetGIDAssignments(); memo_.clear(); + VLOG(1) << "pre rewritten:" << std::endl << PrettyPrint(pre); post = this->VisitExpr(post); + VLOG(1) << "post rewritten:" << std::endl << PrettyPrint(post); count++; } equal = (*structural_equal)(last, post, false, true); diff --git a/src/relay/ir/transform.cc b/src/relay/ir/transform.cc index 344d1cae7823..eacd3783d9b1 100644 --- a/src/relay/ir/transform.cc +++ b/src/relay/ir/transform.cc @@ -130,8 +130,9 @@ IRModule FunctionPassNode::operator()(IRModule mod, const PassContext& pass_ctx) ICHECK(mod.defined()); - DLOG(INFO) << "Executing function pass : " << pass_info->name - << " with opt level: " << pass_info->opt_level; + VLOG_CONTEXT << pass_info->name; + VLOG(0) << "Executing function pass with opt level: " << pass_info->opt_level; + VLOG(1) << "Input module:" << std::endl << PrettyPrint(mod); IRModule updated_mod = mod->ShallowCopy(); @@ -155,6 +156,8 @@ IRModule FunctionPassNode::operator()(IRModule mod, const PassContext& pass_ctx) pass_ctx->diag_ctx.value().Render(); pass_ctx->diag_ctx = previous; + VLOG(1) << "Output module:" << std::endl << PrettyPrint(updated_mod); + // TODO(@jroesch): move away from eager type checking for performance reasons // make issue. return transform::InferType()(updated_mod); diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 8f0537ad7adc..9c193921f93b 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -29,6 +29,7 @@ #include #include #include +#include #include namespace tvm { @@ -119,7 +120,7 @@ int BacktraceFullCallback(void* data, uintptr_t pc, const char* filename, int li std::string Backtrace() { BacktraceInfo bt; - bt.max_size = 100; + bt.max_size = 500; if (_bt_state == nullptr) { return ""; } @@ -166,10 +167,102 @@ namespace tvm { namespace runtime { namespace detail { +namespace { +constexpr const char* kSrcPrefix = "/src/"; +// Note: Better would be std::char_traits::length(kSrcPrefix) but it is not +// a constexpr on all compilation targets. +constexpr const size_t kSrcPrefixLength = 5; +constexpr const char* kDefaultKeyword = "DEFAULT"; +} // namespace + +/* static */ +TvmLogDebugSettings TvmLogDebugSettings::ParseSpec(const char* opt_spec) { + TvmLogDebugSettings settings; + if (opt_spec == nullptr) { + // DLOG and VLOG disabled. + return settings; + } + std::string spec(opt_spec); + if (spec.empty() || spec == "0") { + // DLOG and VLOG disabled. + return settings; + } + settings.dlog_enabled_ = true; + if (spec == "1") { + // Legacy specification for enabling just DLOG. + return settings; + } + std::istringstream spec_stream(spec); + while (spec_stream) { + std::string name; + if (!std::getline(spec_stream, name, '=')) { + // Reached end. + break; + } + if (name.empty()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty name"; + return settings; + } + + std::string level; + if (!std::getline(spec_stream, level, ';')) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, expecting level"; + return settings; + } + if (level.empty()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty level"; + return settings; + } + // Parse level, default to 0 if ill-formed which we don't detect. + char* end_of_level = nullptr; + int level_val = static_cast(strtol(level.c_str(), &end_of_level, 10)); + if (end_of_level != level.c_str() + level.size()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, invalid level"; + return settings; + } + LOG(INFO) << "TVM_LOG_DEBUG enables VLOG statements in '" << name << "' up to level " << level; + settings.vlog_level_map_.emplace(name, level_val); + } + return settings; +} + +bool TvmLogDebugSettings::VerboseEnabledImpl(const std::string& filename, int level) const { + // Canonicalize the filename. + // TODO(mbs): Not Windows friendly. + size_t last_src = filename.rfind(kSrcPrefix, std::string::npos, kSrcPrefixLength); + // Strip anything before the /src/ prefix, on the assumption that will yield the + // TVM project relative filename. If no such prefix fallback to filename without + // canonicalization. + std::string key = + last_src == std::string::npos ? filename : filename.substr(last_src + kSrcPrefixLength); + // Check for exact match. + auto itr = vlog_level_map_.find(key); + if (itr != vlog_level_map_.end()) { + return level <= itr->second; + } + // Check for default. + itr = vlog_level_map_.find(kDefaultKeyword); + if (itr != vlog_level_map_.end()) { + return level <= itr->second; + } + return false; +} + LogFatal::Entry& LogFatal::GetEntry() { static thread_local LogFatal::Entry result; return result; } + +std::string VLogContext::str() const { + std::stringstream result; + for (const auto* entry : context_stack_) { + ICHECK_NOTNULL(entry); + result << entry->str(); + result << ": "; + } + return result.str(); +} + } // namespace detail } // namespace runtime } // namespace tvm diff --git a/tests/cpp/runtime/logging_test.cc b/tests/cpp/runtime/logging_test.cc new file mode 100644 index 000000000000..a4e6c01444e6 --- /dev/null +++ b/tests/cpp/runtime/logging_test.cc @@ -0,0 +1,70 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#include +#include + +namespace tvm { +namespace runtime { +namespace detail { +namespace { + +TEST(TvmLogDebugSettings, Disabled) { + TvmLogDebugSettings settings = TvmLogDebugSettings::ParseSpec(nullptr); + EXPECT_FALSE(settings.dlog_enabled()); + + settings = TvmLogDebugSettings::ParseSpec(""); + EXPECT_FALSE(settings.dlog_enabled()); + + settings = TvmLogDebugSettings::ParseSpec("0"); + EXPECT_FALSE(settings.dlog_enabled()); +} + +TEST(TvmLogDebugSettings, DlogOnly) { + TvmLogDebugSettings settings = TvmLogDebugSettings::ParseSpec("1"); + EXPECT_TRUE(settings.dlog_enabled()); + EXPECT_FALSE(settings.VerboseEnabled("my/filesytem/src/foo/bar.cc", 0)); +} + +TEST(TvmLogDebugSettings, VLogEnabledDefault) { + TvmLogDebugSettings settings = TvmLogDebugSettings::ParseSpec("DEFAULT=3"); + EXPECT_TRUE(settings.dlog_enabled()); + EXPECT_TRUE(settings.VerboseEnabled("my/filesytem/src/foo/bar.cc", 3)); + EXPECT_FALSE(settings.VerboseEnabled("my/filesytem/src/foo/bar.cc", 4)); +} + +TEST(TvmLogDebugSettings, VLogEnabledComplex) { + TvmLogDebugSettings settings = + TvmLogDebugSettings::ParseSpec("foo/bar.cc=3;baz.cc=-1;DEFAULT=2;another/file.cc=4"); + EXPECT_TRUE(settings.dlog_enabled()); + EXPECT_TRUE(settings.VerboseEnabled("my/filesystem/src/foo/bar.cc", 3)); + EXPECT_FALSE(settings.VerboseEnabled("my/filesystem/src/foo/bar.cc", 4)); + EXPECT_TRUE(settings.VerboseEnabled("my/filesystem/src/foo/other.cc", 2)); + EXPECT_FALSE(settings.VerboseEnabled("my/filesystem/src/foo/other.cc", 3)); + EXPECT_FALSE(settings.VerboseEnabled("my/filesystem/src/baz.cc", 0)); +} + +TEST(TvmLogDebugSettings, IllFormed) { + EXPECT_THROW(TvmLogDebugSettings::ParseSpec("foo/bar.cc=bogus;"), InternalError); +} + +} // namespace +} // namespace detail +} // namespace runtime +} // namespace tvm