[XRay][compiler-rt] Use llvm-xray in FDR mode tests

[dberris]

Summary

This change allows us to do an end-to-end test of the FDR mode
implementation that uses the llvm-xray tooling to verify that what we
are both writing and reading the data in a consistent manner.

[kpw]

LGTM

1. Do these run as part of the "check-xray" target?
2. We should update these to set the function time threshold flag to zero when we merge the unwriting patch in.

I volunteer to write a few supplemental test cases when that lands.

• Sets the threshold very high and checks that no functions appear in the log.
• Sets the threshold high, but have some functions that sleep. Check that invocations are erased when it makes sense and remain when eligible.

[dberris]

In D31454#713302, @kpw wrote:

LGTM

1. Do these run as part of the "check-xray" target?

Yes. :)

2. We should update these to set the function time threshold flag to zero when we merge the unwriting patch in.

Agreed.

I volunteer to write a few supplemental test cases when that lands.

• Sets the threshold very high and checks that no functions appear in the log.
• Sets the threshold high, but have some functions that sleep. Check that invocations are erased when it makes sense and remain when eligible.

Those sound like perfect individual tests to run indeed. :)

[eugenis]

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

3

ls fdr-thread-order.* | head -1

How is that supposed to work?

This test never cleans old logs, so they just accumulate in the current directory, and then this line picks one basically at random.

[dberris]

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

3

The line after should take care of that, except for when the tests start failing. I've not found a way with lit to determine a cleanup mechanism that isn't order-dependent -- is there a feature that's useful there? Or is there a better way of spelling this so that the cleanup happens reliably?

[eugenis]

Oh. For some reason when I run it with manually with llvm-lit the temporary files keeping piling up in $PWD.

[dberris]

If that line fails, then yes it will start piling up and never get cleaned up. :(

[eugenis]

Somehow I don't see the problem any longer.
Anyway, if the cleanup is moved to the beginning of the test, stale logs would not affect future test runs.

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

-// RUN: %clangxx_xray -std=c++11 %s -o %t
+// RUN: %clangxx_xray -g -std=c++11 %s -o %t
 // RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-logging-test- xray_fdr_log=true verbosity=1" %run %t 2>&1 | FileCheck %s
-// FIXME: %llvm_xray convert -instr_map=%t "`ls fdr-logging-test-* | head -1`" | FileCheck %s --check-prefix TRACE
+// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t "`ls fdr-logging-test-* | head -1`" | FileCheck %s --check-prefix TRACE
 // RUN: rm fdr-logging-test-*
 
 #include "xray/xray_log_interface.h"
 #include <cassert>
 #include <chrono>
 #include <cstdio>
 #include <iostream>
 #include <stdlib.h>
int main(int argc, char *argv[]) {
   std::cout << "Main execution var = " << var << std::endl;
   // CHECK: Main execution var = 6
   std::cout << "Flush status " << __xray_log_flushLog() << std::endl;
   // CHECK: Flush status {{.*}}
   __xray_unpatch();
   return 0;
 }
 
-// TRACE: { function }
+
+
+// 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-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]+}} }
+//
+// 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-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]+}} }
+
+// 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-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]+}} }

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

+// RUN: %clangxx_xray -g -std=c++11 %s -o %t
+// RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-thread-order. xray_fdr_log=true verbosity=1" %run %t 2>&1 | FileCheck %s
+// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t "`ls fdr-thread-order.* | head -1`" | FileCheck %s --check-prefix TRACE
+// RUN: rm fdr-thread-order.*
+#include "xray/xray_log_interface.h"
+#include <thread>
+#include <cassert>
+
+constexpr auto kBufferSize = 16384;
+constexpr auto kBufferMax = 10;
+
+thread_local uint64_t var = 0;
+[[clang::xray_always_instrument]] void __attribute__((noinline)) f1() { ++var; }
+[[clang::xray_always_instrument]] void __attribute__((noinline)) f2() { ++var; }
+
+int main(int argc, char *argv[]) {
+  using namespace __xray;
+  FDRLoggingOptions Options;
+  assert(__xray_log_init(kBufferSize, kBufferMax, &Options,
+                         sizeof(FDRLoggingOptions)) ==
+         XRayLogInitStatus::XRAY_LOG_INITIALIZED);
+  __xray_patch();
+  std::thread t1([] { f1(); });
+  std::thread t2([] { f2(); });
+  t1.join();
+  t2.join();
+  __xray_log_finalize();
+  __xray_log_flushLog();
+  // CHECK: =={{[0-9]+}}==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]+}} }