[compiler-rt][XRay] Initial per-thread inmemory logging implementation

[dberris]

Summary

Depends on D21612 which implements the building blocks for the compiler-rt
implementation of the XRay runtime. We use a naive in-memory log of fixed-size
entries that get written out to a log file when the buffers are full, and when
the thread exits.

This implementation lays some foundations on to allowing for more complex XRay
records to be written to the log in subsequent changes. It also defines the format
that the function call accounting tool in D21987 will start building upon.

Once D21987 lands, we should be able to start defining more tests using that tool
once the function call accounting tool becomes part of the llvm distribution.

[majnemer]

lib/xray/xray_inmemory_log.cc

108

Could you please use the __rdtscp intrinsic?
Might be good to only do so if you are on X86 with a fallback of __builtin_readcyclecounter ?

117

What if you get a partial write?

[dberris]

lib/xray/xray_inmemory_log.cc

108

Using the __rdtscp intrinsic, let's cross the bridge for non-x86 later?

117

Good catch! Makes the code a bit more complicated, but more correct AFAICT now.

[dberris]

• Use __rdtscp() and account for partial writes

[majnemer]

lib/xray/xray_inmemory_log.cc

124

Isn't this code dead because your while condition requires Written to be non-zero?

[dberris]

• Remove dead code

[dberris]

lib/xray/xray_inmemory_log.cc

125

Whoops, yes. Good catch. :)

[dberris]

• Remove demo logging, use in-memory logging

[majnemer]

lib/xray/xray_inmemory_log.cc

120

Should we handle errno == EINTR?

[dberris]

lib/xray/xray_inmemory_log.cc

120

Yes, and refactor this a bit so we do the right thing both times. :)

[dberris]

• Refactor a bit, make retrying write work consistently at thread exit and when buffer is full

[mehdi_amini]

lib/xray/xray_inmemory_log.cc

64

Early exit:

if (!Offset) return;

66

This while condition isn't clear to me: Written would be 0 if nothing is written, which seem unexpected.
What about a while (1)?

75

If you want to handle partial write properly, I think you need to update start and offset as well.

I feel the interface for RetryingWrite would be more usual of C++ std algorithm with a Begin / End instead of start/offset.

109

Shouldn't error be printed to stderr?

112

This looks like debugging, is it intended to be here?
Do you really want unconditionally always on? And is stdout the right output?

[dberris]

• Handle partial writes better.

lib/xray/xray_inmemory_log.cc

112

Yep, this is for debugging. I'm still thinking about how to control this filename either through an API or through environment variables.

[majnemer]

lib/xray/xray_inmemory_log.cc

81

ISTM that this assert can fail in practice.

I'd maintain the buffer you are trying to write as just a char * to correctly handle this.

[majnemer]

lib/xray/xray_inmemory_log.cc

72

I don't believe write can actually return zero for this case.

[mehdi_amini]

lib/xray/xray_inmemory_log.cc

72

When does write can actually return zero according to the spec?

[majnemer]

lib/xray/xray_inmemory_log.cc

72

From my recollection, it should only be possible if you pass write a count of zero bytes.

[dberris]

lib/xray/xray_inmemory_log.cc

72

Ah, that's right. I was confused by the documentation too. Fixed.

81

Good catch. Done.

[dberris]

• Rebase
• Support partial writes better-er

[mehdi_amini]

lib/xray/xray_inmemory_log.cc

72

I does not matter much for this patch, but for my own curiosity, do you have a pointer to the doc that mentions the zero returned case?

122

stderr maybe?

[dberris]

Rebase

[dberris]

This is still not ready, but the patch we're dependent on is ready (D21612). I will continue to iterate on this to clean it up a bit more, and add more useful information into the head of the log to help with things like figuring out how much walltime elapsed between two TSC ticks where the binary was run, a version identifier for the log, etc.

lib/xray/xray_inmemory_log.cc

74

Link I can find: http://linux.die.net/man/2/write

It says pretty much that it will only return 0 if the size provided was 0. I don't know why anybody would do that, but I guess the API allows it so there's a special case for that. :)

124

Yeah, I think a better way of doing this is to provide the log file base name as a flag (with a sane default, maybe synthesized as "/tmp/<pid>.xray"), then that means we don't need to write it out unless we're being verbose.

[dberris]

Rebase

[dberris]

• Expose the log record definitions and write out headers at the beginning of the log file

[dberris]

Rebase

[dberris]

• Undo changes in assembler

[dberris]

Question for Reid/Medhi/Eric:

Now that D21612 has landed I'm thinking of adding tests here to be able to do some sanity-checking of the generated log file. That though means that the "best" means of doing this is by using a tool that will output the information in a verifiable manner. We have some options in that regard:

• Implement a stand-alone tool in compiler-rt just for testing. This seems brittle but should be simple enough to do.
• Land D21987 in LLVM and then potentially depend on that from compiler-rt (although I'm not sure if the dependency chain would be correct).

I'm leaning towards the first solution, but I'd like to hear your thoughts on how best to go about this too.

Cheers

[dberris]

• WIP: Adding one test, but still failing

I'm currently getting the following error:

		lit.py: /usr/local/google/home/dberris/xray/llvm/utils/lit/lit/TestingConfig.py:115: fatal: unable to parse config file '/usr/local/google/home/dberris/xray/llvm/projects/compiler-rt/test/xray/lit.cfg', traceback: Traceback (most recent call last):
			File "/usr/local/google/home/dberris/xray/llvm/utils/lit/lit/TestingConfig.py", line 102, in load_from_path
				exec(compile(data, path, 'exec'), cfg_globals, None)
			File "/usr/local/google/home/dberris/xray/llvm/projects/compiler-rt/test/xray/lit.cfg", line 6, in <module>
				config.name = 'XRay' + config.name_suffix
		AttributeError: TestingConfig instance has no attribute 'name_suffix'

I'm not seeing what the difference is though with other testing set-ups for other compiler-rt tests.

[dberris]

• Fixup CMake config and lit configuration
• Fixup test case to clean up after itself

This is now ready for another look.

[dberris]

• Remove redundant/wrong addition of COMPILER_RT_BUILD_XRAY

[dberris]

• Rename xray_trampoline_x86.S to xray_trampoline_x86_64.S

Based on review comments from D21612.

[dberris]

ping?

[dberris]

Rebase; depends on D23051.

[dberris]

Rebase again, with fix to math for stack adjustment.

[dberris]

Rebase; Depends on D23154.

[dberris]

Rebase

[majnemer]

include/xray/xray_records.h

41–42 ↗

(On Diff #67112)

Should these be bitfields?

lib/xray/xray_inmemory_log.cc

48

Are we following LLVM convention for XRay? If so, I'd make this function start with a lowercase letter.

53–54

This should be Written < 0. I don't believe errno will be set to anything good if write returns 0; I think you'd observe a previous errno value.

74

Why noexcept?

91

Ditto regarding llvm convention.

91

Should the long be a long long?

92

Should we pass in O_CLOEXEC?

96–97

How do you feel about these potentially failing?

99

Shouldn't this be s64?

157

Any reason not to just use 0?

176

I'd just use unsigned here to match how __rdtscp is defined.

[dberris]

Rebase + style comments and some correctness fixes

include/xray/xray_records.h

41–42 ↗

(On Diff #67112)

Good idea, yep.

lib/xray/xray_inmemory_log.cc

48

Yes, we should be -- sorry I haven't quite internalised the rules. :/

53–54

Good catch, thanks. Done.

74

Habbit... removed.

92

Good idea -- yes, done.

96–97

Not very good... is it better now?

[dberris]

Rebase

[majnemer]

include/xray/xray_records.h

40–42 ↗

(On Diff #68126)

Why not give these bitfields an underlying type of bool?

lib/xray/xray_inmemory_log.cc

72

Should we assert that Fd > 0?

78

Why do we have this fsync? Might deserve a comment.

96–100

This seems wrong in the face of partial reads. Perhaps a retryingRead is called for?

[dberris]

• Address review comments
• Make use of the naive log configurable
• Add test to make sure options from args works

[dberris]

lib/xray/xray_inmemory_log.cc

72

Instead of asserting, I check that Fd is valid before using it in the write in the destructor.

78

Explained a little in a comment, essentially because we're not doing any sort of reference counting (for simplicity's sake) we rely on the sync to flush the data at a thread's exit. We can implement reference counting, but that would complicate this a bit more than necessary IMO.

[majnemer]

include/xray/xray_records.h

39–42 ↗

(On Diff #68136)

You could gain another byte for Padding by sending this between Type and CycleFrequency.

lib/xray/xray_inmemory_log.cc

71

ssize_t?

[dberris]

• Re-order some flags in XRayFileHeader

[dberris]

• Use ssize_t for BytesRead

[rSerge]

Please, see inline.

include/xray/xray_records.h

47 ↗

(On Diff #68142)

So CycleFrequency is an 8-byte variable not aligned to 8 bytes. This may cause portability issues to other CPUs, not only performance drops for unaligned memory access, but they say on some CPUs unaligned access is completely forbidden.

lib/xray/xray_inmemory_log.cc

72

So the loop runs while BytesRead<0 ? Shouldn't it run while BytesToRead > 0?
Then in an if, before checking errno, you can check whether BytesRead < 0.

91

So retryingWrite writes all bytes, while retryingRead reads some bytes up to the given number of bytes, right? Then their parameters should indicate this, or the functions should be renamed to e.g. retryingWriteAll and retryingReadSome .

131

This crashes if Buffer contains formatting, e.g. %d (random memory read) or worse %n (random memory write), but no formatting arguments are given. Consider changing to `fprintf(stderr, "%s", Buffer);

136

(Minor) Why not to have BuffLen as a local static const? This would remove "action at a distance" anti-pattern.

138

Why not thread_local ? How do you ensure no 2 threads race to check whether Fd is initialized and, if not, initializing it?

140

Why do you call it Printf? f in printf stays for formatted, I guess. But PrintToStdErr doesn't support formatting. Consider renaming to SetPrintAndReportCallback .

142

Would be UB in a race condition.

143

How the magic 246 number is calculated?

144

Is 255 logically equal to sizeof(TmpFilename)-1 ? The latter would be preferred over a magic number, and it's easier then to change just one place - the declaration of TmpFilename variable.

148

Consider making "XXXXXX" a constant, replacing 6 with its sizeof-1.

160–164

What if the system has multiple CPU sockets, with different CPUs installed so that TSC frequencies are different for different cores?

167

Why not to report an error?

[dberris]

Address comments

[dberris]

include/xray/xray_records.h

47 ↗

(On Diff #68142)

Are you aware of specific CPUs where this would be an issue?

I'm happy to change it, but I'd like to understand whether this is an actual problem, or just a hypothetical one.

Note that we don't read this, we only ever write it down, so the performance hit isn't as important as maximising the packing of the bytes that eventually make it to disk. The 15 byte padding gives us 15 more bytes to use for later extending the information in the file header.

lib/xray/xray_inmemory_log.cc

138

C++11 ensures this for us, that the first time this function is called, this static variable is initialised exactly once -- this is meant to be synchronised across all threads too.

140

This API is defined by the common sanitizer tools -- I'm just a using it. :)

There are places where Report(...) is called with a format string and additional arguments (like printf), and underneath it dispatches to a callback when these formatted print's are actually invoked. We're providing something that deals with the string that's post-formatted.

142

C++11 ensures this is not a racy initialisation.

143

I was being conservative here, giving an allowance of 10 bytes difference between the size of the temporary filename's buffer size total and the base filename provided as a flag. Fixed it to do relative calculations instead of magic numbers.

160–164

I'm not sure how this works in non-x86, but we assume that all the CPUs will run in the same rate, and use that as an approximation for the TSC frequency rate. This means if we're on this branch of the conditional, we don't get the reliable number and take a guess anyway.

[sdardis]

include/xray/xray_records.h

48 ↗

(On Diff #68969)

Apologies for the drive-by comment.

Pre MIPSR6 requires different instructions (e.g. swl/swr to store 4 bytes) to write unaligned data if it is not naturally aligned to its size. Attempting to access 2/4/8 byte words with a normal load/store triggers a CPU level address exception if unaligned.

For MIPSR6 unaligned support is required, but it is implementation dependent how this is achieved. For example, an implementation could support unaligned access within a cacheline but require OS intervention if the unaligned access crosses a cacheline.

IIRC x86, PowerPC, AArch64 have native support for unaligned access. SPARC, ARM typically don't.

[dberris]

include/xray/xray_records.h

48 ↗

(On Diff #68969)

Apologies for the drive-by comment.

No need for apologies, comments most appreciated!

Pre MIPSR6 requires different instructions (e.g. swl/swr to store 4 bytes) to write unaligned data if it is not naturally aligned to its size. Attempting to access 2/4/8 byte words with a normal load/store triggers a CPU level address exception if unaligned.

For MIPSR6 unaligned support is required, but it is implementation dependent how this is achieved. For example, an implementation could support unaligned access within a cacheline but require OS intervention if the unaligned access crosses a cacheline.

IIRC x86, PowerPC, AArch64 have native support for unaligned access. SPARC, ARM typically don't.

Cool, this is good to know. Happy to change this implementation to be more portable to more platforms. :)

[dberris]

• Undo changes to CMakeLists.txt
• Align CycleFrequency to 8 byte boundaries.

[dberris]

Address comments on alignment of CycleFrequency.

[rSerge]

Looks good to me.

lib/xray/xray_inmemory_log.cc

161–165

I meant a x86/x86_64 system, consumer motherboards can easily have 2 sockets to install 2 different CPUs. Non-x86/x86_64 system is a harder question: a replacement for TSC/RDTSC would be needed.

[dberris]

Rebase before landing.

lib/xray/CMakeLists.txt

 # Build for the XRay runtime support library.
 
 set(XRAY_SOURCES
   xray_init.cc
-  xray_interface.cc
+  xray_interface.cc
+  xray_inmemory_log.cc
 )
 
 include_directories(..)
 include_directories(../../include)
 
 set(XRAY_CFLAGS ${SANITIZER_COMMON_CFLAGS})
 
 set(XRAY_COMMON_DEFINITIONS XRAY_HAS_EXCEPTIONS=1)
 
 add_compiler_rt_object_libraries(RTXray
-    ARCHS ${XRAY_SUPPORTED_ARCH}
-    SOURCES ${XRAY_SOURCES} CFLAGS ${XRAY_CFLAGS}
-    DEFS ${XRAY_COMMON_DEFINITIONS})
+    ARCHS ${XRAY_SUPPORTED_ARCH}
+    SOURCES ${XRAY_SOURCES} CFLAGS ${XRAY_CFLAGS}
+    DEFS ${XRAY_COMMON_DEFINITIONS})
 
 add_custom_target(xray)
 set(XRAY_COMMON_RUNTIME_OBJECT_LIBS RTXray)
 add_compiler_rt_runtime(clang_rt.xray
     STATIC
     ARCHS ${XRAY_SUPPORTED_ARCH}
     OBJECT_LIBS RTXray ${XRAY_COMMON_RUNTIME_OBJECT_LIBS}
     CFLAGS ${XRAY_CFLAGS}
     DEFS ${XRAY_COMMON_DEFINITIONS}
     PARENT_TARGET xray)
 add_dependencies(compiler-rt xray)
 
 # if(COMPILER_RT_INCLUDE_TESTS)
 #   add_subdirectory(tests)
 # endif()

lib/xray/xray_init.cc

 // /proc/curproc/map and make sure that we're able to get it. We signal failure
 // via a global atomic boolean to indicate whether we've initialized properly.
 //
 std::atomic<bool> XRayInitialized{false};
 
 // This should always be updated before XRayInitialized is updated.
 std::atomic<__xray::XRaySledMap> XRayInstrMap{};
 
-void __xray_dump() {
-  // FIXME: This is just a proof-of-concept implementation, should make this
-  // more accessible for the real thing.
-  auto LocalEntries = XRayInstrMap.load(std::memory_order_acquire);
-  if (LocalEntries.Entries == 0) {
-    printf("Instrumentation map is empty.\n");
-    return;
-  }
-
-  printf("__xray_instr_map@%p..%p\n", __start_xray_instr_map,
-         __stop_xray_instr_map);
-  auto Countdown = LocalEntries.Entries;
-  auto Sled = LocalEntries.Sleds;
-  static constexpr char EntrySled[] = "E";
-  static constexpr char ExitSled[] = "X";
-  static constexpr char Always[] = "*";
-  static constexpr char Maybe[] = "?";
-  while (Countdown != 0) {
-    printf("%lx\t%s\t%s\t@function(%lx)\n", Sled->Address,
-           Sled->Kind == static_cast<unsigned short>(XRayEntryType::ENTRY)
-               ? EntrySled
-               : ExitSled,
-           Sled->AlwaysInstrument == 1 ? Always : Maybe, Sled->Function);
-    --Countdown;
-    ++Sled;
-  }
-}
-
-extern "C" {
-void __xray_DemoLog(int32_t FuncId, XRayEntryType Type) {
-  uint64_t Hi;
-  uint32_t Lo, CPUId;
-  __asm__ __volatile__("rdtscp" : "=a"(Lo), "=d"(Hi), "=c"(CPUId));
-  int ignored = printf(
-      "%lu: [%lu] %s%d\n", CPUId, (Hi << 32) | Lo,
-      Type == static_cast<unsigned short>(XRayEntryType::ENTRY) ? "E" : "X",
-      FuncId);
-  (void)(ignored);
-}
-}
-
 // __xray_init() will do the actual loading of the current process' memory map
 // and then proceed to look for the .xray_instr_map section/segment.
 void __xray_init() {
   if (__start_xray_instr_map == nullptr) {
     printf("XRay instrumentation map missing. Not initializing XRay.\n");
     return;
   }
 
   // Now initialize the XRayInstrMap global struct with the address of the
   // entries, reinterpreted as an array of XRaySledEntry objects. We use the
   // virtual pointer we have from the section to provide us the correct
   // information.
   __xray::XRaySledMap SledMap{};
   SledMap.Sleds = __start_xray_instr_map;
   SledMap.Entries = __stop_xray_instr_map - __start_xray_instr_map;
   XRayInstrMap.store(SledMap, std::memory_order_release);
   XRayInitialized.store(true, std::memory_order_release);
 
-  // FIXME: Only for demo, patch the functions before we run main.
-  __xray_dump();
-  __xray_set_handler(__xray_DemoLog);
+  // FIXME: Only for demo, dump the table and patch functions before main.
   __xray_patch();
 }
 
 __attribute__((section(".preinit_array"),
                used)) void (*__local_xray_preinit)(void) = __xray_init;

lib/xray/xray_inmemory_log.cc

+//===-- xray_inmemory_log.cc ------------------------------------*- C++ -*-===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+//
+// This file is a part of XRay, a dynamic runtime instrumentation system.
+//
+// Implementation of a simple in-memory log of XRay events. This defines a
+// logging function that's compatible with the XRay handler interface, and
+// routines for exporting data to files.
+//
+//===----------------------------------------------------------------------===//
+
+#include "xray_interface_internal.h"
+
+#include <mutex>
+#include <thread>
+
+#include <cassert>
+#include <fcntl.h>
+#include <stdio.h>
+#include <sys/stat.h>
+#include <sys/syscall.h>
+#include <sys/types.h>
+#include <unistd.h>
+
+#include <x86intrin.h>
+
+extern "C" {
+void __xray_InMemoryRawLog(int32_t FuncId, XRayEntryType Type);
+}
+
+// __xray_InMemoryRawLog will use a thread-local aligned buffer capped to a
+// certain size (32kb by default) and use it as if it were a circular buffer for
+// events. We store simple fixed-sized entries in the log for external analysis.
+namespace __xray {
+struct alignas(32) XRayRecord {
+  // Get the full 8 bytes of the TSC when we get the log record.
+  uint64_t TSC = 0;
+
+  // The thread ID for the currently running thread.
+  pid_t TId = 0;
+
+  // The CPU where the thread is running. We assume number of CPUs <= 256.
+  uint8_t CPU = 0;
+
+  // The type of the event. Usually either ENTER = 0 or EXIT = 1.
+  uint8_t Type = 0;
+
+  // The function ID for the record.
+  int32_t FuncId = 0;
+};
+
+static_assert(sizeof(XRayRecord) == 32, "XRayRecord != 32 bytes");
+
+std::mutex LogMutex;
+
+static constexpr size_t BuffLen = 1024;
+
+static void RetryingWrite(int Fd, char *Begin, char *End) {
+  if (Begin == End)
+    return;
+  auto TotalBytes = std::distance(Begin, End);
+  while (auto Written = write(Fd, Begin, TotalBytes)) {
+    if (Written <= 0) {
+      if (errno == EINTR)
+        continue; // Try again.
+      fprintf(stderr, "Failed to write; errno = %d", errno);
+      return;
+    }
+
+    // FIXME: Figure out whether/how to assert properly.
+    assert(static_cast<uint64_t>(Written) <= TotalBytes);
+    TotalBytes -= Written;
+    if (TotalBytes == 0)
+      break;
+    Begin += Written;
+  }
+}
+
+class ThreadExitFlusher {
+public:
+  explicit ThreadExitFlusher(int Fd, XRayRecord *Start, size_t &Offset)
+      : Fd(Fd), Start(Start), Offset(Offset) {}
+
+  ~ThreadExitFlusher() noexcept {
+    std::lock_guard<std::mutex> L(LogMutex);
+    RetryingWrite(Fd, reinterpret_cast<char *>(Start),
+                  reinterpret_cast<char *>(Start + Offset));
+    fsync(Fd);
+  }
+
+private:
+  int Fd;
+  XRayRecord *Start;
+  size_t &Offset;
+};
+}
+
+void __xray_InMemoryRawLog(int32_t FuncId, XRayEntryType Type) {
+  using Buffer = std::aligned_storage<sizeof(__xray::XRayRecord),
+                                      alignof(__xray::XRayRecord)>::type;
+  thread_local static Buffer InMemoryBuffer[__xray::BuffLen] = {};
+  thread_local static size_t Offset = 0;
+  static int Fd = [] {
+    // Open a temporary file once for the log.
+    static char TmpFilename[] = "/tmp/xray-log-XXXXXX";
+    int Fd = mkstemp(TmpFilename);
+    if (Fd == -1) {
+      fprintf(stderr,
+              "XRay: Failed opening temporary file '%s'; not logging events.",
+              TmpFilename);
+      return -1;
+    }
+
+    // FIXME: Figure out how to either control this or to make it available some
+    // other way.
+    printf("XRay: Log file in '%s'\n", TmpFilename);
+    return Fd;
+  }();
+  if (Fd == -1)
+    return;
+  thread_local __xray::ThreadExitFlusher Flusher(
+      Fd, reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer), Offset);
+  thread_local pid_t TId = syscall(SYS_gettid);
+
+  // First we get the useful data, and stuff it into the already aligned buffer
+  // through a pointer offset.
+  auto &R = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer)[Offset];
+  uint32_t CPU;
+  R.TSC = __rdtscp(&CPU);
+  R.CPU = CPU;
+  R.TId = TId;
+  R.Type = Type;
+  R.FuncId = FuncId;
+  ++Offset;
+  if (Offset == __xray::BuffLen) {
+    std::lock_guard<std::mutex> L(__xray::LogMutex);
+    auto RecordBuffer = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer);
+    __xray::RetryingWrite(Fd, reinterpret_cast<char *>(RecordBuffer),
+                          reinterpret_cast<char *>(RecordBuffer + Offset));
+    Offset = 0;
+  }
+}
+
+static auto Unused = [] {
+  __xray_set_handler(__xray_InMemoryRawLog);
+  return true;
+}();