[XRay] basic mode PID and TID always fetch

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.

Reviewers: dberris, Maknee

Reviewed By: dberris, Maknee

Subscribers: kpw, llvm-commits, #sanitizers

Differential Revision: https://reviews.llvm.org/D49025

llvm-svn: 336769

diff --git a/compiler-rt/include/xray/xray_records.h b/compiler-rt/include/xray/xray_records.h
index 2b415bb..8cfdeee 100644 (file)
--- a/compiler-rt/include/xray/xray_records.h
+++ b/compiler-rt/include/xray/xray_records.h
@@ -95,8 +95,11 @@ struct alignas(32) XRayRecord {
   // 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");
@@ -115,8 +118,8 @@ struct alignas(32) XRayArgPayload {
   // 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;

diff --git a/compiler-rt/lib/xray/xray_basic_logging.cc b/compiler-rt/lib/xray/xray_basic_logging.cc
index 138679d..529fde8 100644 (file)
--- a/compiler-rt/lib/xray/xray_basic_logging.cc
+++ b/compiler-rt/lib/xray/xray_basic_logging.cc
@@ -60,7 +60,6 @@ struct alignas(64) ThreadLocalData {
   size_t StackSize = 0;
   size_t StackEntries = 0;
   int Fd = -1;
-  tid_t TID = 0;
 };
 
 static pthread_key_t PThreadKey;
@@ -119,7 +118,6 @@ static ThreadLocalData &getThreadLocalData() XRAY_NEVER_INSTRUMENT {
         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 *>(
@@ -227,7 +225,8 @@ void InMemoryRawLog(int32_t FuncId, XRayEntryType Type,
   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);
@@ -274,7 +273,8 @@ void InMemoryRawLogWithArg(int32_t FuncId, XRayEntryType Type, uint64_t Arg1,
   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) {
@@ -334,12 +334,12 @@ static void TLDDestructor(void *P) XRAY_NEVER_INSTRUMENT {
     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;
   }

diff --git a/compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc b/compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc
new file mode 100644 (file)
index 0000000..414fc32
--- /dev/null
+++ b/compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc
@@ -0,0 +1,100 @@
+// 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]+}} }