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

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

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

Sam McCall via llvm-dev

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

 

 

 

 

 



_______________________________________________
LLVM Developers mailing list
[hidden email]
http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev

arg1-arg0-logging.cc (1K) Download Attachment
fdr-mode.cc (7K) Download Attachment
fdr-mode-no-flush.cc (7K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Sam McCall via llvm-dev


> On 12 Jun 2018, at 07:49, Henry Zhu via llvm-dev <[hidden email]> 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@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.
>

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 Developers mailing list
[hidden email]
http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev