Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Relay] VLOG for finer grained control of hyper-detailed logging #9012

Merged
merged 12 commits into from
Sep 22, 2021

Conversation

mbs-octoml
Copy link
Contributor

@mbs-octoml mbs-octoml commented Sep 14, 2021

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 #8788 for use in the wild.

I noticed the DCHECK macros were disabled instead of 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.

Comment on lines 402 to 403
if (const char* var = std::getenv("TVM_LOG_DEBUG")) {
if (var[0] == '1') {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

According this logic there is no difference for TVM_LOG_DEBUG = 11 and TVM_LOG_DEBUG = 1, this seems like not make sense, could you help to give more information about why just check first digit here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was a lazy way to allow "1" or "1;...." to enable. I made it more specific.

@@ -409,6 +413,68 @@ inline bool DebugLoggingEnabled() {
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 char* filename, int level,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

here mixed used "std::string" and "char *", recommend to use std::string to match existing global function style that used string.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done. Note the original filename comes via a FILE so I left const char* for the main func.

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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the "\p" seems like not necessary.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm using that as a convention to quote parameters or code. Looks nicer in the formatted comments.

std::string str() const;

private:
std::vector<std::stringstream*> context_stack;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

context_stack_

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done , thx.

// Re-export error types
using runtime::Error;
using runtime::InternalError;

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no need this line.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

Comment on lines 244 to 246
size_t last_src = key.rfind("/src/", std::string::npos, 5);
if (last_src != std::string::npos) {
key = key.substr(last_src + 5);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

key can be filename or the string after last "/src/", why for some file the key can be file name and other can not ?

for the file /abc/src/foo.cc and /def/src/foo.cc, the key will be same , is it intend logic?

should avoid hardcode logic that use 5 directly

const char * src = "/src/";
size_t src_len = strlen(src);
size_t last_src = key.rfind(src, std::string::npos, src_len);
....
   key = key.substr(last_src + src_len);

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done for code cleanup. Just wanted to gracefully fallback if the filename for some reason is outside of the /src/ root. Could LOG(FATAL) since it signals the user is trying to use VLOG in, say, include. wdyt?

Comment on lines 251 to 247
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;
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the duplicate map search seems like not efficient, why not do "*" search only when key not found?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes that was silly of me!

@huajsj
Copy link
Contributor

huajsj commented Sep 14, 2021

thanks @mbs-octoml.

@mbs-octoml
Copy link
Contributor Author

@huajsj thanks for the quick review, PTAL.

Comment on lines -578 to +589
file(GLOB TEST_SRCS tests/cpp/*.cc)
file(GLOB_RECURSE TEST_SRCS tests/cpp/*.cc)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why changed from GLOB into GLOB_RECURSE?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because i'm adding a unit test under runtime/, paving the way for adding more c++ unit tests in a directory structure that mirrors src/.

Comment on lines 136 to 137
* // (default behaviour)
* COND_CHECK_EQ(quit_on_assertion, a, b) << "some error message when quiting"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

136 and 137 should be same line.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok, but that will have to be for another cl unless ci fails :-|

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@@ -395,10 +399,13 @@ 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")) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

seems like change not necessary, should keep no change "auto var = std::getenv("TVM_LOG_DEBUG")"

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't have a consistent style on auto, but generally I spell out the types except for auto x = make_object(...), auto f = ... {...}, and iterators.

if (std::string(var) == "1") {
if (const char* var = std::getenv("TVM_LOG_DEBUG")) {
std::string var_str(var);
if (var_str == "1" || var_str.rfind("1;", 0) == 0) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

seems like there are multiple type information get put into TVM_LOG_DEBUG, this would make the use of such environment variable become trivial and complicated, please avoid such usage.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will address in your comment below.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

var_str.find ?

Comment on lines 433 to 438
* 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;"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This usage looks like not user friendly, is there any other better way to do this? for example
TVM_LOG_DEBUG_LEVEL_2="relay/foo.cc;"
TVM_LOG_DEBUG_LEVEL_0="ir/bar.cc;"

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are many possible designs. I settled on re-using the existing TWM_LOG_DEBUG since

  • it is one control surface
  • I often modules on and off during debugging and having one var to redefine makes that easy

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

According the logic, TVM_LOG_DEBUG now have a hiding strict format assumptions, these setting like "=2;1;" or "=2;1", "*=1;" will be illegal, I don't see any necessary here to introduce such complexity for environment variable content.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I definitely agree with you the ergonomics are horrible! Using an env variable at all is already unfortunate but forced on us by the python-is-the-driver convention for TVM. But I think this is all very temporary and 'for developers only' while we figure out a more structured approach to controlling, capturing and redirecting logging, including both 'for debug' logging as well as logging which may be relevant to downstream customers running tvm in a production environment.
(+ @jroesch since we were chatting about this today).

At this point the CI is green -- do you feel strongly enough we should not proceed as is?

Copy link
Contributor

@huajsj huajsj Sep 16, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we agree that is a problem , that sound not make sense not to fix it, and better to avoid a temporary solution that in some case will become a permanent solution, as a user for this VLOG feature, I like the idea filtering in file level, but I think such configuration method is unnecessary complicated and error-prone, if we can better to find a more easy to use method.
about CI is green, I can understand the CI consume time, to get it become green not very easy, but from my point view we should better to more focus on code logic instead of CI.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks @areusch, @mbs-octoml for the follow up, that make sense.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Along the same line as 'we have many frontends' I'm also trying to support writing C++ unit tests, and obviously being able to control logging for any test is vital. So any python-only control surface would not work for that case.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As far as syntax is concerned:

  • obviously the legacy TVM_LOG_DEBUG=1 behavior must be kept. Tat will turn on DLOG but leave the implied default VLOG levels for all files as -1.
  • but for finer control the '1' start seems to be throwing folks off, so I'll drop that. Eg
    TVM_LOG_DEBUG="foo/bar.cc=3" means enable DLOG and VLOG for that file at levels 0 to 3.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mbs-octoml does that mean there's no way to do global + per-file at once?

Copy link
Contributor

@areusch areusch Sep 17, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok i see. i'm okay with this change if you also print a warning or just FATAL when someone tries to do src/*.cc=3

Comment on lines 268 to 269
static const std::unordered_map<std::string, int>* map =
new std::unordered_map<std::string, int>(ParseTvmLogDebugSpec(std::getenv("TVM_LOG_DEBUG")));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

recommend to use smart pointer.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the idiom for statically initialized aggregate structures. Since they can never be freed they go in 'raw' pointers.

* 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:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe a little confusing to say 2 here but then have TVM_LOG_DEBUG="1 below

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, looks like I'm going to go through CI again so let's get this at least better if not perfect. See above mega-comment.

Comment on lines 433 to 438
* 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;"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@huajsj i agree this is a bit more complex, but it is backwards-compatible. i also don't think it's especially complex given what it does.

it seems like a more structured, frontend-agnostic interface might be a PackedFunc like:

TVM_REGISTER_GLOBAL("set_vlog_level").set_body_typed([](const std::string& file_name, int level) {
  my_global_map[file_name] = level
}

I'm totally open to adding this. However, I'd like to point out a couple of advantages of the environment variable route @mbs-octoml proposes here.

  • use of a single variable or config string: it's very easy to determine exactly the VLOG configuration of TVM. you just echo ${TVM_LOG_DEBUG}. if multiple variables are used, the command becomes more complex: export | grep TVM_LOG_DEBUG_LEVEL_
  • use of environment variable: We make heavy use of multiprocessing or PopenPool, and have many different frontends. i'd argue that VLOG level configuration is a TVM developer-facing interface. If we use a command-line flag or script to configure logging, then every time a program is launched with a different entry point, a parser would need to be written to convert some command-line flag into a set of get_function("set_vlog_level")(file_name, level) calls. Each script may have a different way to parse out the various vlog levels, so if a TVM C++ developer is trying to help a user debug a problem in libtvm.so, they first would need to determine how to configure TVM VLOG levels. TVM_LOG_DEBUG is a more foolproof route. Additionally, we would need to find a way to thread this down through multiprocessing/PopenPool so that this configuration is propagated to e.g. autotuning Builder/Runner.

I agree with your point that temporary solutions can tend to become permanent. In this case I'd argue that the complex part of this PR is in parsing the environment variable and not in the change to the logging system. Given the advantages listed above, I think I'd still want to keep this functionality even if we overhaul the fundamental way logging works here. I also don't think this mechanism has to be kept particularly backwards-compatible--we can continue to improve it as we consider bigger changes to logging. What do you think?

if (std::string(var) == "1") {
if (const char* var = std::getenv("TVM_LOG_DEBUG")) {
std::string var_str(var);
if (var_str == "1" || var_str.rfind("1;", 0) == 0) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

var_str.find ?

}
std::string spec(opt_spec);
// Check we are enabled overall with at least one VLOG option.
if (spec.rfind("1;", 0) != 0) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

spec.find ? is there any reason here use rfind instead of find ?

if (spec == "1" || spec.find("1;") != 0)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's the idiom for checking a string begins with a prefix. It won't waste time looking though the whole string, just check the first 3 chars.

LOG(INFO) << "VLOG disabled, TVM_LOG_DEBUG does not start with '1;'";
return map;
}
size_t start = 2UL;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the hardcode 2UL not readable, how about use

const char *str_enable = "1;";
//use str_enable for whether debug enable check.
size_t start = strlen(str_enable);

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done - this is going to be rejigged anyway.

Comment on lines 185 to 225
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<int>(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;
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

recommend to use istringstream, just a example.

std::istringstream istr(spec.substr(strlen(str_enable)));
std::string str;
while(getline(istr, str, ';')){
        istringstream istr_file(str);
        string file, level;
        if (!getline(istr_file, file, '=')){
            break;
        }
        if (!getline(istr_file, level, '=')) {
            break;
        }
        map.emplace(file, level);
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, that is nicer. Not quite the same behavior but better than index hacking. I'm a little worried this might be too onerous for the runtimes but let's see what CI says.

@mbs-octoml
Copy link
Contributor Author

PTAL.

@mbs-octoml
Copy link
Contributor Author

@huajsj @areusch PTAL, and CI is green :-)

Comment on lines 174 to 189
if (opt_spec == nullptr) {
// DLOG and VLOG disabled.
return map;
}
std::string spec(opt_spec);
if (spec.empty() || spec == "0") {
// DLOG and VLOG disabled.
return map;
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

std::string spec(opt_spec);
if (opt_spec == nullptr || spec.emptry() || spec == "0"){
// DLOG and VLOG disabled.
return map;
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

avoiding undefined string over nullptr

@@ -166,10 +167,118 @@ namespace tvm {
namespace runtime {
namespace detail {

namespace {
constexpr const char* kSrcPrefix = "/src/";
constexpr const size_t kSrcPrefixLength = 5;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

constexpr size_t kSrcPrefixLength = std::char_traits<const char>::length(kSrcPrefix);

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's a good trick, thx.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Alas it fails on the i386 compilation CI flow, reverted.

Comment on lines 218 to 223
char* end_of_level = nullptr;
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";
return map;
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

recommend to use c++ here to make code style consistent and more readable.

int level_val = std::stoi(level);
if (to_string(level_val) != level) {
  LOG(FATAL) << "TVM_LOG_DEBUG ill-formed, invalid level";
  return map;
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's good enough.


bool VerboseEnabledInMap(const std::string& filename, int level,
const std::unordered_map<std::string, int>& map) {
if (level < 0) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

seems like correct level start from 0 and negative level will no need check, could you add some comments to explain this logic?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added to VerboseLoggingEnabled comment.

// 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);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this logic seems like not backward compatible in performance. when spec == "1", VerboseEnabledInMap still need to do string parse and map search, that seems like not necessary, is there any specific concern here not just leave map be empty and return false in VerboseEnabledInMap when map.empty() is true?

Copy link
Contributor Author

@mbs-octoml mbs-octoml Sep 18, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Everything is gated on the TVM_LOG_DEBUG #define, signalling this is a developer build for the purposes of debugging. If this were on prod code paths then we'd need to do some very special tricks to cache the lookup per file.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TVM_LOG_DEBUG gate only can help for TVM_LOG_DEBUG not define or be 0 case, when #define TVM_LOG_DEBUG 1, and TVM_LOG_DEBUG="1", VerboseLoggingEnabled should directly return false instead of still doing filename parse and map search, I think that a normal check instead of special trick and doing correct check should also apply for debug build.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done.

Copy link
Contributor

@huajsj huajsj left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, Thanks @mbs-octoml.

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 apache#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.
Gotta get my docker setup going
Andrew pointed out *=9 suggests foo/*.cc=9 would work but it is not supported.
@areusch areusch merged commit 3fbce70 into apache:main Sep 22, 2021
@areusch
Copy link
Contributor

areusch commented Sep 22, 2021

thanks @mbs-octoml @huajsj the PR is now merged!

@mbs-octoml mbs-octoml deleted the mbs-vlog branch September 22, 2021 19:13
ylc pushed a commit to ylc/tvm that referenced this pull request Sep 29, 2021
…che#9012)

* [Relay] VLOG for finer grained control of hyper-detailed logging

I've been making very heavy use of DLOG and PrettyPrint to trace, understand and
debug Relay transforms. I've found myself deleting log statements to reduce the
output verbosity, only to have to re-add them a few days later. Better would be to
support leaving all those statements in place but have finer control over when they
are enabled.

This PR introduces a 'VLOG(level)' macro to that end. The log is ignored
unless TVM_LOG_DEBUG is enabled (both as #define and an environment var), and the
the current verbosity level is >= level. The current verbosity level can be set
globally and/or overridden per source file (see 'VerboseLoggingEnabled').

(Those familiar with the origin of the LOG and DLOG family will also recognize VLOG.)

I also introduce a 'VLOG_CONTEXT' macro which pushes a string onto an internal
per-thread stack. Each VLOG message includes that stack as its prefix, which is a
very handy way to keep track of the (often recursive) program context in which each
VLOG is executed.

I've rejigged some existing DLOGs to VLOGs to illustrate, but left most of them
alone for now.  See the draft apache#8788 for use in the
wild.

I noticed the DCHECK macros *disabled* instead enabled with TVM_LOG_DEBUG defined, so
fixed that.

I've also made changes to the Relay text printer to dump attributes in a human
readable format rather than the indirect but machine readable 'meta' representation.
This is gated by the show_meta_data_ flag, and I think this use is consistent with it's
original purpose.

* [checkpoint] lints

* [checkpoint] missing \n lint

Gotta get my docker setup going

* [checkpoint] woops, we don't support gmock.h

* [checkpoint] Address Hua Jiang's comments.

* [checkpoint] strlen not avail on all toolchains?

* [checkpoint] Rework TVM_LOG_DEBUG spec and parser

* [checkpoint] woops, forgot the static modifier on map

* [checkpoint] * -> DEFAULT for wildcard.

Andrew pointed out *=9 suggests foo/*.cc=9 would work but it is not supported.

* [checkpoint] constexpr length

* [checkpoint] length is not constexpr on all targets, reverting

* [checkpoint] minimize VLOG overhead when in legacy DLOG-only mode
@linlifan
Copy link

it seems like after this commit , IR print under TVM_LOG_DEBUG=1 control is gone again...... i think many people are relying on it to debug performance variations, better there are some DOC to explain , how to enable it back

@mbs-octoml
Copy link
Contributor Author

@linlifan you're quite right, sorry. #9278.

ylc pushed a commit to ylc/tvm that referenced this pull request Jan 13, 2022
…che#9012)

* [Relay] VLOG for finer grained control of hyper-detailed logging

I've been making very heavy use of DLOG and PrettyPrint to trace, understand and
debug Relay transforms. I've found myself deleting log statements to reduce the
output verbosity, only to have to re-add them a few days later. Better would be to
support leaving all those statements in place but have finer control over when they
are enabled.

This PR introduces a 'VLOG(level)' macro to that end. The log is ignored
unless TVM_LOG_DEBUG is enabled (both as #define and an environment var), and the
the current verbosity level is >= level. The current verbosity level can be set
globally and/or overridden per source file (see 'VerboseLoggingEnabled').

(Those familiar with the origin of the LOG and DLOG family will also recognize VLOG.)

I also introduce a 'VLOG_CONTEXT' macro which pushes a string onto an internal
per-thread stack. Each VLOG message includes that stack as its prefix, which is a
very handy way to keep track of the (often recursive) program context in which each
VLOG is executed.

I've rejigged some existing DLOGs to VLOGs to illustrate, but left most of them
alone for now.  See the draft apache#8788 for use in the
wild.

I noticed the DCHECK macros *disabled* instead enabled with TVM_LOG_DEBUG defined, so
fixed that.

I've also made changes to the Relay text printer to dump attributes in a human
readable format rather than the indirect but machine readable 'meta' representation.
This is gated by the show_meta_data_ flag, and I think this use is consistent with it's
original purpose.

* [checkpoint] lints

* [checkpoint] missing \n lint

Gotta get my docker setup going

* [checkpoint] woops, we don't support gmock.h

* [checkpoint] Address Hua Jiang's comments.

* [checkpoint] strlen not avail on all toolchains?

* [checkpoint] Rework TVM_LOG_DEBUG spec and parser

* [checkpoint] woops, forgot the static modifier on map

* [checkpoint] * -> DEFAULT for wildcard.

Andrew pointed out *=9 suggests foo/*.cc=9 would work but it is not supported.

* [checkpoint] constexpr length

* [checkpoint] length is not constexpr on all targets, reverting

* [checkpoint] minimize VLOG overhead when in legacy DLOG-only mode
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants