[llvm-dev] XRay FDR mode doesn’t log main thread calls

Henry Zhu via llvm-dev llvm-dev at lists.llvm.org
Fri Jun 8 13:23:29 PDT 2018


Hello,



I am initializing FDR mode and finalizing/flushing the buffers manually.
XRay does not log calls from the main thread unless there is a function
call after __xray_log_finalize(). This behavior is abnormal since one would
expect the trace file to contain all function calls made up to the point
when __xray_log_finalize() is called. To demonstrate this behavior, I have
taken the test case from TestCases/Posix and modified it.



I am running Ubuntu 16.04.1 on a x86_64 machine and am using clang 7.0.

henry at OptiPlex-9010:~$ uname -a

Linux OptiPlex-9010 4.13.0-43-generic #48~16.04.1-Ubuntu SMP Thu May 17
12:56:46 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux



I will demonstrate the behavior mentioned above by displaying the result
from the test file and then the result from modifying the fdr-mode.cc test
provided in the TestCases/Posix directory.



====UNMODIFIED fdr-mode.cc====



./clang++ -fxray-instrument fdr-mode.cc -o fdr-mode



XRAY_OPTIONS="patch_premain=false xray_mode=xray-fdr verbosity=1"
XRAY_FDR_OPTIONS="func_duration_thr eshold_us=0" ./fdr-mode

Logging before init.

==31756==Initializing FDR mode with options: buffer_size=16384:buffer_max=10

==31756==XRay FDR init successful.

Init status 2

Patching...

Joined

Finalize status 4

Main execution var = 6

==31756==XRay: Log file in 'xray-log.fdr-mode.Xubrrm'

Flush status 2



henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./llvm-xray
convert  -f yaml -symbolize -instr_map=./fdr-mode xray-log.fdr-mode.Xubrrm

---

header:

  version:         2

  type:            1

  constant-tsc:    true

  nonstop-tsc:     true

  cycle-frequency: 3400000000

records:

  - { type: 0, func-id: 3, function: 'fA()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956329578 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956357542 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956358238 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956358730 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956412062 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956412434 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956412734 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956413034 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956413422 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956413686 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956413906 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956414154 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956414378 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956414638 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956414878 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956415094 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956415338 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956415550 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-enter, tsc: 4955892956415774 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 2, thread: 31756, kind:
function-exit, tsc: 4955892956416022 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 0, thread: 31757, kind:
function-enter, tsc: 4955892956513912 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 0, thread: 31757, kind:
function-exit, tsc: 4955892956521160 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 0, thread: 31757, kind:
function-enter, tsc: 4955892956521896 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 0, thread: 31757, kind:
function-enter, tsc: 4955892956522296 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 0, thread: 31757, kind:
function-exit, tsc: 4955892956522520 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 0, thread: 31757, kind:
function-exit, tsc: 4955892956522804 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 0, thread: 31757, kind:
function-enter, tsc: 4955892956523144 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 0, thread: 31757, kind:
function-enter, tsc: 4955892956523424 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 0, thread: 31757, kind:
function-enter, tsc: 4955892956523672 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 0, thread: 31757, kind:
function-exit, tsc: 4955892956523896 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 0, thread: 31757, kind:
function-exit, tsc: 4955892956524172 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 0, thread: 31757, kind:
function-exit, tsc: 4955892956524424 }

  - { type: 0, func-id: 4, function: 'fArg(int)', args: [ 1 ], cpu: 0,
thread: 31757, kind: function-enter-arg, tsc: 4955892956525092 }

  - { type: 0, func-id: 4, function: 'fArg(int)', cpu: 0, thread: 31757,
kind: function-exit, tsc: 4955892956527200 }

...



The logger prints out “==31756==XRay: Log file in
'xray-log.fdr-mode.Xubrrm'” and there is a TID associated with the main
thread in the trace file. However, in the modified fdr-mode.cc shown below,
the trace does not report the main thread’s id.



=====MODIFIED fdr-mode.cc======

The only change I made was commenting out the call to fC() on line 74
before the call to  std::cout << "Main execution var = " << var <<
std::endl;



// RUN: %clangxx_xray -g -std=c++11 %s -o %t

// RUN: rm fdr-logging-test-* || true

// RUN: rm fdr-unwrite-test-* || true

// RUN: XRAY_OPTIONS="patch_premain=false
xray_logfile_base=fdr-logging-test- \

// RUN:     xray_mode=xray-fdr verbosity=1" \

// RUN: XRAY_FDR_OPTIONS="func_duration_threshold_us=0" \

// RUN:     %run %t 2>&1 | FileCheck %s

// RUN: XRAY_OPTIONS="patch_premain=false \

// RUN:     xray_logfile_base=fdr-unwrite-test- xray_mode=xray-fdr \

// RUN:     verbosity=1" \

// RUN: XRAY_FDR_OPTIONS="func_duration_threshold_us=5000" \

// RUN:     %run %t 2>&1 | FileCheck %s

// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \

// RUN:     "`ls fdr-logging-test-* | head -1`" \

// RUN:     | FileCheck %s --check-prefix=TRACE

// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \

// RUN:     "`ls fdr-unwrite-test-* | head -1`" \

// RUN:     | FileCheck %s --check-prefix=UNWRITE

// RUN: rm fdr-logging-test-*

// RUN: rm fdr-unwrite-test-*

// FIXME: Make llvm-xray work on non-x86_64 as well.

// REQUIRES: x86_64-target-arch

// REQUIRES: built-in-llvm-tree



#include "xray/xray_log_interface.h"

#include <cassert>

#include <chrono>

#include <cstdio>

#include <iostream>

#include <stdlib.h>

#include <thread>

#include <time.h>



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;

  std::cout << "Logging before init." << std::endl;

  // CHECK: Logging before init.

  assert(__xray_log_select_mode("xray-fdr") ==

         XRayLogRegisterStatus::XRAY_REGISTRATION_OK);

  auto status =

      __xray_log_init_mode("xray-fdr", "buffer_size=16384:buffer_max=10");

  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;

  // CHECK: Main execution var = 6

  std::cout << "Flush status " << __xray_log_flushLog() << std::endl;

  // CHECK: Flush status {{.*}}

  __xray_unpatch();

  return 0;

}



// 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|tail-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|tail-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|tail-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|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.

// 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}}



henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++
-fxray-instrument fdr-mode.cc -o fdr-mode



henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=false xray_mode=xray-fdr verbosity=1"
XRAY_FDR_OPTIONS="func_duration_threshold_us=0" ./fdr-mode

Logging before init.

==31823==Initializing FDR mode with options: buffer_size=16384:buffer_max=10

==31823==XRay FDR init successful.

Init status 2

Patching...

Joined

Finalize status 4

Main execution var = 5

==31823==XRay: Log file in 'xray-log.fdr-mode.2RGxtt'

Flush status 2





henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./llvm-xray
convert  -f yaml -symbolize -instr_map=./fdr-mode xray-log.fdr-mode.2RGxtt

---

header:

  version:         2

  type:            1

  constant-tsc:    true

  nonstop-tsc:     true

  cycle-frequency: 3400000000

records:

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352650592 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352650592 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352656724 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352656724 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352657480 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352657480 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352657936 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352657936 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352658164 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352658164 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352658432 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352658432 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352658748 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352658748 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352659040 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352659040 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352659288 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-enter, tsc: 4956245352659288 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352659516 }

  - { type: 0, func-id: 1, function: 'fC()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352659516 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352659796 }

  - { type: 0, func-id: 2, function: 'fB()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352659796 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352660052 }

  - { type: 0, func-id: 3, function: 'fA()', cpu: 3, thread: 31824, kind:
function-exit, tsc: 4956245352660052 }

  - { type: 0, func-id: 4, function: 'fArg(int)', args: [ 1 ], cpu: 3,
thread: 31824, kind: function-enter-arg, tsc: 4956245352661192 }

  - { type: 0, func-id: 4, function: 'fArg(int)', args: [ 1 ], cpu: 3,
thread: 31824, kind: function-enter-arg, tsc: 4956245352661192 }

  - { type: 0, func-id: 4, function: 'fArg(int)', cpu: 3, thread: 31824,
kind: function-exit, tsc: 4956245352663520 }

  - { type: 0, func-id: 4, function: 'fArg(int)', cpu: 3, thread: 31824,
kind: function-exit, tsc: 4956245352663520 }

...



The logger reports “==31823==XRay: Log file in 'xray-log.fdr-mode.2RGxtt'”,
but there’s no TID associated with the main thread in the trace compared to
the trace generated with the call to fC().



Is this expected behavior?



I have included the file as an attachment below.

Thanks,

Henry
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/llvm-dev/attachments/20180608/8152d0de/attachment.html>
-------------- next part --------------
// RUN: %clangxx_xray -g -std=c++11 %s -o %t
// RUN: rm fdr-logging-test-* || true
// RUN: rm fdr-unwrite-test-* || true
// RUN: XRAY_OPTIONS="patch_premain=false xray_logfile_base=fdr-logging-test- \
// RUN:     xray_mode=xray-fdr verbosity=1" \
// RUN: XRAY_FDR_OPTIONS="func_duration_threshold_us=0" \
// RUN:     %run %t 2>&1 | FileCheck %s
// RUN: XRAY_OPTIONS="patch_premain=false \
// RUN:     xray_logfile_base=fdr-unwrite-test- xray_mode=xray-fdr \
// RUN:     verbosity=1" \
// RUN: XRAY_FDR_OPTIONS="func_duration_threshold_us=5000" \
// RUN:     %run %t 2>&1 | FileCheck %s
// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \
// RUN:     "`ls fdr-logging-test-* | head -1`" \
// RUN:     | FileCheck %s --check-prefix=TRACE
// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t \
// RUN:     "`ls fdr-unwrite-test-* | head -1`" \
// RUN:     | FileCheck %s --check-prefix=UNWRITE
// RUN: rm fdr-logging-test-*
// RUN: rm fdr-unwrite-test-*
// FIXME: Make llvm-xray work on non-x86_64 as well.
// REQUIRES: x86_64-target-arch
// REQUIRES: built-in-llvm-tree

#include "xray/xray_log_interface.h"
#include <cassert>
#include <chrono>
#include <cstdio>
#include <iostream>
#include <stdlib.h>
#include <thread>
#include <time.h>

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;
  std::cout << "Logging before init." << std::endl;
  // CHECK: Logging before init.
  assert(__xray_log_select_mode("xray-fdr") ==
         XRayLogRegisterStatus::XRAY_REGISTRATION_OK);
  auto status =
      __xray_log_init_mode("xray-fdr", "buffer_size=16384:buffer_max=10");
  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;
  // CHECK: Main execution var = 6
  std::cout << "Flush status " << __xray_log_flushLog() << std::endl;
  // CHECK: Flush status {{.*}}
  __xray_unpatch();
  return 0;
}

// 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|tail-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|tail-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|tail-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|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.
// 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}}


More information about the llvm-dev mailing list