[XRay] [compiler-rt] FDR logging arg1 handler

[pelikan]

Summary

Write out records about logged function call first arguments. D32840
implements the reading of this in llvm-xray.

There are some refactoring options and bugs discovered along the way, this is
only a commit to get things working.

Depends on D32840.

[dberris]

Adding in @kpw who also has more context on this implementation.

include/xray/xray_log_interface.h

163 ↗

(On Diff #97762)

Because of ABI reasons, we really shouldn't change this struct. The comments say that if implementations need to add their arg1 handler, they should do it in the init implementation.

lib/xray/xray_fdr_logging.cc

196 ↗

(On Diff #97762)

You dropped the XRAY_NEVER_INSTRUMENT?

Also now you probably want to mark this always inline.

It would also make it more efficient to just return a 16-byte struct, so the inliner doesn't have to guess whether TSC and/or CPU alias.

224–225 ↗

(On Diff #97762)

I'm ambivalent about this API change. Let me try to explain why.

First, while the compiler might tail-call into the specified function, it was already using 7 arguments. In SysV64, that means the first 6 arguments that fit in registers will be in the registers already. Adding an argument spills more stuff onto the stack. That's one.

Second, we're paying this cost in the path where we know we don't have an argument. That seems like a waste to me.

Maybe it's better to refactor this differently, so we have the innards of processFunctionHook extracted appropriately so we can handle the "we are logging arguments" case and "we are not logging arguments" better?

Or at least be able to compose either of these functions in an easier manner so while there will be a little redundancy, it's going to be easier to read and reason about. Packing on more arguments to the already overloaded processFunctionHook function seems like a bad way to go especially if we intend to support multiple argument logging in the future.

[pelikan]

after a long discussion and a long time on a different project, update to reflect comments

include/xray/xray_log_interface.h

163 ↗

(On Diff #97762)

After our discussions about why we can't change this ABI (despite the fact LLVM itself is incredibly progressive in this regard), I've changed this to describe the proposed behaviour for anyone reading this code later.

lib/xray/xray_fdr_logging.cc

196 ↗

(On Diff #97762)

It was never there, fixed. I don't see the point of "inline" since it's already static and because processFunctionHook is so huge, we obviously don't care about the function call overhead here.

Can we change this later, when that FIXME is being fixed properly?

224–225 ↗

(On Diff #97762)

While I agree with you on the problems with the code structure, I tried making the change the least intrusive possible, and refactor later. I'll take your comment as a permission to tear processFunctionHook apart.

[dberris]

LGTM (with a couple of suggestions)

lib/xray/xray_fdr_logging_impl.h

613 ↗

(On Diff #104091)

nit: writeTSCForThisCPU -> writeCurrentCPUTSC

623 ↗

(On Diff #104091)

Consider using std::numeric_limits<int32_t>::max() instead.

[pelikan]

Rebased to HEAD.

[pelikan]

address nitpicks

[dberris]

Okay, now I think this needs a rebase given the latest changes.

[dberris]

lib/xray/xray_fdr_logging.cc

293 ↗

(On Diff #115327)

Actually, you want to install the arg1 logging handler first, so that all the functions that have arg1 logging enabled don't sometimes use the arg0 then switch to the arg1 handler.

lib/xray/xray_fdr_logging_impl.h

670 ↗

(On Diff #115327)

Why make a copy of the shared_ptr here? I don't think we actually need a copy, do we?

747 ↗

(On Diff #115327)

You want to use the global instead of a function-local here. See what we do in the logArg0 case.

776 ↗

(On Diff #115327)

No validation here on the type of the entry? Nothing like what we do in the logArg0 handler to see that the EntryType isn't one of the unexpected values?

test/xray/TestCases/Linux/fdr-mode.cc

92 ↗

(On Diff #115327)

I think you want 'TRACE-DAG' still, but also need to look for the actual arguments too. Aren't we writing the list of arguments yet?

[pelikan]

rebase to HEAD

[pelikan]

lib/xray/xray_fdr_logging.cc

293 ↗

(On Diff #115327)

Good point. Fixed and documented.

[pelikan]

address yesterday's discussion

[dberris]

lib/xray/xray_fdr_logging_impl.h

586–595 ↗

(On Diff #116913)

You can turn this into an early return:

if (CPU != TLD.CurrentCPU) {
  ...
  return RecordTSCDelta;
}

// rest of code that's in else branch.

721–722 ↗

(On Diff #116913)

Why isn't this just in the cases above?

[pelikan]

address comment

[dberris]

LGTM

test/xray/TestCases/Linux/fdr-mode.cc

100–101 ↗

(On Diff #116920)

Probably use UNWRITE-DAG here instead, similar to how we use TRACE-DAG above.

[pelikan]

lib/xray/xray_fdr_logging_impl.h

586–595 ↗

(On Diff #116913)

Makes sense.

721–722 ↗

(On Diff #116913)

Because of the ordering. The metadata need to be after the function record as that means it belongs to the function.

670 ↗

(On Diff #115327)

Good point. I haven't gotten used to using shared_ptr properly yet. (C programmer learning.)

test/xray/TestCases/Linux/fdr-mode.cc

100–101 ↗

(On Diff #116920)

As discussed, we can't do that here since the point of UNWRITE is testing the other calls will *not* fire. The previous version of the test made sure of that which means putting UNWRITE-DAG here would actually destroy the tested behaviour.

[pelikan]

latest update before commit

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

struct XRayLogImpl {
   /// See XRayLogInitStatus for details on what the implementation MUST return
   /// when called.
   XRayLogInitStatus (*log_finalize)();
 
   /// The 0-argument function call handler. XRay logging implementations MUST
   /// always have a handler for function entry and exit events. In case the
   /// implementation wants to support arg1 (or other future extensions to XRay
   /// logging) those MUST be installed by the installed 'log_init' handler.
+  ///
+  /// Because we didn't want to change the ABI of this struct, the arg1 handler
+  /// may be silently overwritten during initialization as well.
   void (*handle_arg0)(int32_t, XRayEntryType);
 
   /// The log implementation provided routine for when __xray_log_flushLog() is
   /// called.
   ///
   /// See XRayLogFlushStatus for details on what the implementation MUST return
   /// when called.
   XRayLogFlushStatus (*flush_log)();

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

struct alignas(16) MetadataRecord {
   // unsigned 8-bit enum class to do so).
   enum class RecordKinds : uint8_t {
     NewBuffer,
     EndOfBuffer,
     NewCPUId,
     TSCWrap,
     WalltimeMarker,
     CustomEventMarker,
+    CallArgument,
   };
   // Use 7 bits to identify this record type.
   /* RecordKinds */ uint8_t RecordKind : 7;
   char Data[15];
 } __attribute__((packed));
 
 static_assert(sizeof(MetadataRecord) == 16, "Wrong size for MetadataRecord.");
 

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

 // capture as much data as we can, we use smaller records compared to the
 // default mode of always writing fixed-size records.
 
 namespace __xray {
 XRayLogInitStatus fdrLoggingInit(size_t BufferSize, size_t BufferMax,
                                  void *Options, size_t OptionsSize);
 XRayLogInitStatus fdrLoggingFinalize();
 void fdrLoggingHandleArg0(int32_t FuncId, XRayEntryType Entry);
+void fdrLoggingHandleArg1(int32_t FuncId, XRayEntryType Entry, uint64_t Arg1);
 XRayLogFlushStatus fdrLoggingFlush();
 XRayLogInitStatus fdrLoggingReset();
 
 } // namespace __xray
 
 #endif // XRAY_XRAY_FDR_LOGGING_H

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

if (TSCSupported) {
     TSC = TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
   }
   return std::make_tuple(TSC, CPU);
 }
 
 void fdrLoggingHandleArg0(int32_t FuncId,
                           XRayEntryType Entry) XRAY_NEVER_INSTRUMENT {
   auto TSC_CPU = getTimestamp();
-  __xray_fdr_internal::processFunctionHook(FuncId, Entry, std::get<0>(TSC_CPU),
-                                           std::get<1>(TSC_CPU), clock_gettime,
-                                           LoggingStatus, *BQ);
+  __xray_fdr_internal::processFunctionHook(
+      FuncId, Entry, std::get<0>(TSC_CPU), std::get<1>(TSC_CPU), 0,
+      clock_gettime, *BQ);
+}
+
+void fdrLoggingHandleArg1(int32_t FuncId, XRayEntryType Entry,
+                          uint64_t Arg) XRAY_NEVER_INSTRUMENT {
+  auto TSC_CPU = getTimestamp();
+  __xray_fdr_internal::processFunctionHook(
+      FuncId, Entry, std::get<0>(TSC_CPU), std::get<1>(TSC_CPU), Arg,
+      clock_gettime, *BQ);
 }
 
 void fdrLoggingHandleCustomEvent(void *Event,
                                  std::size_t EventSize) XRAY_NEVER_INSTRUMENT {
   using namespace __xray_fdr_internal;
   auto TSC_CPU = getTimestamp();
   auto &TSC = std::get<0>(TSC_CPU);
   auto &CPU = std::get<1>(TSC_CPU);
if (BQ == nullptr)
     BQ = new std::shared_ptr<BufferQueue>();
 
   *BQ = std::make_shared<BufferQueue>(BufferSize, BufferMax, Success);
   if (!Success) {
     Report("BufferQueue init failed.\n");
     return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
   }
 
+  // Arg1 handler should go in first to avoid concurrent code accidentally
+  // falling back to arg0 when it should have ran arg1.
+  __xray_set_handler_arg1(fdrLoggingHandleArg1);
   // Install the actual handleArg0 handler after initialising the buffers.
   __xray_set_handler(fdrLoggingHandleArg0);
   __xray_set_customevent_handler(fdrLoggingHandleCustomEvent);
 
   __sanitizer::atomic_store(&LoggingStatus,
                             XRayLogInitStatus::XRAY_LOG_INITIALIZED,
                             __sanitizer::memory_order_release);
   Report("XRay FDR init successful.\n");

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

 
 /// Called to close the buffer when the thread exhausts the buffer or when the
 /// thread exits (via a thread local variable destructor).
 static void writeEOBMetadata();
 
 /// TSC Wrap records are written when a TSC delta encoding scheme overflows.
 static void writeTSCWrapMetadata(uint64_t TSC);
 
-/// Here's where the meat of the processing happens. The writer captures
-/// function entry, exit and tail exit points with a time and will create
-/// TSCWrap, NewCPUId and Function records as necessary. The writer might
-/// walk backward through its buffer and erase trivial functions to avoid
-/// polluting the log and may use the buffer queue to obtain or release a
-/// buffer.
-static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
-                                uint64_t TSC, unsigned char CPU,
-                                int (*wall_clock_reader)(clockid_t,
-                                                         struct timespec *),
-                                __sanitizer::atomic_sint32_t &LoggingStatus,
-                                const std::shared_ptr<BufferQueue> &BQ);
-
 // Group together thread-local-data in a struct, then hide it behind a function
 // call so that it can be initialized on first use instead of as a global.
 struct ThreadLocalData {
   BufferQueue::Buffer Buffer;
   char *RecordPtr = nullptr;
   // The number of FunctionEntry records immediately preceding RecordPtr.
   uint8_t NumConsecutiveFnEnters = 0;
 
inline void writeTSCWrapMetadata(uint64_t TSC,
   TLD.NumConsecutiveFnEnters = 0;
   TLD.NumTailCalls = 0;
 }
 
 inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT {
   writeTSCWrapMetadata(TSC, getThreadLocalData().RecordPtr);
 }
 
-inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
+// Call Argument metadata records store the arguments to a function in the
+// order of their appearance; holes are not supported by the buffer format.
+static inline void writeCallArgumentMetadata(uint64_t A) XRAY_NEVER_INSTRUMENT {
+  auto &TLD = getThreadLocalData();
+  MetadataRecord CallArg;
+  CallArg.Type = uint8_t(RecordType::Metadata);
+  CallArg.RecordKind = uint8_t(MetadataRecord::RecordKinds::CallArgument);
+
+  std::memcpy(CallArg.Data, &A, sizeof(A));
+  std::memcpy(TLD.RecordPtr, &CallArg, sizeof(MetadataRecord));
+  TLD.RecordPtr += sizeof(MetadataRecord);
+}
+
+static inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
                                        XRayEntryType EntryType,
                                        char *&MemPtr) XRAY_NEVER_INSTRUMENT {
   std::aligned_storage<sizeof(FunctionRecord), alignof(FunctionRecord)>::type
       AlignedFuncRecordBuffer;
   auto &FuncRecord =
       *reinterpret_cast<FunctionRecord *>(&AlignedFuncRecordBuffer);
   FuncRecord.Type = uint8_t(RecordType::Function);
   // Only take 28 bits of the function id.
   FuncRecord.FuncId = FuncId & ~(0x0F << 28);
   FuncRecord.TSCDelta = TSCDelta;
if (TLD.CurrentCPU == std::numeric_limits<uint16_t>::max()) {
     // the current CPU and record this as the first TSC we've seen.
     TLD.CurrentCPU = CPU;
     writeNewCPUIdMetadata(CPU, TSC);
   }
 
   return true;
 } // namespace __xray_fdr_internal
 
+// Compute the TSC difference between the time of measurement and the previous
+// event. There are a few interesting situations we need to account for:
+//
+//   - The thread has migrated to a different CPU. If this is the case, then
+//     we write down the following records:
+//
+//       1. A 'NewCPUId' Metadata record.
+//       2. A FunctionRecord with a 0 for the TSCDelta field.
+//
+//   - The TSC delta is greater than the 32 bits we can store in a
+//     FunctionRecord. In this case we write down the following records:
+//
+//       1. A 'TSCWrap' Metadata record.
+//       2. A FunctionRecord with a 0 for the TSCDelta field.
+//
+//   - The TSC delta is representable within the 32 bits we can store in a
+//     FunctionRecord. In this case we write down just a FunctionRecord with
+//     the correct TSC delta.
+inline uint32_t writeCurrentCPUTSC(ThreadLocalData &TLD, uint64_t TSC, uint8_t CPU) {
+  if (CPU != TLD.CurrentCPU) {
+    // We've moved to a new CPU.
+    writeNewCPUIdMetadata(CPU, TSC);
+    return 0;
+  }
+  // If the delta is greater than the range for a uint32_t, then we write out
+  // the TSC wrap metadata entry with the full TSC, and the TSC for the
+  // function record be 0.
+  uint64_t Delta = TSC - TLD.LastTSC;
+  if (Delta <= std::numeric_limits<uint32_t>::max())
+    return Delta;
+
+  writeTSCWrapMetadata(TSC);
+  return 0;
+}
+
 inline void endBufferIfFull() XRAY_NEVER_INSTRUMENT {
   auto &TLD = getThreadLocalData();
   auto BufferStart = static_cast<char *>(TLD.Buffer.Buffer);
   if ((TLD.RecordPtr + MetadataRecSize) - BufferStart == MetadataRecSize) {
     writeEOBMetadata();
     if (!releaseThreadLocalBuffer(*TLD.LocalBQ))
       return;
     TLD.RecordPtr = nullptr;
   }
 }
 
 thread_local volatile bool Running = false;
 
+/// Here's where the meat of the processing happens. The writer captures
+/// function entry, exit and tail exit points with a time and will create
+/// TSCWrap, NewCPUId and Function records as necessary. The writer might
+/// walk backward through its buffer and erase trivial functions to avoid
+/// polluting the log and may use the buffer queue to obtain or release a
+/// buffer.
 inline void processFunctionHook(
     int32_t FuncId, XRayEntryType Entry, uint64_t TSC, unsigned char CPU,
-    int (*wall_clock_reader)(clockid_t, struct timespec *),
-    __sanitizer::atomic_sint32_t &LoggingStatus,
+    uint64_t Arg1, int (*wall_clock_reader)(clockid_t, struct timespec *),
     const std::shared_ptr<BufferQueue> &BQ) XRAY_NEVER_INSTRUMENT {
   // Prevent signal handler recursion, so in case we're already in a log writing
   // mode and the signal handler comes in (and is also instrumented) then we
   // don't want to be clobbering potentially partial writes already happening in
   // the thread. We use a simple thread_local latch to only allow one on-going
   // handleArg0 to happen at any given time.
   RecursionGuard Guard{Running};
   if (!Guard) {
inline void processFunctionHook(
   // that the record we are about to write is going to fit into the buffer,
   // without overflowing the buffer.
   //
   // To do this properly, we use the following assumptions:
   //
   //   - The least number of bytes we will ever write is 8
   //     (sizeof(FunctionRecord)) only if the delta between the previous entry
   //     and this entry is within 32 bits.
-  //   - The most number of bytes we will ever write is 8 + 16 = 24. This is
-  //     computed by:
+  //   - The most number of bytes we will ever write is 8 + 16 + 16 = 40.
+  //     This is computed by:
   //
-  //       sizeof(FunctionRecord) + sizeof(MetadataRecord)
+  //       MaxSize = sizeof(FunctionRecord) + 2 * sizeof(MetadataRecord)
   //
   //     These arise in the following cases:
   //
   //       1. When the delta between the TSC we get and the previous TSC for the
   //          same CPU is outside of the uint32_t range, we end up having to
   //          write a MetadataRecord to indicate a "tsc wrap" before the actual
   //          FunctionRecord.
   //       2. When we learn that we've moved CPUs, we need to write a
   //          MetadataRecord to indicate a "cpu change", and thus write out the
   //          current TSC for that CPU before writing out the actual
   //          FunctionRecord.
   //       3. When we learn about a new CPU ID, we need to write down a "new cpu
   //          id" MetadataRecord before writing out the actual FunctionRecord.
+  //       4. The second MetadataRecord is the optional function call argument.
   //
   //   - An End-of-Buffer (EOB) MetadataRecord is 16 bytes.
   //
   // So the math we need to do is to determine whether writing 24 bytes past the
   // current pointer leaves us with enough bytes to write the EOB
   // MetadataRecord. If we don't have enough space after writing as much as 24
   // bytes in the end of the buffer, we need to write out the EOB, get a new
   // Buffer, set it up properly before doing any further writing.
-  //
-  if (!prepareBuffer(wall_clock_reader, FunctionRecSize + MetadataRecSize)) {
+  size_t MaxSize = FunctionRecSize + 2 * MetadataRecSize;
+  if (!prepareBuffer(wall_clock_reader, MaxSize)) {
     TLD.LocalBQ = nullptr;
     return;
   }
 
-  // By this point, we are now ready to write at most 24 bytes (one metadata
-  // record and one function record).
-  assert((TLD.RecordPtr + (MetadataRecSize + FunctionRecSize)) -
-                 static_cast<char *>(TLD.Buffer.Buffer) >=
+  // By this point, we are now ready to write up to 40 bytes (explained above).
+  assert((TLD.RecordPtr + MaxSize) - static_cast<char *>(TLD.Buffer.Buffer) >=
              static_cast<ptrdiff_t>(MetadataRecSize) &&
          "Misconfigured BufferQueue provided; Buffer size not large enough.");
 
-  // Here we compute the TSC Delta. There are a few interesting situations we
-  // need to account for:
-  //
-  //   - The thread has migrated to a different CPU. If this is the case, then
-  //     we write down the following records:
-  //
-  //       1. A 'NewCPUId' Metadata record.
-  //       2. A FunctionRecord with a 0 for the TSCDelta field.
-  //
-  //   - The TSC delta is greater than the 32 bits we can store in a
-  //     FunctionRecord. In this case we write down the following records:
-  //
-  //       1. A 'TSCWrap' Metadata record.
-  //       2. A FunctionRecord with a 0 for the TSCDelta field.
-  //
-  //   - The TSC delta is representable within the 32 bits we can store in a
-  //     FunctionRecord. In this case we write down just a FunctionRecord with
-  //     the correct TSC delta.
-  //
-  uint32_t RecordTSCDelta = 0;
-  if (CPU != TLD.CurrentCPU) {
-    // We've moved to a new CPU.
-    writeNewCPUIdMetadata(CPU, TSC);
-  } else {
-    // If the delta is greater than the range for a uint32_t, then we write out
-    // the TSC wrap metadata entry with the full TSC, and the TSC for the
-    // function record be 0.
-    auto Delta = TSC - TLD.LastTSC;
-    if (Delta > (1ULL << 32) - 1)
-      writeTSCWrapMetadata(TSC);
-    else
-      RecordTSCDelta = Delta;
-  }
-
+  auto RecordTSCDelta = writeCurrentCPUTSC(TLD, TSC, CPU);
   TLD.LastTSC = TSC;
   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;
static bool Once = [&] {
       return true;
     }();
     (void)Once;
     return;
   }
   }
 
   writeFunctionRecord(FuncId, RecordTSCDelta, Entry, TLD.RecordPtr);
+  if (Entry == XRayEntryType::LOG_ARGS_ENTRY)
+    writeCallArgumentMetadata(Arg1);
 
   // If we've exhausted the buffer by this time, we then release the buffer to
   // make sure that other threads may start using this buffer.
   endBufferIfFull();
 }
 
 } // namespace __xray_fdr_internal
 } // namespace __xray
 
 #endif // XRAY_XRAY_FDR_LOGGING_IMPL_H

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

__xray_ArgLoggerEntry:
 
   // If [arg1 logging handler] not set, defer to no-arg logging.
   movq  _ZN6__xray19XRayPatchedFunctionE(%rip), %rax
   testq %rax, %rax
   je  .Larg1entryFail
 
 .Larg1entryLog:
 
-  // First argument will become the third
+  // First argument will become the third
   movq  %rdi, %rdx
 
-  // XRayEntryType::ENTRY into the second
-  xorq  %rsi, %rsi
+  // XRayEntryType::LOG_ARGS_ENTRY into the second
+  mov  $0x3, %esi
 
   // 32-bit function ID becomes the first
   movl  %r10d, %edi
   callq *%rax
 
 .Larg1entryFail:
   RESTORE_REGISTERS
   retq

compiler-rt/trunk/test/xray/TestCases/Linux/arg1-logger.cc

 
 [[clang::xray_always_instrument, clang::xray_log_args(1)]] void foo(void *) {}
 
 int main() {
   // CHECK: XRay: Log file in 'arg1-logger-{{.*}}'
 
   __xray_set_handler_arg1(arg1logger);
   foo(nullptr);
-  // CHECK: Arg1: 0, XRayEntryType 0
+  // CHECK: Arg1: 0, XRayEntryType 3
 
   __xray_remove_handler_arg1();
   foo((void *) 0xBADC0DE);
   // nothing expected to see here
 
   __xray_set_handler_arg1(arg1logger);
   foo((void *) 0xDEADBEEFCAFE);
-  // CHECK-NEXT: Arg1: deadbeefcafe, XRayEntryType 0
+  // CHECK-NEXT: Arg1: deadbeefcafe, XRayEntryType 3
   foo((void *) -1);
-  // CHECK-NEXT: Arg1: ffffffffffffffff, XRayEntryType 0
+  // CHECK-NEXT: Arg1: ffffffffffffffff, XRayEntryType 3
 }

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

 
 thread_local uint64_t var = 0;
 [[clang::xray_always_instrument]] void __attribute__((noinline)) fC() { ++var; }
 
 [[clang::xray_always_instrument]] void __attribute__((noinline)) fB() { fC(); }
 
 [[clang::xray_always_instrument]] void __attribute__((noinline)) fA() { fB(); }
 
+[[clang::xray_always_instrument, clang::xray_log_args(1)]]
+void __attribute__((noinline)) fArg(int) { }
+
 int main(int argc, char *argv[]) {
   using namespace __xray;
   FDRLoggingOptions Options;
   std::cout << "Logging before init." << std::endl;
   // CHECK: Logging before init.
   auto status = __xray_log_init(kBufferSize, kBufferMax, &Options,
                                 sizeof(FDRLoggingOptions));
   assert(status == XRayLogInitStatus::XRAY_LOG_INITIALIZED);
   std::cout << "Init status " << status << std::endl;
   // CHECK: Init status {{.*}}
   std::cout << "Patching..." << std::endl;
   // CHECK: Patching...
   __xray_patch();
   fA();
   fC();
   fB();
   fA();
   fC();
   std::thread other_thread([]() {
     fC();
     fB();
     fA();
+    fArg(1);
   });
   other_thread.join();
   std::cout << "Joined" << std::endl;
   // CHECK: Joined
   std::cout << "Finalize status " << __xray_log_finalize() << std::endl;
   // CHECK: Finalize status {{.*}}
   fC();
   std::cout << "Main execution var = " << var << std::endl;

 // 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|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|tail-exit}}, tsc: {{[0-9]+}} }
 
+// TRACE-DAG: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2]], kind: function-enter-arg, tsc: {{[0-9]+}} }
+// TRACE-DAG: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], kind: function-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
+// Even with a high threshold, arg1 logging is never unwritten.
+// UNWRITE: header:
+// UNWRITE: records:
+// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter-arg, tsc: {{[0-9]+}} }
+// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
 // UNWRITE-NOT: function-enter
 // UNWRITE-NOT: function-{{exit|tail-exit}}