From cadc92490a353026e3c1d00576d94e9ef1a5f0cc Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Tue, 14 Sep 2021 14:17:32 -0700 Subject: [PATCH 01/12] [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. --- CMakeLists.txt | 2 +- include/tvm/runtime/logging.h | 120 +++++++++++++++++++++++++++--- 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 | 114 +++++++++++++++++++++++++++- tests/cpp/runtime/logging_test.cc | 70 +++++++++++++++++ 12 files changed, 357 insertions(+), 49 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..956e9ae53bb6 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,7 @@ #include #include #include +#include /*! * \brief Macro helper to force a function not to be inlined. @@ -129,8 +131,9 @@ * 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 = ... @@ -395,8 +398,8 @@ class LogMessageVoidify { inline bool DebugLoggingEnabled() { static int state = 0; if (state == 0) { - if (auto var = std::getenv("TVM_LOG_DEBUG")) { - if (std::string(var) == "1") { + if (const char* var = std::getenv("TVM_LOG_DEBUG")) { + if (var[0] == '1') { state = 1; } else { state = -1; @@ -409,6 +412,68 @@ inline bool DebugLoggingEnabled() { return state == 1; } +/*! \brief Helpers for \p VerboseLoggingEnabled. Exposed for unit testing only. */ +std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec); +bool VerboseEnabledInMap(const char* filename, int level, + const std::unordered_map& map); + +/*! + * \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. + * + * 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="1;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="1;*=2;ir/bar.cc=-1;" + * \endcode + */ +bool VerboseLoggingEnabled(const char* filename, int 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 +512,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 +553,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 as 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 +573,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 +614,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 " " @@ -549,8 +643,10 @@ TVM_CHECK_FUNC(_NE, !=) (x) : (x)) // NOLINT(*) } // namespace runtime + // 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..4662a95399ec 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,121 @@ namespace tvm { namespace runtime { namespace detail { +std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) { + // Cache the verbosity level map. + std::unordered_map map; + LOG(INFO) << "initializing VLOG map"; + if (opt_spec == nullptr) { + LOG(INFO) << "VLOG disabled, no TVM_LOG_DEBUG environment variable"; + return map; + } + std::string spec(opt_spec); + // Check we are enabled overall with at least one VLOG option. + if (spec.rfind("1;", 0) != 0) { + LOG(INFO) << "VLOG disabled, TVM_LOG_DEBUG does not start with '1;'"; + return map; + } + size_t start = 2UL; + while (start < spec.size()) { + // We are looking for "name=level;" or "*=level;" + size_t end = start; + // Scan up to '='. + while (spec[end] != '=') { + ++end; + if (end >= spec.size()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing '='"; + return map; + } + } + if (end == start) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty name"; + return map; + } + std::string name(spec.substr(start, end - start)); + // Skip '=' + ++end; + if (end >= spec.size()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing level"; + return map; + } + // Scan up to ';'. + start = end; + while (spec[end] != ';') { + ++end; + if (end >= spec.size()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing ';'"; + return map; + } + } + if (end == start) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty level"; + return map; + } + std::string level_str(spec.substr(start, end - start)); + // Skip ';'. + ++end; + // Parse level, default to 0 if ill-formed which we don't detect. + char* end_of_level = nullptr; + int level = static_cast(strtol(level_str.c_str(), &end_of_level, 10)); + if (end_of_level != level_str.c_str() + level_str.size()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, invalid level"; + } + LOG(INFO) << "adding VLOG entry for '" << name << "' at level " << level; + map.emplace(name, level); + start = end; + } + return map; +} + +bool VerboseEnabledInMap(const char* filename, int level, + const std::unordered_map& map) { + if (filename == nullptr || level < 0) { + return false; + } + // Canonicalize filename. + std::string key(filename); + // TODO(mbs): Not Windows friendly. + size_t last_src = key.rfind("/src/", std::string::npos, 5); + if (last_src != std::string::npos) { + key = key.substr(last_src + 5); + } + // Assume disabled. + int limit = -1; + // Apply '*' wildcard if any. + auto itr = map.find("*"); + if (itr != map.end()) { + limit = itr->second; + } + // Apply specific filename if any. + itr = map.find(key); + if (itr != map.end()) { + limit = itr->second; + } + return level <= limit; +} + +bool VerboseLoggingEnabled(const char* filename, int level) { + // Cache the verbosity level map. + static const std::unordered_map* map = + new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); + return VerboseEnabledInMap(filename, level, *map); +}; + 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..7472e37abf61 --- /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 +#include + +namespace tvm { +namespace runtime { +namespace detail { +namespace { + +TEST(ParseTvmLogDebugSpec, Disabled) { + auto map = ParseTvmLogDebugSpec(nullptr); + EXPECT_THAT(map.size(), testing::Eq(0)); + + map = ParseTvmLogDebugSpec(""); + EXPECT_THAT(map.size(), testing::Eq(0)); + + map = ParseTvmLogDebugSpec("0"); + EXPECT_THAT(map.size(), testing::Eq(0)); + + map = ParseTvmLogDebugSpec("1"); + EXPECT_THAT(map.size(), testing::Eq(0)); +} + +TEST(ParseTvmLogDebugSpec, SomeEnabled) { + auto map = ParseTvmLogDebugSpec("1;foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); + EXPECT_THAT(map.size(), testing::Eq(4)); + + EXPECT_THAT(map, testing::Contains(testing::Pair("*", 2))); + EXPECT_THAT(map, testing::Contains(testing::Pair("foo/bar.cc", 3))); + EXPECT_THAT(map, testing::Contains(testing::Pair("baz.cc", -1))); + EXPECT_THAT(map, testing::Contains(testing::Pair("another/file.cc", 4))); +} + +TEST(ParseTvmLogDebugSpec, IllFormed) { + EXPECT_THROW(ParseTvmLogDebugSpec("1;foo/bar.cc=bogus;"), InternalError); +} + +TEST(VerboseEnabledInMap, Lookup) { + auto map = ParseTvmLogDebugSpec("1;foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); + + EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 3, map)); + EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 4, map)); + EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/other.cc", 2, map)); + EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/foo/other.cc", 3, map)); + EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/baz.cc", 0, map)); +} + +} // namespace +} // namespace detail +} // namespace runtime +} // namespace tvm \ No newline at end of file From 51dfc56631c1c7723025ba5e037de62efb4215c4 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Tue, 14 Sep 2021 14:22:42 -0700 Subject: [PATCH 02/12] [checkpoint] lints --- include/tvm/runtime/logging.h | 1 + src/runtime/logging.cc | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 956e9ae53bb6..aca060cbd1bf 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -40,6 +40,7 @@ #include #include #include +#include /*! * \brief Macro helper to force a function not to be inlined. diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 4662a95399ec..2a9dd69f0201 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -265,7 +265,7 @@ bool VerboseLoggingEnabled(const char* filename, int level) { static const std::unordered_map* map = new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); return VerboseEnabledInMap(filename, level, *map); -}; +} LogFatal::Entry& LogFatal::GetEntry() { static thread_local LogFatal::Entry result; From 5751337fea3eba94136b6e1e47c1379337637eac Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Tue, 14 Sep 2021 14:33:33 -0700 Subject: [PATCH 03/12] [checkpoint] missing \n lint Gotta get my docker setup going --- tests/cpp/runtime/logging_test.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/cpp/runtime/logging_test.cc b/tests/cpp/runtime/logging_test.cc index 7472e37abf61..88eb0d010a39 100644 --- a/tests/cpp/runtime/logging_test.cc +++ b/tests/cpp/runtime/logging_test.cc @@ -67,4 +67,4 @@ TEST(VerboseEnabledInMap, Lookup) { } // namespace } // namespace detail } // namespace runtime -} // namespace tvm \ No newline at end of file +} // namespace tvm From b7b8176a7f18401cac60fde1e592ab9020c0baf0 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Tue, 14 Sep 2021 16:16:47 -0700 Subject: [PATCH 04/12] [checkpoint] woops, we don't support gmock.h --- tests/cpp/runtime/logging_test.cc | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/tests/cpp/runtime/logging_test.cc b/tests/cpp/runtime/logging_test.cc index 88eb0d010a39..40dc78d1ae9c 100644 --- a/tests/cpp/runtime/logging_test.cc +++ b/tests/cpp/runtime/logging_test.cc @@ -17,7 +17,6 @@ * under the License. */ -#include #include #include @@ -28,26 +27,26 @@ namespace { TEST(ParseTvmLogDebugSpec, Disabled) { auto map = ParseTvmLogDebugSpec(nullptr); - EXPECT_THAT(map.size(), testing::Eq(0)); + EXPECT_EQ(map.size(), 0); map = ParseTvmLogDebugSpec(""); - EXPECT_THAT(map.size(), testing::Eq(0)); + EXPECT_EQ(map.size(), 0); map = ParseTvmLogDebugSpec("0"); - EXPECT_THAT(map.size(), testing::Eq(0)); + EXPECT_EQ(map.size(), 0); map = ParseTvmLogDebugSpec("1"); - EXPECT_THAT(map.size(), testing::Eq(0)); + EXPECT_EQ(map.size(), 0); } TEST(ParseTvmLogDebugSpec, SomeEnabled) { auto map = ParseTvmLogDebugSpec("1;foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); - EXPECT_THAT(map.size(), testing::Eq(4)); + EXPECT_EQ(map.size(), 4); - EXPECT_THAT(map, testing::Contains(testing::Pair("*", 2))); - EXPECT_THAT(map, testing::Contains(testing::Pair("foo/bar.cc", 3))); - EXPECT_THAT(map, testing::Contains(testing::Pair("baz.cc", -1))); - EXPECT_THAT(map, testing::Contains(testing::Pair("another/file.cc", 4))); + EXPECT_EQ(map["*"], 2); + EXPECT_EQ(map["foo/bar.cc"], 3); + EXPECT_EQ(map["baz.cc"], -1); + EXPECT_EQ(map["another/file.cc"], 4); } TEST(ParseTvmLogDebugSpec, IllFormed) { From e75d7a92d78efcd989bf38f32267ec9055b026b1 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Tue, 14 Sep 2021 16:57:37 -0700 Subject: [PATCH 05/12] [checkpoint] Address Hua Jiang's comments. --- include/tvm/runtime/logging.h | 16 ++++++++------ src/runtime/logging.cc | 41 ++++++++++++++++++++--------------- 2 files changed, 33 insertions(+), 24 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index aca060cbd1bf..8b9b3c72eae5 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -400,9 +400,12 @@ inline bool DebugLoggingEnabled() { static int state = 0; if (state == 0) { if (const char* var = std::getenv("TVM_LOG_DEBUG")) { - if (var[0] == '1') { + std::string var_str(var); + if (var_str == "1" || var_str.rfind("1;", 0) == 0) { + // Enabled, either without or with an additional VLOG specification. state = 1; } else { + // Not enabled. state = -1; } } else { @@ -415,7 +418,7 @@ inline bool DebugLoggingEnabled() { /*! \brief Helpers for \p VerboseLoggingEnabled. Exposed for unit testing only. */ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec); -bool VerboseEnabledInMap(const char* filename, int level, +bool VerboseEnabledInMap(const std::string& filename, int level, const std::unordered_map& map); /*! @@ -444,17 +447,17 @@ bool VerboseLoggingEnabled(const char* filename, int level); */ class VLogContext { public: - void Push(std::stringstream* stream) { context_stack.push_back(stream); } + void Push(std::stringstream* stream) { context_stack_.push_back(stream); } void Pop() { - if (!context_stack.empty()) { - context_stack.pop_back(); + if (!context_stack_.empty()) { + context_stack_.pop_back(); } } std::string str() const; private: - std::vector context_stack; + std::vector context_stack_; }; /*! \brief Thread local \p VLogContext for tracking a stack of VLOG context messages. */ @@ -644,7 +647,6 @@ TVM_CHECK_FUNC(_NE, !=) (x) : (x)) // NOLINT(*) } // namespace runtime - // Re-export error types using runtime::Error; using runtime::InternalError; diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 2a9dd69f0201..7b8b7830046c 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -26,6 +26,7 @@ #include #include +#include #include #include #include @@ -233,37 +234,43 @@ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) return map; } -bool VerboseEnabledInMap(const char* filename, int level, +constexpr const char* kSrcPrefix = "/src/"; + +bool VerboseEnabledInMap(const std::string& filename, int level, const std::unordered_map& map) { - if (filename == nullptr || level < 0) { + if (level < 0) { return false; } // Canonicalize filename. - std::string key(filename); // TODO(mbs): Not Windows friendly. - size_t last_src = key.rfind("/src/", std::string::npos, 5); - if (last_src != std::string::npos) { - key = key.substr(last_src + 5); - } - // Assume disabled. - int limit = -1; - // Apply '*' wildcard if any. - auto itr = map.find("*"); + + const size_t prefix_length = strlen(kSrcPrefix); + size_t last_src = filename.rfind(kSrcPrefix, std::string::npos, prefix_length); + // 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 + prefix_length); + // Check for exact. + auto itr = map.find(key); if (itr != map.end()) { - limit = itr->second; + return level <= itr->second; } - // Apply specific filename if any. - itr = map.find(key); + // Check for '*' wildcard. + itr = map.find("*"); if (itr != map.end()) { - limit = itr->second; + return level <= itr->second; } - return level <= limit; + return false; } bool VerboseLoggingEnabled(const char* filename, int level) { // Cache the verbosity level map. static const std::unordered_map* map = new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); + if (filename == nullptr) { + return false; + } return VerboseEnabledInMap(filename, level, *map); } @@ -274,7 +281,7 @@ LogFatal::Entry& LogFatal::GetEntry() { std::string VLogContext::str() const { std::stringstream result; - for (const auto* entry : context_stack) { + for (const auto* entry : context_stack_) { ICHECK_NOTNULL(entry); result << entry->str(); result << ": "; From 69ea23f874d17117c12377f2558664f0b80a2523 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Wed, 15 Sep 2021 08:51:58 -0700 Subject: [PATCH 06/12] [checkpoint] strlen not avail on all toolchains? --- src/runtime/logging.cc | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 7b8b7830046c..5d4c6b193f5b 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -26,7 +26,6 @@ #include #include -#include #include #include #include @@ -235,6 +234,7 @@ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) } constexpr const char* kSrcPrefix = "/src/"; +constexpr const size_t kSrcPrefixLength = 5; bool VerboseEnabledInMap(const std::string& filename, int level, const std::unordered_map& map) { @@ -244,13 +244,12 @@ bool VerboseEnabledInMap(const std::string& filename, int level, // Canonicalize filename. // TODO(mbs): Not Windows friendly. - const size_t prefix_length = strlen(kSrcPrefix); - size_t last_src = filename.rfind(kSrcPrefix, std::string::npos, prefix_length); + 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 + prefix_length); + last_src == std::string::npos ? filename : filename.substr(last_src + kSrcPrefixLength); // Check for exact. auto itr = map.find(key); if (itr != map.end()) { From 214ab8213cdda4cb23adbd0541d7c842dd45b562 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Thu, 16 Sep 2021 15:23:45 -0700 Subject: [PATCH 07/12] [checkpoint] Rework TVM_LOG_DEBUG spec and parser --- include/tvm/runtime/logging.h | 59 ++++++++++++-------- src/runtime/logging.cc | 92 ++++++++++++++----------------- tests/cpp/runtime/logging_test.cc | 26 ++++----- 3 files changed, 89 insertions(+), 88 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 8b9b3c72eae5..8f25e290e6a4 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -133,15 +133,15 @@ * 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) + * // (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" * } * } @@ -395,32 +395,43 @@ class LogMessageVoidify { void operator&(std::ostream&) {} }; +// The following three methods are helpers for \p DebugLoggingEnabled and \p VerboseLoggingEnabled. +// They are public for unit testing only. + +// Parses \p opt_spec as per specification for \p TVM_LOG_DEBUG given by \p DebugLoggingEnabled +// and \p VerboseLoggingEnabled. The map is non-empty iff DLOG is enabled. The map has an +// entry for a specific file iff that file is mentioned in \p TVM_LOG_DEBUG. Tha map has a +// '*' wildcard entry iff \p TVM_LOG_DEBUG=1 or \p TVM_LOG_DEBUG has a wildcard entry. +std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec); +// As above, but using the actual \p TVM_LOG_DEBUG environment variable. +const std::unordered_map& TvmLogDebugSpec(); +// As for \p VerboseLoggingEnabled, but using given \p map. +bool VerboseEnabledInMap(const std::string& filename, int level, + const std::unordered_map& 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 (const char* var = std::getenv("TVM_LOG_DEBUG")) { - std::string var_str(var); - if (var_str == "1" || var_str.rfind("1;", 0) == 0) { - // Enabled, either without or with an additional VLOG specification. - state = 1; - } else { - // Not enabled. - state = -1; - } - } else { - // by default hide debug logging. + if (TvmLogDebugSpec().empty()) { + // Not enabled. state = -1; + } else { + // At least one VLOG entry (possibly just '*'=-1), so DLOG enabled. + state = 1; } } return state == 1; } -/*! \brief Helpers for \p VerboseLoggingEnabled. Exposed for unit testing only. */ -std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec); -bool VerboseEnabledInMap(const std::string& filename, int level, - const std::unordered_map& map); - /*! * \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. @@ -430,15 +441,19 @@ bool VerboseEnabledInMap(const std::string& filename, int level, * * 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="1;relay/foo.cc=2;ir/bar.cc=0;" + * 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="1;*=2;ir/bar.cc=-1;" + * TVM_LOG_DEBUG="*=2;ir/bar.cc=-1;" * \endcode + * + * Any of these settings will also enable DLOG statements. */ -bool VerboseLoggingEnabled(const char* filename, int level); +inline bool VerboseLoggingEnabled(const char* opt_filename, int level) { + return opt_filename != nullptr && VerboseEnabledInMap(opt_filename, level, TvmLogDebugSpec()); +} /*! * \brief A stack of VLOG context messages. diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 5d4c6b193f5b..0c7c9f6fa364 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -167,72 +167,70 @@ namespace tvm { namespace runtime { namespace detail { +// Parse \p opt_spec as a VLOG specification as per comment in +// DebugLoggingEnabled and VerboseLoggingEnabled. std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) { - // Cache the verbosity level map. std::unordered_map map; - LOG(INFO) << "initializing VLOG map"; if (opt_spec == nullptr) { - LOG(INFO) << "VLOG disabled, no TVM_LOG_DEBUG environment variable"; + // DLOG and VLOG disabled. return map; } std::string spec(opt_spec); - // Check we are enabled overall with at least one VLOG option. - if (spec.rfind("1;", 0) != 0) { - LOG(INFO) << "VLOG disabled, TVM_LOG_DEBUG does not start with '1;'"; + if (spec.empty() || spec == "0") { + // DLOG and VLOG disabled. return map; } - size_t start = 2UL; - while (start < spec.size()) { - // We are looking for "name=level;" or "*=level;" - size_t end = start; - // Scan up to '='. - while (spec[end] != '=') { - ++end; - if (end >= spec.size()) { - LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing '='"; - return map; - } - } - if (end == start) { - LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty name"; + if (spec == "1") { + // Legacy specification for enabling just DLOG. + // A wildcard entry in the map will signal DLOG is on, but all VLOG levels are disabled. + LOG(INFO) << "TVM_LOG_DEBUG enables DLOG statements only"; + map.emplace("*", -1); + return map; + } + std::istringstream spec_stream(spec); + for (std::string entry; std::getline(spec_stream, entry, ';'); /* no-op */) { + if (entry.empty()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty entry"; return map; } - std::string name(spec.substr(start, end - start)); - // Skip '=' - ++end; - if (end >= spec.size()) { - LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing level"; + std::istringstream entry_stream(entry); + std::string name; + if (!std::getline(entry_stream, name, '=')) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing '='"; return map; } - // Scan up to ';'. - start = end; - while (spec[end] != ';') { - ++end; - if (end >= spec.size()) { - LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing ';'"; - return map; - } + if (name.empty()) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty name"; + return map; } - if (end == start) { + std::string level; + entry_stream >> level; + if (level.empty()) { LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty level"; return map; } - std::string level_str(spec.substr(start, end - start)); - // Skip ';'. - ++end; // Parse level, default to 0 if ill-formed which we don't detect. char* end_of_level = nullptr; - int level = static_cast(strtol(level_str.c_str(), &end_of_level, 10)); - if (end_of_level != level_str.c_str() + level_str.size()) { + 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"; } - LOG(INFO) << "adding VLOG entry for '" << name << "' at level " << level; - map.emplace(name, level); - start = end; + if (map.empty()) { + LOG(INFO) << "TVM_LOG_DEBUG enables DLOG statements"; + } + LOG(INFO) << "TVM_LOG_DEBUG enables VLOG statements in '" << name << "' up to level " << level; + map.emplace(name, level_val); } return map; } +const std::unordered_map& TvmLogDebugSpec() { + // Parse and cache the verbosity level map. + const auto* map = + new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); + return *map; +} + constexpr const char* kSrcPrefix = "/src/"; constexpr const size_t kSrcPrefixLength = 5; @@ -263,16 +261,6 @@ bool VerboseEnabledInMap(const std::string& filename, int level, return false; } -bool VerboseLoggingEnabled(const char* filename, int level) { - // Cache the verbosity level map. - static const std::unordered_map* map = - new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); - if (filename == nullptr) { - return false; - } - return VerboseEnabledInMap(filename, level, *map); -} - LogFatal::Entry& LogFatal::GetEntry() { static thread_local LogFatal::Entry result; return result; diff --git a/tests/cpp/runtime/logging_test.cc b/tests/cpp/runtime/logging_test.cc index 40dc78d1ae9c..f232eddd842f 100644 --- a/tests/cpp/runtime/logging_test.cc +++ b/tests/cpp/runtime/logging_test.cc @@ -26,21 +26,19 @@ namespace detail { namespace { TEST(ParseTvmLogDebugSpec, Disabled) { - auto map = ParseTvmLogDebugSpec(nullptr); - EXPECT_EQ(map.size(), 0); - - map = ParseTvmLogDebugSpec(""); - EXPECT_EQ(map.size(), 0); - - map = ParseTvmLogDebugSpec("0"); - EXPECT_EQ(map.size(), 0); + EXPECT_TRUE(ParseTvmLogDebugSpec(nullptr).empty()); + EXPECT_TRUE(ParseTvmLogDebugSpec("").empty()); + EXPECT_TRUE(ParseTvmLogDebugSpec("0").empty()); +} - map = ParseTvmLogDebugSpec("1"); - EXPECT_EQ(map.size(), 0); +TEST(ParseTvmLogDebugSpec, DlogOnly) { + auto map = ParseTvmLogDebugSpec("1"); + EXPECT_EQ(map.size(), 1); + EXPECT_EQ(map["*"], -1); } -TEST(ParseTvmLogDebugSpec, SomeEnabled) { - auto map = ParseTvmLogDebugSpec("1;foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); +TEST(ParseTvmLogDebugSpec, VLogEnabled) { + auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4"); EXPECT_EQ(map.size(), 4); EXPECT_EQ(map["*"], 2); @@ -50,11 +48,11 @@ TEST(ParseTvmLogDebugSpec, SomeEnabled) { } TEST(ParseTvmLogDebugSpec, IllFormed) { - EXPECT_THROW(ParseTvmLogDebugSpec("1;foo/bar.cc=bogus;"), InternalError); + EXPECT_THROW(ParseTvmLogDebugSpec("foo/bar.cc=bogus;"), InternalError); } TEST(VerboseEnabledInMap, Lookup) { - auto map = ParseTvmLogDebugSpec("1;foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); + auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 3, map)); EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 4, map)); From fdf61c06d1a4ebb30054aada746271a040cb1fac Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Thu, 16 Sep 2021 15:53:31 -0700 Subject: [PATCH 08/12] [checkpoint] woops, forgot the static modifier on map --- src/runtime/logging.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 0c7c9f6fa364..4d70dbd47b61 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -226,7 +226,7 @@ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) const std::unordered_map& TvmLogDebugSpec() { // Parse and cache the verbosity level map. - const auto* map = + static const auto* map = new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); return *map; } From 09a172286c8152b7c9d9db8ffcf7dd70a5badee7 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Fri, 17 Sep 2021 16:06:08 -0700 Subject: [PATCH 09/12] [checkpoint] * -> DEFAULT for wildcard. Andrew pointed out *=9 suggests foo/*.cc=9 would work but it is not supported. --- include/tvm/runtime/logging.h | 6 ++--- src/runtime/logging.cc | 37 +++++++++++++++++-------------- tests/cpp/runtime/logging_test.cc | 18 +++++++++------ 3 files changed, 34 insertions(+), 27 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 8f25e290e6a4..0bdf816e74ab 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -441,12 +441,12 @@ inline bool DebugLoggingEnabled() { * * 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;" + * 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="*=2;ir/bar.cc=-1;" + * TVM_LOG_DEBUG="DEFAULT=2;ir/bar.cc=-1" * \endcode * * Any of these settings will also enable DLOG statements. @@ -574,7 +574,7 @@ TVM_CHECK_FUNC(_NE, !=) /*! * \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 as their prefix to help with debugging. E.g.: + * 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"; diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 4d70dbd47b61..363bed3871de 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -167,6 +167,12 @@ namespace tvm { namespace runtime { namespace detail { +namespace { +constexpr const char* kSrcPrefix = "/src/"; +constexpr const size_t kSrcPrefixLength = 5; +constexpr const char* kDefaultKeyword = "DEFAULT"; +} // namespace + // Parse \p opt_spec as a VLOG specification as per comment in // DebugLoggingEnabled and VerboseLoggingEnabled. std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) { @@ -184,27 +190,26 @@ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) // Legacy specification for enabling just DLOG. // A wildcard entry in the map will signal DLOG is on, but all VLOG levels are disabled. LOG(INFO) << "TVM_LOG_DEBUG enables DLOG statements only"; - map.emplace("*", -1); + map.emplace(kDefaultKeyword, -1); return map; } std::istringstream spec_stream(spec); - for (std::string entry; std::getline(spec_stream, entry, ';'); /* no-op */) { - if (entry.empty()) { - LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty entry"; - return map; - } - std::istringstream entry_stream(entry); + while (spec_stream) { std::string name; - if (!std::getline(entry_stream, name, '=')) { - LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, missing '='"; - return map; + if (!std::getline(spec_stream, name, '=')) { + // Reached end. + break; } if (name.empty()) { LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty name"; return map; } + std::string level; - entry_stream >> level; + if (!std::getline(spec_stream, level, ';')) { + LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, expecting level"; + return map; + } if (level.empty()) { LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty level"; return map; @@ -214,6 +219,7 @@ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) 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 map; } if (map.empty()) { LOG(INFO) << "TVM_LOG_DEBUG enables DLOG statements"; @@ -231,9 +237,6 @@ const std::unordered_map& TvmLogDebugSpec() { return *map; } -constexpr const char* kSrcPrefix = "/src/"; -constexpr const size_t kSrcPrefixLength = 5; - bool VerboseEnabledInMap(const std::string& filename, int level, const std::unordered_map& map) { if (level < 0) { @@ -248,13 +251,13 @@ bool VerboseEnabledInMap(const std::string& filename, int level, // canonicalization. std::string key = last_src == std::string::npos ? filename : filename.substr(last_src + kSrcPrefixLength); - // Check for exact. + // Check for exact match. auto itr = map.find(key); if (itr != map.end()) { return level <= itr->second; } - // Check for '*' wildcard. - itr = map.find("*"); + // Check for default. + itr = map.find(kDefaultKeyword); if (itr != map.end()) { return level <= itr->second; } diff --git a/tests/cpp/runtime/logging_test.cc b/tests/cpp/runtime/logging_test.cc index f232eddd842f..ad110cd445e8 100644 --- a/tests/cpp/runtime/logging_test.cc +++ b/tests/cpp/runtime/logging_test.cc @@ -34,14 +34,19 @@ TEST(ParseTvmLogDebugSpec, Disabled) { TEST(ParseTvmLogDebugSpec, DlogOnly) { auto map = ParseTvmLogDebugSpec("1"); EXPECT_EQ(map.size(), 1); - EXPECT_EQ(map["*"], -1); + EXPECT_EQ(map["DEFAULT"], -1); } -TEST(ParseTvmLogDebugSpec, VLogEnabled) { - auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4"); - EXPECT_EQ(map.size(), 4); +TEST(ParseTvmLogDebugSpec, VLogEnabledDefault) { + auto map = ParseTvmLogDebugSpec("DEFAULT=3"); + EXPECT_EQ(map.size(), 1); + EXPECT_EQ(map["DEFAULT"], 3); +} - EXPECT_EQ(map["*"], 2); +TEST(ParseTvmLogDebugSpec, VLogEnabledComplex) { + auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;DEFAULT=2;another/file.cc=4"); + EXPECT_EQ(map.size(), 4); + EXPECT_EQ(map["DEFAULT"], 2); EXPECT_EQ(map["foo/bar.cc"], 3); EXPECT_EQ(map["baz.cc"], -1); EXPECT_EQ(map["another/file.cc"], 4); @@ -52,8 +57,7 @@ TEST(ParseTvmLogDebugSpec, IllFormed) { } TEST(VerboseEnabledInMap, Lookup) { - auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;*=2;another/file.cc=4;"); - + auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;DEFAULT=2;another/file.cc=4;"); EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 3, map)); EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 4, map)); EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/other.cc", 2, map)); From 0a90d405bc66e0af252186a1afe0edf8d6218aca Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Sat, 18 Sep 2021 09:33:33 -0700 Subject: [PATCH 10/12] [checkpoint] constexpr length --- include/tvm/runtime/logging.h | 2 +- src/runtime/logging.cc | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 0bdf816e74ab..1e4ab4bd85fd 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -434,7 +434,7 @@ inline bool DebugLoggingEnabled() { /*! * \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. + * 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/). diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 363bed3871de..950d417053ec 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -169,7 +169,7 @@ namespace detail { namespace { constexpr const char* kSrcPrefix = "/src/"; -constexpr const size_t kSrcPrefixLength = 5; +constexpr const size_t kSrcPrefixLength = std::char_traits::length(kSrcPrefix); constexpr const char* kDefaultKeyword = "DEFAULT"; } // namespace From e59321e8d4e6983102290576d4b3e719e5781733 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Sat, 18 Sep 2021 11:01:37 -0700 Subject: [PATCH 11/12] [checkpoint] length is not constexpr on all targets, reverting --- src/runtime/logging.cc | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 950d417053ec..4cb8179352b0 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -169,7 +169,9 @@ namespace detail { namespace { constexpr const char* kSrcPrefix = "/src/"; -constexpr const size_t kSrcPrefixLength = std::char_traits::length(kSrcPrefix); +// 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 From bf088b96de3bd137a025ee1f7fc20437133a9564 Mon Sep 17 00:00:00 2001 From: Mark Shields Date: Mon, 20 Sep 2021 16:08:29 -0700 Subject: [PATCH 12/12] [checkpoint] minimize VLOG overhead when in legacy DLOG-only mode --- include/tvm/runtime/logging.h | 69 +++++++++++++++++++++---------- src/runtime/logging.cc | 56 +++++++++---------------- tests/cpp/runtime/logging_test.cc | 57 +++++++++++++------------ 3 files changed, 95 insertions(+), 87 deletions(-) diff --git a/include/tvm/runtime/logging.h b/include/tvm/runtime/logging.h index 1e4ab4bd85fd..a951264b9706 100644 --- a/include/tvm/runtime/logging.h +++ b/include/tvm/runtime/logging.h @@ -395,19 +395,52 @@ class LogMessageVoidify { void operator&(std::ostream&) {} }; -// The following three methods are helpers for \p DebugLoggingEnabled and \p VerboseLoggingEnabled. -// They are public for unit testing only. - -// Parses \p opt_spec as per specification for \p TVM_LOG_DEBUG given by \p DebugLoggingEnabled -// and \p VerboseLoggingEnabled. The map is non-empty iff DLOG is enabled. The map has an -// entry for a specific file iff that file is mentioned in \p TVM_LOG_DEBUG. Tha map has a -// '*' wildcard entry iff \p TVM_LOG_DEBUG=1 or \p TVM_LOG_DEBUG has a wildcard entry. -std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec); -// As above, but using the actual \p TVM_LOG_DEBUG environment variable. -const std::unordered_map& TvmLogDebugSpec(); -// As for \p VerboseLoggingEnabled, but using given \p map. -bool VerboseEnabledInMap(const std::string& filename, int level, - const std::unordered_map& map); +/*! \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 @@ -421,13 +454,7 @@ bool VerboseEnabledInMap(const std::string& filename, int level, inline bool DebugLoggingEnabled() { static int state = 0; if (state == 0) { - if (TvmLogDebugSpec().empty()) { - // Not enabled. - state = -1; - } else { - // At least one VLOG entry (possibly just '*'=-1), so DLOG enabled. - state = 1; - } + state = TvmLogDebugSettings::FromFlag().dlog_enabled() ? 1 : -1; } return state == 1; } @@ -452,7 +479,7 @@ inline bool DebugLoggingEnabled() { * Any of these settings will also enable DLOG statements. */ inline bool VerboseLoggingEnabled(const char* opt_filename, int level) { - return opt_filename != nullptr && VerboseEnabledInMap(opt_filename, level, TvmLogDebugSpec()); + return TvmLogDebugSettings::FromFlag().VerboseEnabled(opt_filename, level); } /*! diff --git a/src/runtime/logging.cc b/src/runtime/logging.cc index 4cb8179352b0..9c193921f93b 100644 --- a/src/runtime/logging.cc +++ b/src/runtime/logging.cc @@ -175,25 +175,22 @@ constexpr const size_t kSrcPrefixLength = 5; constexpr const char* kDefaultKeyword = "DEFAULT"; } // namespace -// Parse \p opt_spec as a VLOG specification as per comment in -// DebugLoggingEnabled and VerboseLoggingEnabled. -std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) { - std::unordered_map map; +/* static */ +TvmLogDebugSettings TvmLogDebugSettings::ParseSpec(const char* opt_spec) { + TvmLogDebugSettings settings; if (opt_spec == nullptr) { // DLOG and VLOG disabled. - return map; + return settings; } std::string spec(opt_spec); if (spec.empty() || spec == "0") { // DLOG and VLOG disabled. - return map; + return settings; } + settings.dlog_enabled_ = true; if (spec == "1") { // Legacy specification for enabling just DLOG. - // A wildcard entry in the map will signal DLOG is on, but all VLOG levels are disabled. - LOG(INFO) << "TVM_LOG_DEBUG enables DLOG statements only"; - map.emplace(kDefaultKeyword, -1); - return map; + return settings; } std::istringstream spec_stream(spec); while (spec_stream) { @@ -204,49 +201,34 @@ std::unordered_map ParseTvmLogDebugSpec(const char* opt_spec) } if (name.empty()) { LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty name"; - return map; + return settings; } std::string level; if (!std::getline(spec_stream, level, ';')) { LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, expecting level"; - return map; + return settings; } if (level.empty()) { LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, empty level"; - return map; + 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 map; - } - if (map.empty()) { - LOG(INFO) << "TVM_LOG_DEBUG enables DLOG statements"; + return settings; } LOG(INFO) << "TVM_LOG_DEBUG enables VLOG statements in '" << name << "' up to level " << level; - map.emplace(name, level_val); + settings.vlog_level_map_.emplace(name, level_val); } - return map; -} - -const std::unordered_map& TvmLogDebugSpec() { - // Parse and cache the verbosity level map. - static const auto* map = - new std::unordered_map(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG"))); - return *map; + return settings; } -bool VerboseEnabledInMap(const std::string& filename, int level, - const std::unordered_map& map) { - if (level < 0) { - return false; - } - // Canonicalize filename. +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 @@ -254,13 +236,13 @@ bool VerboseEnabledInMap(const std::string& filename, int level, std::string key = last_src == std::string::npos ? filename : filename.substr(last_src + kSrcPrefixLength); // Check for exact match. - auto itr = map.find(key); - if (itr != map.end()) { + auto itr = vlog_level_map_.find(key); + if (itr != vlog_level_map_.end()) { return level <= itr->second; } // Check for default. - itr = map.find(kDefaultKeyword); - if (itr != map.end()) { + itr = vlog_level_map_.find(kDefaultKeyword); + if (itr != vlog_level_map_.end()) { return level <= itr->second; } return false; diff --git a/tests/cpp/runtime/logging_test.cc b/tests/cpp/runtime/logging_test.cc index ad110cd445e8..a4e6c01444e6 100644 --- a/tests/cpp/runtime/logging_test.cc +++ b/tests/cpp/runtime/logging_test.cc @@ -25,44 +25,43 @@ namespace runtime { namespace detail { namespace { -TEST(ParseTvmLogDebugSpec, Disabled) { - EXPECT_TRUE(ParseTvmLogDebugSpec(nullptr).empty()); - EXPECT_TRUE(ParseTvmLogDebugSpec("").empty()); - EXPECT_TRUE(ParseTvmLogDebugSpec("0").empty()); -} +TEST(TvmLogDebugSettings, Disabled) { + TvmLogDebugSettings settings = TvmLogDebugSettings::ParseSpec(nullptr); + EXPECT_FALSE(settings.dlog_enabled()); + + settings = TvmLogDebugSettings::ParseSpec(""); + EXPECT_FALSE(settings.dlog_enabled()); -TEST(ParseTvmLogDebugSpec, DlogOnly) { - auto map = ParseTvmLogDebugSpec("1"); - EXPECT_EQ(map.size(), 1); - EXPECT_EQ(map["DEFAULT"], -1); + settings = TvmLogDebugSettings::ParseSpec("0"); + EXPECT_FALSE(settings.dlog_enabled()); } -TEST(ParseTvmLogDebugSpec, VLogEnabledDefault) { - auto map = ParseTvmLogDebugSpec("DEFAULT=3"); - EXPECT_EQ(map.size(), 1); - EXPECT_EQ(map["DEFAULT"], 3); +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(ParseTvmLogDebugSpec, VLogEnabledComplex) { - auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;DEFAULT=2;another/file.cc=4"); - EXPECT_EQ(map.size(), 4); - EXPECT_EQ(map["DEFAULT"], 2); - EXPECT_EQ(map["foo/bar.cc"], 3); - EXPECT_EQ(map["baz.cc"], -1); - EXPECT_EQ(map["another/file.cc"], 4); +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(ParseTvmLogDebugSpec, IllFormed) { - EXPECT_THROW(ParseTvmLogDebugSpec("foo/bar.cc=bogus;"), InternalError); +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(VerboseEnabledInMap, Lookup) { - auto map = ParseTvmLogDebugSpec("foo/bar.cc=3;baz.cc=-1;DEFAULT=2;another/file.cc=4;"); - EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 3, map)); - EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/foo/bar.cc", 4, map)); - EXPECT_TRUE(VerboseEnabledInMap("my/filesystem/src/foo/other.cc", 2, map)); - EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/foo/other.cc", 3, map)); - EXPECT_FALSE(VerboseEnabledInMap("my/filesystem/src/baz.cc", 0, map)); +TEST(TvmLogDebugSettings, IllFormed) { + EXPECT_THROW(TvmLogDebugSettings::ParseSpec("foo/bar.cc=bogus;"), InternalError); } } // namespace