thr3ads.net - llvm dev - [llvm-dev] XRAY_OPTIONS variable does not enable FDR mode and log flushing [Jun 2018]

If this information is useful, please help other people find it:
Share via:

Henry Zhu via llvm-dev

2018-Jun-11 21:49 UTC

[llvm-dev] XRAY_OPTIONS variable does not enable FDR mode and log flushing

Hello,



Setting the xray_mode to xray-fdr in XRAY_OPTIONS does not enable FDR mode.
Under Flight Data Recorder Mode in the docs (https://llvm.org/docs/XRay.html),
it mentions that “ To use FDR mode on your application, you may set the
xray_mode variable to xray-fdr in the XRAY_OPTIONS environment variable.”

I will demonstrate below with output generated from setting the flag



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



The test file I will be using is arg1-arg0-logging.cc from the
TestCases/Posix directory. I will include the file as an attachment as well.



Steps taken:

henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++
-fxray-instrument -std=c++11 arg1-arg0-logging.cc



Running with xray-fdr mode enabled:



henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=true verbosity=1 xray_mode=xray-fdr"
./a.out

hello, arg0!

hello, arg1!





Running with basic-mode enabled:



henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=true verbosity=1 xray_mode=xray-basic"
./a.out

==13229==XRay: Log file in 'xray-log.a.out.dpsGGd'

hello, arg0!

hello, arg1!

==13229==Skipping buffer for TID: 13229; Fd = 3; Offset = 0

==13229==Cleaned up log for TID: 13229



As shown above, setting the xray_mode=xray-fdr does not initialize or
produce any logs. The documentation states that setting this variable would
enable fdr mode, but nothing from the output indicates that.



Instead, I enabled xray-fdr programmatically, but it does not produce a
trace even when the program terminates. I have to call __xray_log_finalize
and __xray_log_flushLog() to produce a trace. Shouldn’t XRay in FDR mode
produce a trace when the program terminates like basic mode does?



The test file I will be using is fdr-mode.cc from the TestCases/Posix
directory. I will also modify the test case and its new name is
fdr-mode-no-flush.cc. I have included the files as attachments as well.



fdr-mode-no-flush.cc (I have removed the lines to __xray_log_finalize and
xray_log_flushLog():

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

  fC();

  std::cout << "Main execution var = " << var <<
std::endl;

  // CHECK: Main execution var = 6

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



Compiling:

henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++
-fxray-instrument -std=c++11 fdr-mode-no-flush.cc



henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=true verbosity=1 xray_mode=xray-fdr"
./a.out

Logging before init.

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

==13595==XRay FDR init successful.

Init status 2

Patching...

Joined

Main execution var = 6



XRay reports that fdr-mode is initialized, but when the program is finished
executing, the logs are not flushed to a trace file. I would expect
fdr-mode to flush like basic-mode does when before a program terminates,
but it does not do so unless __xray_log_finalize and __xray_log_flushLog
are called before program termination.



fdr-mode.cc(same as the TestCase/Posix/fdr-mode.cc):



Compiling:

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

henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=true verbosity=1 xray_mode=xray-fdr"
./a.out

Logging before init.

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

==13609==XRay FDR init successful.

Init status 2

Patching...

Joined

Finalize status 4

Main execution var = 6

==13609==XRay: Log file in 'xray-log.a.out.Fef0vA'

Flush status 2



Now, the log is generated. It seems a bit odd to me that setting
xray_mode=xray-fdr does not enable fdr mode as stated in the documentation.
In addition, one has to manually configure the program to initialize
fdr-mode and flush its buffers before program termination. Is there a
reason for fdr mode to be setup this way? Is it possible to enable fdr mode
and flushing to logs by setting xray_mode=xray-fdr?



Thanks,

Henry
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20180611/8cc8b07a/attachment-0001.html>
-------------- next part --------------
// Allow having both the no-arg and arg1 logging implementation live together,
// and be called in the correct cases.
//
// RUN: rm arg0-arg1-logging-* || true
// RUN: %clangxx_xray -std=c++11 %s -o %t
// RUN: XRAY_OPTIONS="patch_premain=true verbosity=1
xray_logfile_base=arg0-arg1-logging-" %run %t
//
// TODO: Support these in ARM and PPC
// XFAIL: arm || aarch64 || mips
// UNSUPPORTED: powerpc64le

#include "xray/xray_interface.h"
#include <cassert>
#include <cstdio>

using namespace std;

bool arg0loggercalled = false;
void arg0logger(int32_t, XRayEntryType) { arg0loggercalled = true; }

[[clang::xray_always_instrument]] void arg0fn() { printf("hello,
arg0!\n"); }

bool arg1loggercalled = false;
void arg1logger(int32_t, XRayEntryType, uint64_t) { arg1loggercalled = true; }

[[ clang::xray_always_instrument, clang::xray_log_args(1) ]] void
arg1fn(uint64_t arg1) {
  printf("hello, arg1!\n");
}

int main(int argc, char *argv[]) {
  __xray_set_handler(arg0logger);
  __xray_set_handler_arg1(arg1logger);
  arg0fn();
  arg1fn(0xcafef00d);
  __xray_remove_handler_arg1();
  __xray_remove_handler();
  assert(arg0loggercalled && arg1loggercalled);
}
-------------- 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}}
-------------- 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
  fC();
  std::cout << "Main execution var = " << var <<
std::endl;
  // CHECK: Main execution var = 6
  __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}}

Dean Michael Berris via llvm-dev

2018-Jun-12 00:39 UTC

head link

[llvm-dev] XRAY_OPTIONS variable does not enable FDR mode and log flushing

> On 12 Jun 2018, at 07:49, Henry Zhu via llvm-dev <llvm-dev at
lists.llvm.org> wrote:
> 
> Hello,
> 
> 
>  
> Setting the xray_mode to xray-fdr in XRAY_OPTIONS does not enable FDR mode.
Under Flight Data Recorder Mode in the docs (https://llvm.org/docs/XRay.html),
it mentions that “ To use FDR mode on your application, you may set the
xray_mode variable to xray-fdr in the XRAY_OPTIONS environment variable.”
> 
> I will demonstrate below with output generated from setting the flag
> 
>  
> 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
> 
>  
> The test file I will be using is arg1-arg0-logging.cc from the
TestCases/Posix directory. I will include the file as an attachment as well.
> 
>  
> Steps taken:
> 
> henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++
-fxray-instrument -std=c++11 arg1-arg0-logging.cc
> 
>  
> Running with xray-fdr mode enabled:
> 
>  
> henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=true verbosity=1 xray_mode=xray-fdr"
./a.out
> 
> hello, arg0!
> 
> hello, arg1!
> 
>  
>  
> Running with basic-mode enabled:
> 
>  
> henry at OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$
XRAY_OPTIONS="patch_premain=true verbosity=1 xray_mode=xray-basic"
./a.out
> 
> ==13229==XRay: Log file in 'xray-log.a.out.dpsGGd'
> 
> hello, arg0!
> 
> hello, arg1!
> 
> ==13229==Skipping buffer for TID: 13229; Fd = 3; Offset = 0
> 
> ==13229==Cleaned up log for TID: 13229
> 
>  
> As shown above, setting the xray_mode=xray-fdr does not initialize or
produce any logs. The documentation states that setting this variable would
enable fdr mode, but nothing from the output indicates that.
> 
Can you say whether you’re doing this against HEAD?

We’ve recently made changes to make it so that installing FDR mode will actually
initialise it. We’ve also made it so that the configuration options for FDR mode
are in `XRAY_FDR_OPTIONS` along with the `XRAY_OPTIONS` environment variable.
>  
> Instead, I enabled xray-fdr programmatically, but it does not produce a
trace even when the program terminates. I have to call __xray_log_finalize and
__xray_log_flushLog() to produce a trace. Shouldn’t XRay in FDR mode produce a
trace when the program terminates like basic mode does?
> 
It could, but it currently doesn’t.

As I mentioned in the other email you sent, it’s a little tricky to do this
automatically for any mode currently selected, but it’s not impossible to do.
>  
> XRay reports that fdr-mode is initialized, but when the program is finished
executing, the logs are not flushed to a trace file. I would expect fdr-mode to
flush like basic-mode does when before a program terminates, but it does not do
so unless __xray_log_finalize and __xray_log_flushLog are called before program
termination.
> 
That’s a reasonable expectation. We could certainly implement something like
that which will work for all XRay modes.
> 
> 
>  
> Now, the log is generated. It seems a bit odd to me that setting
xray_mode=xray-fdr does not enable fdr mode as stated in the documentation. In
addition, one has to manually configure the program to initialize fdr-mode and
flush its buffers before program termination. Is there a reason for fdr mode to
be setup this way? Is it possible to enable fdr mode and flushing to logs by
setting xray_mode=xray-fdr?
> 
The reason it’s implemented this way, is to explicitly support the use-case of
programmatically controlling when FDR mode starts and ends. We haven’t
prioritised the use-case of wanting to get FDR mode traces at program
termination.

I admit the naming is a little misleading, given that flight data recorders
usually work best looking at “just before unusual termination” conditions. Like
mentioned in the other email, it’s not impossible to add this capability as
well.

Cheers

-- Dean

llvm dev - Jun 2018 - XRAY_OPTIONS variable does not enable FDR mode and log flushing

[llvm-dev] XRAY_OPTIONS variable does not enable FDR mode and log flushing

[llvm-dev] XRAY_OPTIONS variable does not enable FDR mode and log flushing