[XRay][compiler-rt] Handle tail-call exits in the XRay runtime

[dberris]

Summary

This change starts differentiating tail exits from normal exits. We also
increase the version number of the "naive" log to version 2, which will
be the starting version where these records start appearing. In FDR mode
we treat the tail exits as normal exits, and are thus subject to the
same treatment with regard to record unwriting.

Updating the version number is important to signal older builds of the
llvm-xray tool that do not deal with the tail exit records must fail
early (and that users should only use the llvm-xray tool built after
the support for tail exits to get accurate handling of these records).

Depends on D37964.

[pelikan]

I don't understand why do we need the version number bumped but I'm guessing you'll show me a counter-example in response to this comment.

[dberris]

In D37965#873417, @pelikan wrote:

I don't understand why do we need the version number bumped but I'm guessing you'll show me a counter-example in response to this comment.

Right, apologies if it wasn't too clear.

This one is a matter of non-backwards compatibility. We're using the version number in the log to indicate that older versions of the llvm-xray tools aren't expected to handle this version of the log (because we write new kinds of records here). This makes it so that when the previously built/released version of the llvm-xray tool is used on a newer version of the log, the older built tool will fail immediately on an unknown version.

I'll update the description to explain this a bit more.

[dberris]

Reword description.

compiler-rt/trunk/include/xray/xray_records.h

struct alignas(32) XRayRecord {
   // This is the type of the record being written. We use 16 bits to allow us to
   // treat this as a discriminant, and so that the first 4 bytes get packed
   // properly. See RecordTypes for more supported types.
   uint16_t RecordType = 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.
+  // The type of the event. One of the following:
+  //   ENTER = 0
+  //   EXIT = 1
+  //   TAIL_EXIT = 2
   uint8_t Type = 0;
 
   // The function ID for the record.
   int32_t FuncId = 0;
 
   // Get the full 8 bytes of the TSC when we get the log record.
   uint64_t TSC = 0;
 

compiler-rt/trunk/lib/xray/xray_fdr_logging_impl.h

inline void processFunctionHook(
   TLD.CurrentCPU = CPU;
   switch (Entry) {
   case XRayEntryType::ENTRY:
   case XRayEntryType::LOG_ARGS_ENTRY:
     // Update the thread local state for the next invocation.
     TLD.LastFunctionEntryTSC = TSC;
     break;
   case XRayEntryType::TAIL:
-    break;
   case XRayEntryType::EXIT:
     // Break out and write the exit record if we can't erase any functions.
     if (TLD.NumConsecutiveFnEnters == 0 ||
         (TSC - TLD.LastFunctionEntryTSC) >= thresholdTicks())
       break;
     rewindRecentCall(TSC, TLD.LastTSC, TLD.LastFunctionEntryTSC, FuncId);
     return; // without writing log.
   case XRayEntryType::CUSTOM_EVENT: {

compiler-rt/trunk/lib/xray/xray_inmemory_log.cc

static int __xray_OpenLogFile() XRAY_NEVER_INSTRUMENT {
   static bool TSCSupported = probeRequiredCPUFeatures();
   static uint64_t CycleFrequency = TSCSupported ? getTSCFrequency()
                                    : __xray::NanosecondsPerSecond;
 
   // Since we're here, we get to write the header. We set it up so that the
   // header will only be written once, at the start, and let the threads
   // logging do writes which just append.
   XRayFileHeader Header;
-  Header.Version = 1;
+  Header.Version = 2;  // Version 2 includes tail exit records.
   Header.Type = FileTypes::NAIVE_LOG;
   Header.CycleFrequency = CycleFrequency;
 
   // FIXME: Actually check whether we have 'constant_tsc' and 'nonstop_tsc'
   // before setting the values in the header.
   Header.ConstantTSC = 1;
   Header.NonstopTSC = 1;
   retryingWriteAll(F, reinterpret_cast<char *>(&Header),
void __xray_InMemoryRawLog(int32_t FuncId, XRayEntryType Type,
   thread_local static size_t Offset = 0;
   static int Fd = __xray_OpenLogFile();
   if (Fd == -1)
     return;
   thread_local __xray::ThreadExitFlusher Flusher(
       Fd, reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer), Offset);
   thread_local pid_t TId = syscall(SYS_gettid);
 
+  // Use a simple recursion guard, to handle cases where we're already logging
+  // and for one reason or another, this function gets called again in the same
+  // thread.
+  thread_local volatile bool RecusionGuard = false;
+  if (RecusionGuard) return;
+  RecusionGuard = true;
+
   // 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];
   R.RecordType = RecordTypes::NORMAL;
   R.TSC = ReadTSC(R.CPU);
   R.TId = TId;
   R.Type = Type;
   R.FuncId = FuncId;
   ++Offset;
   if (Offset == BuffLen) {
     __sanitizer::SpinMutexLock L(&LogMutex);
     auto RecordBuffer = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer);
     retryingWriteAll(Fd, reinterpret_cast<char *>(RecordBuffer),
                      reinterpret_cast<char *>(RecordBuffer + Offset));
     Offset = 0;
   }
+
+  RecusionGuard = false;
 }
 
 void __xray_InMemoryRawLogRealTSC(int32_t FuncId,
                                   XRayEntryType Type) XRAY_NEVER_INSTRUMENT {
   __xray_InMemoryRawLog(FuncId, Type, __xray::readTSC);
 }
 
 void __xray_InMemoryEmulateTSC(int32_t FuncId,

compiler-rt/trunk/lib/xray/xray_trampoline_x86_64.S

 
 //===----------------------------------------------------------------------===//
 
   .global __xray_FunctionTailExit
   .align 16, 0x90
   .type __xray_FunctionTailExit,@function
 __xray_FunctionTailExit:
   .cfi_startproc
-  // Save the important registers as in the entry trampoline, but indicate that
-  // this is an exit. In the future, we will introduce a new entry type that
-  // differentiates between a normal exit and a tail exit, but we'd have to do
-  // this and increment the version number for the header.
   SAVE_REGISTERS
 
   movq  _ZN6__xray19XRayPatchedFunctionE(%rip), %rax
   testq %rax,%rax
   je  .Ltmp4
 
   movl  %r10d, %edi
-  movl  $1, %esi
+  movl  $2, %esi
   callq *%rax
 
 .Ltmp4:
   RESTORE_REGISTERS
   retq
 .Ltmp5:
   .size __xray_FunctionTailExit, .Ltmp5-__xray_FunctionTailExit
   .cfi_endproc

compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc

int main(int argc, char *argv[]) {
   std::cout << "Flush status " << __xray_log_flushLog() << std::endl;
   // CHECK: Flush status {{.*}}
   __xray_unpatch();
   return 0;
 }
 
 // Check that we're able to see two threads, each entering and exiting fA().
 // TRACE-DAG: - { type: 0, func-id: [[FIDA:[0-9]+]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE:     - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE:     - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE:     - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE:     - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
 //
 // Do the same as above for fC()
 // TRACE-DAG: - { type: 0, func-id: [[FIDC:[0-9]+]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE:     - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE:     - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE:     - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE:     - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
 
 // Do the same as above for fB()
 // TRACE-DAG: - { type: 0, func-id: [[FIDB:[0-9]+]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE:     - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE:     - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE:     - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE:     - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
 
 // Assert that when unwriting is enabled with a high threshold time, all the function records are erased. A CPU switch could erroneously fail this test, but
 // is unlikely given the test program.
 // UNWRITE: header
 // UNWRITE-NOT: function-enter
-// UNWRITE-NOT: function-exit
+// UNWRITE-NOT: function-{{exit|tail-exit}}

compiler-rt/trunk/test/xray/TestCases/Linux/fdr-thread-order.cc

int main(int argc, char *argv[]) {
   __xray_log_finalize();
   __xray_log_flushLog();
   // CHECK: {{.*}}XRay: Log file in '{{.*}}'
 }
 
 // We want to make sure that the order of the function log doesn't matter.
 // TRACE-DAG: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FID2:[0-9]+]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
-// TRACE-DAG: - { type: 0, func-id: [[FID1]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
-// TRACE-DAG: - { type: 0, func-id: [[FID2]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
+// TRACE-DAG: - { type: 0, func-id: [[FID1]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: {{function-exit|function-tail-exit}}, tsc: {{[0-9]+}} }
+// TRACE-DAG: - { type: 0, func-id: [[FID2]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: {{function-exit|function-tail-exit}}, tsc: {{[0-9]+}} }