This is an archive of the discontinued LLVM Phabricator instance.

[ORC-RT] Add debug logging macros.
ClosedPublic

Authored by lhames on Dec 21 2021, 7:05 PM.

Details

Summary

Inspired by LLVM_DEBUG, but using environment variables rather than command line
options.

Code can use ORC_RT_DEBUG(...) (if ORC_RT_DEBUG_TYPE is set), or
ORC_RT_DEBUG_WITH_TYPE(<type>, ...) (if ORC_RT_DEBUG_TYPE is not set. E.g. in
headers).

Debug logging is enabled in the executor by setting the ORC_RT_DEBUG environment
variable. Debug logging can be restricted by type by setting the
ORC_RT_DEBUG_TYPES environment variable to a comma separated list of types,
e.g. ORC_RT_DEBUG_TYPES=macho_platform,sps.

Diff Detail

Event Timeline

lhames created this revision.Dec 21 2021, 7:05 PM
lhames requested review of this revision.Dec 21 2021, 7:05 PM
Herald added a project: Restricted Project. · View Herald TranscriptDec 21 2021, 7:05 PM
Herald added a subscriber: Restricted Project. · View Herald Transcript

This doesn't address _how_ we'd log, just how we'd enable/disable logging expressions.

In my out-of-tree tests I've just been using fprintf, but it may make sense to add a debugging-specific output API along the lines of llvm::dbgs(). The key constraint we're working under is that since this will be used _by_ the platform support classes it can't rely on any non-trivial global constructors/destructors.

benlangmuir added inline comments.Dec 22 2021, 9:59 AM
compiler-rt/lib/orc/debug.cpp
28

I'm not familiar with the history of -debug vs. -debug-only. What's the reason for not just basing this on a single value -- is ORC_RT_DEBUG_TYPES empty or not?

49

This could be an assert instead of a condition.

compiler-rt/lib/orc/debug.h
33

If we really need to initialize it here, we could skip the second atomic load in the common case that it's already initialized

auto State = ::__orc_rt::DebugState.load(memory_order_acquire);
if (State == DebugStates::Uninitialized) {
  initializeDebug();
  State = ::__orc_rt::DebugState.load(memory_order_relaxed);
}
if (State == DebugStates::Enabled && ...

Or to improve code size, initialize DebugState to Enabled and put a std::call_once in isCurrentDebugType to actually initialize it the first time.

We could also get away with load(memory_order_acquire) here instead of the default sequentially consistent. Or perhaps even load(memory_order_relaxed) if we're willing to accept a stale value of DebugTypes if there's contention during initialization.

benlangmuir added inline comments.Dec 22 2021, 10:04 AM
compiler-rt/lib/orc/debug.h
36

X needs to be in {} or it could have a dangling else

lhames added inline comments.Dec 23 2021, 1:55 AM
compiler-rt/lib/orc/debug.cpp
28

Using the empty-string feels counter-intuitive -- I think people are going to write:
ORC_RT_DEBUG=1 and get confused when it doesn't print anything.

What if we reserve '1', 'true', 'on', or 'all' for "log everything"?

compiler-rt/lib/orc/debug.h
33

It's a debug macro and the ORC runtime isn't likely to contain any too-hot code. I guess one think that we need to watch out for is the possibility that relying on sequential consistency for logging checks might obscure ordering bugs?

benlangmuir added inline comments.Dec 23 2021, 11:43 AM
compiler-rt/lib/orc/debug.cpp
28

I think people are going to write: ORC_RT_DEBUG=1 and get confused when it doesn't print anything.

This the status quo for both this patch and the -debug flag in llvm though. It's already confusing that you need to set two independent things to get any output. That's why I was wondering if we should just check ORC_RT_DEBUG_TYPES (the _TYPES one), which I think makes it clearer that it's not just a boolean flag. But if there's some good reason to keep them separate, that's fine with me too, I was mostly curious why we have this two-part configuration.

compiler-rt/lib/orc/debug.h
33

Okay, I'm not going to try to hold this patch up over this, but I would suggest at least refactoring to only do a single atomic load in the common case that you've already done the initialization, and preferably using acquire or relaxed ordering.

I guess one think that we need to watch out for is the possibility that relying on sequential consistency for logging checks might obscure ordering bugs?

I suspect the slowness of the logging itself would be a bigger issue for reproducibility of bugs unless you're running under tsan. Or are you thinking of when logging is disabled?

lhames updated this revision to Diff 396245.Dec 26 2021, 4:55 PM

Use relaxed memory order.

Merge ORC_RT_DEBUG_TYPES functionality into the ORC_RT_DEBUG environment
variable: the empty string or '1' will be interpreted as "log everything",
otherwise the string will be interpreted as a comma-separated list of types
to log.

Add a printdbg function with printf-like behavior. Currently equivalent to
fprintf(stderr, format, ...), this is intended to make it easy to find and
replace the logging calls if/when we update the logging mechanism.

lhames marked 2 inline comments as done.Dec 26 2021, 5:02 PM
lhames added inline comments.
compiler-rt/lib/orc/debug.h
33

I was thinking when logging is disabled, which will be common during development. My thought was that maybe this would matter if we ever wanted to try turning on logging in release mode to find a bug. It's too early to worry about that though -- it's not clear if/when we'll ever need that, nor how much this would help.

That said, I've switched to relaxed everywhere because it doesn't seem like it should hurt: repeated initialize calls will always write the same values, so at worst we'll duplicate some work on multiple threads at initialization time.

lhames updated this revision to Diff 396246.Dec 26 2021, 5:08 PM

clang-format, remove unnecessary 'extern "C"'.

Handling "" as enabling all logging is a bit strange to me -- what was the reasoning for that? LGTM other than than the return value from initializeDebug that I mentioned.

compiler-rt/lib/orc/debug.cpp
42

Should return &DebugTypesNone, I think.

This revision was not accepted when it landed; it landed in state Needs Review.Jan 7 2022, 10:28 PM
This revision was landed with ongoing or failed builds.
This revision was automatically updated to reflect the committed changes.
lhames marked an inline comment as done.Jan 7 2022, 10:53 PM

Handling "" as enabling all logging is a bit strange to me -- what was the reasoning for that? LGTM other than than the return value from initializeDebug that I mentioned.

Defining ORC_RT_DEBUG to empty is an odd corner case. I don't know whether having it equivalent to "all" or "none" makes more sense. I've switched it to "none" for the commit, but no strong feelings either way.

Handling "" as enabling all logging is a bit strange to me -- what was the reasoning for that? LGTM other than than the return value from initializeDebug that I mentioned.

Defining ORC_RT_DEBUG to empty is an odd corner case. I don't know whether having it equivalent to "all" or "none" makes more sense. I've switched it to "none" for the commit, but no strong feelings either way.

FWIW, I think empty should match "none" (the new behaviour after the update). In shell scripts, unset and empty are often used interchangeably (e.g., using [ -z "$VAR" ] rather than spelling out [ -z "${VAR:-}" ]).