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@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@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@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@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
#include
#include
#include
#include <stdlib.h>
#include
#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();
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@OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++ -fxray-instrument -std=c++11 fdr-mode-no-flush.cc
henry@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@OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++ -fxray-instrument -std=c++11 fdr-mode.cc
henry@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
arg1-arg0-logging.cc (1.13 KB)
fdr-mode.cc (5.66 KB)
fdr-mode-no-flush.cc (5.45 KB)