Skip to content

Commit

Permalink
[checkpoint] Rework TVM_LOG_DEBUG spec and parser
Browse files Browse the repository at this point in the history
  • Loading branch information
@mbs-octoml
mbs-octoml committed Sep 16, 2021
1 parent aedf15e commit 0771005
Show file tree
Hide file tree
Showing 3 changed files with 89 additions and 88 deletions.
59 changes: 37 additions & 22 deletions include/tvm/runtime/logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
* }
* }
Expand Down Expand Up @@ -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<std::string, int> ParseTvmLogDebugSpec(const char* opt_spec);
// As above, but using the actual \p TVM_LOG_DEBUG environment variable.
const std::unordered_map<std::string, int>& TvmLogDebugSpec();
// As for \p VerboseLoggingEnabled, but using given \p map.
bool VerboseEnabledInMap(const std::string& filename, int level,
const std::unordered_map<std::string, int>& 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<std::string, int> ParseTvmLogDebugSpec(const char* opt_spec);
bool VerboseEnabledInMap(const std::string& filename, int level,
const std::unordered_map<std::string, int>& 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.
Expand All @@ -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.
Expand Down
92 changes: 40 additions & 52 deletions src/runtime/logging.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<std::string, int> ParseTvmLogDebugSpec(const char* opt_spec) {
// Cache the verbosity level map.
std::unordered_map<std::string, int> 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<int>(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<int>(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<std::string, int>& TvmLogDebugSpec() {
// Parse and cache the verbosity level map.
const auto* map =
new std::unordered_map<std::string, int>(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG")));
return *map;
}

constexpr const char* kSrcPrefix = "/src/";
constexpr const size_t kSrcPrefixLength = 5;

Expand Down Expand Up @@ -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<std::string, int>* map =
new std::unordered_map<std::string, int>(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;
Expand Down
26 changes: 12 additions & 14 deletions tests/cpp/runtime/logging_test.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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));
Expand Down

0 comments on commit 0771005

Please sign in to comment.