[XRay] basic mode PID and TID always fetch

[Maknee]

Summary

XRayRecords now includes a PID field. Basic handlers fetch pid and tid each time they are called instead of caching the value. Added a testcase that calls fork and checks if the child TID is different from the parent TID to verify that the processes' TID are different in the trace.

[dberris]

Thanks @Maknee -- can you remove the 'TID' from thread-local data for basic mode logging to ensure that we've removed all references to it?

[dberris]

compiler-rt/lib/xray/xray_basic_logging.cc

231 ↗

(On Diff #154407)

Can you use internal_getpid() instead?

[Maknee]

• Merge branch 'master' of https://github.com/llvm-project/llvm-project-20170507 into UpdateBasicLoggingPidAndTid

[Maknee]

Updating D49025: [XRay] basic mode PID and TID always fetch

Accidently added changes from different diff containing fdr changes

[Maknee]

Replaced getpid() with internal_getpid(). Removed TID field from TLD and removed references to the TID field.

[dberris]

LGTM, with one minor comment.

Please let me know if/when it's ready to land, so that either I or @kpw can land it for you.

Thanks!

Cheers

compiler-rt/include/xray/xray_records.h

99 ↗

(On Diff #154641)

Minor: Maybe name this PId to be consistent with TId.

[Maknee]

Changed Pid to PId in XRayRecord

[Maknee]

Ready to land

[krytarowski]

This test seems to have a Linux assumption and I have concerns how to port it to NetBSD.

On NetBSD TIDs start from 1 to N in each process. Each process has a single distinct PID. TID numbers are not unique between processes (they are unique only within a process). PID numbers are unique.

On Linux TID is effectively PID and this is linuxism.

[dberris]

In D49025#1288182, @krytarowski wrote:

This test seems to have a Linux assumption and I have concerns how to port it to NetBSD.

On NetBSD TIDs start from 1 to N in each process. Each process has a single distinct PID. TID numbers are not unique between processes (they are unique only within a process). PID numbers are unique.

On Linux TID is effectively PID and this is linuxism.

Right, I'm missing the concern here -- the change actually records both PID and TID by getting them regularly instead of caching them at the start of the thread.

Does this fail in NetBSD and if it does, what is the failure mode?

[krytarowski]

In this test parent_tid = 1, child_tid = 1 always and distinguishing this way child and parent is broken. Switching syscall_gettid() to behave like getpid() is not sufficient as the test has assumptions that thread is like pid.

$ /public/llvm-build/./bin/llvm-xray convert --symbolize --output-format=yaml -instr_map=/public/llvm-build/projects/compiler-rt/test/xray/X86_64NetBSDConfig/TestCases/Posix/Output/fork_basic_logging.cc.tmp      "`ls -S fork-basic-logging-test-* | head -1`"      | ./bin/FileCheck /public/compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc --check-prefix=TRACE
---
header:          
  version:         3
  type:            0
  constant-tsc:    true
  nonstop-tsc:     true
  cycle-frequency: 3392489040
records:         
  - { type: 0, func-id: 1, function: 'log_syscall_gettid()', cpu: 0, thread: 1, process: 6843, kind: function-enter, tsc: 4422386299208 }
  - { type: 0, func-id: 1, function: 'log_syscall_gettid()', cpu: 0, thread: 1, process: 6843, kind: function-enter, tsc: 4422386299208 }
  - { type: 0, func-id: 1, function: 'log_syscall_gettid()', cpu: 0, thread: 1, process: 6843, kind: function-exit, tsc: 4422386409791 }
  - { type: 0, func-id: 1, function: 'log_syscall_gettid()', cpu: 0, thread: 1, process: 6843, kind: function-exit, tsc: 4422386409791 }
  - { type: 0, func-id: 4, function: 'print_parent_or_child()', cpu: 0, thread: 1, process: 6843, kind: function-enter, tsc: 4422386596150 }
  - { type: 0, func-id: 2, function: 'print_parent_tid(unsigned long)', args: [ 6843 ], cpu: 0, thread: 1, process: 6843, kind: function-enter-arg, tsc: 4422386614652 }
  - { type: 0, func-id: 2, function: 'print_parent_tid(unsigned long)', cpu: 0, thread: 1, process: 6843, kind: function-exit, tsc: 4422386648144 }
  - { type: 0, func-id: 4, function: 'print_parent_or_child()', cpu: 0, thread: 1, process: 6843, kind: function-exit, tsc: 4422386648972 }
  - { type: 0, func-id: 4, function: 'print_parent_or_child()', cpu: 0, thread: 1, process: 14316, kind: function-enter, tsc: 4422387049656 }
  - { type: 0, func-id: 3, function: 'print_child_tid(unsigned long)', args: [ 14316 ], cpu: 0, thread: 1, process: 14316, kind: function-enter-arg, tsc: 4422387125834 }
  - { type: 0, func-id: 3, function: 'print_child_tid(unsigned long)', cpu: 0, thread: 1, process: 14316, kind: function-exit, tsc: 4422387294637 }
  - { type: 0, func-id: 4, function: 'print_parent_or_child()', cpu: 0, thread: 1, process: 14316, kind: function-exit, tsc: 4422387295979 }
...

/public/compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc:94:15: error: TRACE-DAG: expected string not found in input
// TRACE-DAG: - { type: 0, func-id: [[PPTARG:[0-9]+]], function: {{.*print_parent_tid.*}}, args: [ [[THREAD1]] ], cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS1]], kind: function-enter-arg, tsc: {{[0-9]+}} }
              ^
<stdin>:1:1: note: scanning from here
---
^
<stdin>:1:1: note: with variable "THREAD1" equal to "1"
---
^
<stdin>:1:1: note: with variable "THREAD1" equal to "1"
---
^
<stdin>:1:1: note: with variable "PROCESS1" equal to "6843"
---
^

I've marked this test as UNSUPPORTED for NetBSD. It would be nice to keep a test for TID that is portable, but it would need significant rewrite.

[dberris]

Aha! Right, I think the test is wrong indeed. We shouldn't be assuming that the tid == pid in the test, when recording the first argument for the thread id, and rather be calling the correct function for getting the thread id all the time.

include/xray/xray_records.h

struct alignas(32) XRayRecord {
   int32_t FuncId = 0;
 
   // 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.
   uint32_t TId = 0;
 
+  // The ID of process that is currently running
+  uint32_t PId = 0;
+  
   // Use some bytes in the end of the record for buffers.
-  char Buffer[12] = {};
+  char Buffer[8] = {};
 } __attribute__((packed));
 
 static_assert(sizeof(XRayRecord) == 32, "XRayRecord != 32 bytes");
 
 struct alignas(32) XRayArgPayload {
   // We use the same 16 bits as a discriminant for the records in the log here
   // too, and so that the first 4 bytes are packed properly.
   uint16_t RecordType = RecordTypes::ARG_PAYLOAD;
 
   // Add a few bytes to pad.
   uint8_t Padding[2] = {};
 
   // The function ID for the record.
   int32_t FuncId = 0;
 
   // The thread ID for the currently running thread.
   uint32_t TId = 0;
 
-  // Add more padding.
-  uint8_t Padding2[4] = {};
+  // The ID of process that is currently running
+  uint32_t PId = 0;
 
   // The argument payload.
   uint64_t Arg = 0;
 
   // The rest of this record ought to be left as padding.
   uint8_t TailPadding[8] = {};
 } __attribute__((packed));
 
 static_assert(sizeof(XRayArgPayload) == 32, "XRayArgPayload != 32 bytes");
 
 } // namespace __xray
 
 #endif // XRAY_XRAY_RECORDS_H

lib/xray/xray_basic_logging.cc

 struct alignas(64) ThreadLocalData {
   void *InMemoryBuffer = nullptr;
   size_t BufferSize = 0;
   size_t BufferOffset = 0;
   void *ShadowStack = nullptr;
   size_t StackSize = 0;
   size_t StackEntries = 0;
   int Fd = -1;
-  tid_t TID = 0;
 };
 
 static pthread_key_t PThreadKey;
 
 static atomic_uint8_t BasicInitialized{0};
 
 BasicLoggingOptions GlobalOptions;
 

 static ThreadLocalData &getThreadLocalData() XRAY_NEVER_INSTRUMENT {
   thread_local ThreadLocalData TLD;
   thread_local bool UNUSED TOnce = [] {
     if (GlobalOptions.ThreadBufferSize == 0) {
       if (Verbosity())
         Report("Not initializing TLD since ThreadBufferSize == 0.\n");
       return false;
     }
-    TLD.TID = GetTid();
     pthread_setspecific(PThreadKey, &TLD);
     TLD.Fd = getGlobalFd();
     TLD.InMemoryBuffer = reinterpret_cast<XRayRecord *>(
         InternalAlloc(sizeof(XRayRecord) * GlobalOptions.ThreadBufferSize,
                       nullptr, alignof(XRayRecord)));
     TLD.BufferSize = GlobalOptions.ThreadBufferSize;
     TLD.BufferOffset = 0;
     if (GlobalOptions.MaxStackDepth == 0) {
void InMemoryRawLog(int32_t FuncId, XRayEntryType Type,
   }
 
   // First determine whether the delta between the function's enter record and
   // the exit record is higher than the threshold.
   XRayRecord R;
   R.RecordType = RecordTypes::NORMAL;
   R.CPU = CPU;
   R.TSC = TSC;
-  R.TId = TLD.TID;
+  R.TId = GetTid(); 
+  R.PId = internal_getpid(); 
   R.Type = Type;
   R.FuncId = FuncId;
   auto FirstEntry = reinterpret_cast<XRayRecord *>(TLD.InMemoryBuffer);
   internal_memcpy(FirstEntry + TLD.BufferOffset, &R, sizeof(R));
   if (++TLD.BufferOffset == TLD.BufferSize) {
     SpinMutexLock L(&LogMutex);
     retryingWriteAll(Fd, reinterpret_cast<char *>(FirstEntry),
                      reinterpret_cast<char *>(FirstEntry + TLD.BufferOffset));
void InMemoryRawLogWithArg(int32_t FuncId, XRayEntryType Type, uint64_t Arg1,
   RecursionGuard G(Guard);
   if (!G)
     return;
 
   // And from here on write the arg payload.
   XRayArgPayload R;
   R.RecordType = RecordTypes::ARG_PAYLOAD;
   R.FuncId = FuncId;
-  R.TId = TLD.TID;
+  R.TId = GetTid(); 
+  R.PId = internal_getpid(); 
   R.Arg = Arg1;
   internal_memcpy(FirstEntry + TLD.BufferOffset, &R, sizeof(R));
   if (++TLD.BufferOffset == BuffLen) {
     SpinMutexLock L(&LogMutex);
     retryingWriteAll(Fd, reinterpret_cast<char *>(FirstEntry),
                      reinterpret_cast<char *>(FirstEntry + TLD.BufferOffset));
     TLD.BufferOffset = 0;
     TLD.StackEntries = 0;
static void TLDDestructor(void *P) XRAY_NEVER_INSTRUMENT {
   ThreadLocalData &TLD = *reinterpret_cast<ThreadLocalData *>(P);
   auto ExitGuard = at_scope_exit([&TLD] {
     // Clean up dynamic resources.
     if (TLD.InMemoryBuffer)
       InternalFree(TLD.InMemoryBuffer);
     if (TLD.ShadowStack)
       InternalFree(TLD.ShadowStack);
     if (Verbosity())
-      Report("Cleaned up log for TID: %d\n", TLD.TID);
+      Report("Cleaned up log for TID: %d\n", GetTid());
   });
 
   if (TLD.Fd == -1 || TLD.BufferOffset == 0) {
     if (Verbosity())
-      Report("Skipping buffer for TID: %d; Fd = %d; Offset = %llu\n", TLD.TID,
+      Report("Skipping buffer for TID: %d; Fd = %d; Offset = %llu\n", GetTid(),
              TLD.Fd, TLD.BufferOffset);
     return;
   }
 
   {
     SpinMutexLock L(&LogMutex);
     retryingWriteAll(TLD.Fd, reinterpret_cast<char *>(TLD.InMemoryBuffer),
                      reinterpret_cast<char *>(TLD.InMemoryBuffer) +

test/xray/TestCases/Posix/fork_basic_logging.cc

+// Check that when forking in basic logging mode, we get the different tids for child and parent
+// RUN: %clangxx_xray -g -std=c++11 %s -o %t
+// RUN: rm -f fork-basic-logging-test-*
+// RUN: XRAY_OPTIONS="patch_premain=true xray_logfile_base=fork-basic-logging-test- \
+// RUN:     xray_mode=xray-basic verbosity=1" \
+// RUN:     %run %t 2>&1 | FileCheck %s
+// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \
+// RUN:     "`ls -S fork-basic-logging-test-* | head -1`" \
+// RUN:     | FileCheck %s --check-prefix=TRACE
+
+// REQUIRES: x86_64-target-arch
+// REQUIRES: built-in-llvm-tree
+
+#include "xray/xray_log_interface.h"
+#include <stdio.h>
+#include <unistd.h>
+#include <stdint.h>
+#include <sys/syscall.h>
+
+//modified from sanitizer
+
+static uintptr_t syscall_gettid() {
+  uint64_t retval;
+  asm volatile("syscall" : "=a"(retval) : "a"(__NR_gettid) : "rcx", "r11",
+               "memory", "cc");
+  return retval;
+}
+
+/////////////
+
+static uint64_t parent_tid;
+
+[[clang::xray_always_instrument]]
+uint64_t __attribute__((noinline)) log_syscall_gettid()
+{
+  //don't optimize this function away
+  uint64_t tid = syscall_gettid();
+  printf("Logging tid %lu\n", tid);
+  return tid;
+}
+
+[[clang::xray_always_instrument, clang::xray_log_args(1)]]
+void __attribute__((noinline)) print_parent_tid(uint64_t tid)
+{
+  printf("Parent with tid %lu", tid);
+}
+
+[[clang::xray_always_instrument, clang::xray_log_args(1)]]
+void __attribute__((noinline)) print_child_tid(uint64_t tid)
+{
+  printf("Child with tid %lu", tid);
+}
+
+[[clang::xray_always_instrument]] void __attribute__((noinline)) print_parent_or_child()
+{
+  uint64_t tid = syscall_gettid();
+  if(tid == parent_tid)
+  {
+    print_parent_tid(tid);
+  }
+  else
+  {
+    print_child_tid(tid);
+  }
+}
+
+int main()
+{
+  parent_tid = log_syscall_gettid();
+  if(fork())
+  {
+    print_parent_or_child();
+      // CHECK: Parent with tid
+  }
+  else
+  {
+    print_parent_or_child();
+      // CHECK: Child with tid
+  }
+  return 0;
+}
+
+// Make sure we know which thread is the parent process
+// TRACE-DAG: - { type: 0, func-id: [[LSGT:[0-9]+]], function: {{.*log_syscall_gettid.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
+
+// TRACE-DAG: - { type: 0, func-id: [[PPOC:[0-9]+]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-enter, tsc: {{[0-9]+}} }
+//
+// The parent will print its pid first
+// TRACE-DAG: - { type: 0, func-id: [[PPTARG:[0-9]+]], function: {{.*print_parent_tid.*}}, args: [ [[THREAD1]] ], cpu: {{.*}}, thread: [[THREAD1]], kind: function-enter-arg, tsc: {{[0-9]+}} }
+// TRACE-DAG: - { type: 0, func-id: [[PPTARG]], function: {{.*print_parent_tid.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
+//
+// TRACE:     - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }
+
+// TRACE-DAG: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
+//
+// The child will print its pid now
+// TRACE-DAG: - { type: 0, func-id: [[PCTARG:[0-9]+]], function: {{.*print_child_tid.*}}, args: [ [[THREAD2]] ], cpu: {{.*}}, thread: [[THREAD2]], kind: function-enter-arg, tsc: {{[0-9]+}} }
+// TRACE-DAG: - { type: 0, func-id: [[PCTARG]], function: {{.*print_child_tid.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
+//
+// TRACE:     - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} }