[ORC-RT] Add debug logging macros.

[lhames]

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.

[lhames]

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]

compiler-rt/lib/orc/debug.cpp

29

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?

50

This could be an assert instead of a condition.

compiler-rt/lib/orc/debug.h

34

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]

compiler-rt/lib/orc/debug.h

37

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

[lhames]

compiler-rt/lib/orc/debug.cpp

29

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

34

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]

compiler-rt/lib/orc/debug.cpp

29

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

34

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]

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]

compiler-rt/lib/orc/debug.h

34

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]

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

[benlangmuir]

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

41

Should return &DebugTypesNone, I think.

[lhames]

In D116139#3220124, @benlangmuir wrote:

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.

[dexonsmith]

In D116139#3229089, @lhames wrote:

In D116139#3220124, @benlangmuir wrote:

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:-}" ]).

compiler-rt/lib/orc/CMakeLists.txt

 # Build for all components of the ORC runtime support library.
 
 # ORC runtime library implementation files.
 set(ORC_SOURCES
+  debug.cpp
   extensible_rtti.cpp
   log_error_to_stderr.cpp
   macho_ehframe_registration.cpp
   macho_platform.cpp
   elfnix_platform.cpp
   run_program_wrapper.cpp
   )
 

compiler-rt/lib/orc/debug.h

+//===- debug.h - Debugging output utilities ---------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+//
+// This file is a part of the ORC runtime support library.
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef ORC_RT_DEBUG_H
+#define ORC_RT_DEBUG_H
+
+#include <atomic>
+
+#ifndef NDEBUG
+
+namespace __orc_rt {
+
+extern std::atomic<const char *> DebugTypes;
+extern char DebugTypesAll;
+extern char DebugTypesNone;
+
+const char *initializeDebug();
+bool debugTypeEnabled(const char *Type, const char *Types);
+void printdbg(const char *format, ...);
+
+} // namespace __orc_rt
+
+#define ORC_RT_DEBUG_WITH_TYPE(TYPE, X)                                        \
+  do {                                                                         \
+    const char *Types =                                                        \
+        ::__orc_rt::DebugTypes.load(std::memory_order_relaxed);                \
+    if (!Types)                                                                \
+      Types = initializeDebug();                                               \
+    if (Types == &DebugTypesNone)                                              \
+      break;                                                                   \
+    if (Types == &DebugTypesAll ||                                             \
+        ::__orc_rt::debugTypeEnabled(TYPE, Types)) {                           \
+      X;                                                                       \
+    }                                                                          \
+  } while (false)
+
+#else
+
+#define ORC_RT_DEBUG_WITH_TYPE(TYPE, X)                                        \
+  do {                                                                         \
+  } while (false)
+
+#endif // !NDEBUG
+
+#define ORC_RT_DEBUG(X) ORC_RT_DEBUG_WITH_TYPE(DEBUG_TYPE, X)
+
+#endif // ORC_RT_COMMON_H

compiler-rt/lib/orc/debug.cpp

+//===- debug.cpp ----------------------------------------------------------===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+//
+// This file is a part of the ORC runtime support library.
+//
+//===----------------------------------------------------------------------===//
+
+#include "debug.h"
+
+#include <cassert>
+#include <cstdio>
+#include <cstdlib>
+
+namespace __orc_rt {
+
+#ifndef NDEBUG
+
+std::atomic<const char *> DebugTypes;
+char DebugTypesAll;
+char DebugTypesNone;
+
+/// Sets the DebugState and DebugTypes values -- this function may be called
+/// concurrently on multiple threads, but will always assign the same values so
+/// this should be safe.
+const char *initializeDebug() {
+  if (const char *DT = getenv("ORC_RT_DEBUG")) {
+    if (strcmp(DT, "") == 0 || strcmp(DT, "1") == 0) {
+      DebugTypes.store(&DebugTypesAll, std::memory_order_relaxed);
+      return &DebugTypesAll;
+    } else {
+      DebugTypes.store(DT, std::memory_order_relaxed);
+      return DT;
+    }
+  } else {
+    DebugTypes.store(&DebugTypesNone, std::memory_order_relaxed);
+    return &DebugTypesAll;
+  }
+}
+
+bool debugTypeEnabled(const char *Type, const char *Types) {
+  assert(Types && Types != &DebugTypesAll && Types != &DebugTypesNone &&
+         "Invalid Types value");
+  size_t TypeLen = strlen(Type);
+  const char *Start = Types;
+  const char *End = Start;
+
+  do {
+    if (*End == '\0' || *End == ',') {
+      size_t ItemLen = End - Start;
+      if (ItemLen == TypeLen && memcmp(Type, Start, TypeLen) == 0)
+        return true;
+      if (*End == '\0')
+        return false;
+      Start = End + 1;
+    }
+    ++End;
+  } while (true);
+}
+
+void printdbg(const char *format, ...) {
+  va_list Args;
+  va_start(Args, format);
+  vfprintf(stderr, format, Args);
+  va_end(Args);
+}
+
+#endif // !NDEBUG
+
+} // end namespace __orc_rt