1 // RUN: %clangxx_xray -g -std=c++11 %s -o %t 2 // RUN: rm -f fdr-logging-test-* 3 // RUN: rm -f fdr-unwrite-test-* 4 // RUN: XRAY_OPTIONS="patch_premain=false xray_logfile_base=fdr-logging-test- \ 5 // RUN: xray_mode=xray-fdr verbosity=1" \ 6 // RUN: XRAY_FDR_OPTIONS="func_duration_threshold_us=0" \ 7 // RUN: %run %t 2>&1 | FileCheck %s 8 // RUN: XRAY_OPTIONS="patch_premain=false \ 9 // RUN: xray_logfile_base=fdr-unwrite-test- xray_mode=xray-fdr \ 10 // RUN: verbosity=1" \ 11 // RUN: XRAY_FDR_OPTIONS="func_duration_threshold_us=5000" \ 12 // RUN: %run %t 2>&1 | FileCheck %s 13 // RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \ 14 // RUN: "`ls fdr-logging-test-* | head -1`" \ 15 // RUN: | FileCheck %s --check-prefix=TRACE 16 // RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \ 17 // RUN: "`ls fdr-unwrite-test-* | head -1`" \ 18 // RUN: | FileCheck %s --check-prefix=UNWRITE 19 // RUN: rm fdr-logging-test-* 20 // RUN: rm fdr-unwrite-test-* 21 // FIXME: Make llvm-xray work on non-x86_64 as well. 22 // REQUIRES: x86_64-target-arch 23 // REQUIRES: built-in-llvm-tree 24 25 #include "xray/xray_log_interface.h" 26 #include <cassert> 27 #include <chrono> 28 #include <cstdio> 29 #include <iostream> 30 #include <stdlib.h> 31 #include <thread> 32 #include <time.h> 33 34 thread_local uint64_t var = 0; 35 [[clang::xray_always_instrument]] void __attribute__((noinline)) fC() { ++var; } 36 37 [[clang::xray_always_instrument]] void __attribute__((noinline)) fB() { fC(); } 38 39 [[clang::xray_always_instrument]] void __attribute__((noinline)) fA() { fB(); } 40 41 [[clang::xray_always_instrument, clang::xray_log_args(1)]] 42 void __attribute__((noinline)) fArg(int) { } 43 44 int main(int argc, char *argv[]) { 45 std::cout << "Logging before init." << std::endl; 46 // CHECK: Logging before init. 47 assert(__xray_log_select_mode("xray-fdr") == 48 XRayLogRegisterStatus::XRAY_REGISTRATION_OK); 49 auto status = 50 __xray_log_init_mode("xray-fdr", "buffer_size=16384:buffer_max=10"); 51 assert(status == XRayLogInitStatus::XRAY_LOG_INITIALIZED); 52 std::cout << "Init status " << status << std::endl; 53 // CHECK: Init status {{.*}} 54 std::cout << "Patching..." << std::endl; 55 // CHECK: Patching... 56 __xray_patch(); 57 fA(); 58 fC(); 59 fB(); 60 fA(); 61 fC(); 62 std::thread other_thread([]() { 63 fC(); 64 fB(); 65 fA(); 66 fArg(1); 67 }); 68 other_thread.join(); 69 std::cout << "Joined" << std::endl; 70 // CHECK: Joined 71 std::cout << "Finalize status " << __xray_log_finalize() << std::endl; 72 // CHECK: Finalize status {{.*}} 73 fC(); 74 std::cout << "Main execution var = " << var << std::endl; 75 // CHECK: Main execution var = 6 76 std::cout << "Flush status " << __xray_log_flushLog() << std::endl; 77 // CHECK: Flush status {{.*}} 78 __xray_unpatch(); 79 return 0; 80 } 81 82 // Check that we're able to see two threads, each entering and exiting fA(). 83 // TRACE-DAG: - { type: 0, func-id: [[FIDA:[0-9]+]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}}, data: '' } 84 // TRACE: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}}, data: '' } 85 // TRACE-DAG: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}}, data: '' } 86 // TRACE: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}}, data: '' } 87 // 88 // Do the same as above for fC() 89 // TRACE-DAG: - { type: 0, func-id: [[FIDC:[0-9]+]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}}, data: '' } 90 // TRACE: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}}, data: '' } 91 // TRACE-DAG: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}}, data: '' } 92 // TRACE: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}}, data: '' } 93 94 // Do the same as above for fB() 95 // TRACE-DAG: - { type: 0, func-id: [[FIDB:[0-9]+]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}}, data: '' } 96 // TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}}, data: '' } 97 // TRACE-DAG: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}}, data: '' } 98 // TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}}, data: '' } 99 100 // TRACE-DAG: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-enter-arg, tsc: {{[0-9]+}}, data: '' } 101 // TRACE-DAG: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-exit, tsc: {{[0-9]+}}, data: '' } 102 103 // 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 104 // is unlikely given the test program. 105 // Even with a high threshold, arg1 logging is never unwritten. 106 // UNWRITE: header: 107 // UNWRITE: records: 108 // UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-enter-arg, tsc: {{[0-9]+}}, data: '' } 109 // UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-exit, tsc: {{[0-9]+}}, data: '' } 110 // UNWRITE-NOT: function-enter 111 // UNWRITE-NOT: function-{{exit|tail-exit}} 112