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