thr3ads.net - llvm dev - [llvm-dev] XRay FDR mode doesn’t log main thread calls [Jun 2018]

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

Henry Zhu via llvm-dev

2018-Jun-08 20:23 UTC

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

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

Dean Michael Berris via llvm-dev

2018-Jun-12 00:22 UTC

head link

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

> On 9 Jun 2018, at 06:23, Henry Zhu via llvm-dev <llvm-dev at
lists.llvm.org> wrote:
> 
> 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.
> 
Yes, this is definitely a bug, but one that I thought we’ve already fixed. Can
you say whether the latest in HEAD is still exhibiting the same problem?

If not, this one should be easy to reproduce and fix (with a test, upstream in
particular).

If you can file a bug (as well) through https://llvm.org/bugs then Keith and I
can probably track this better/easier.
> 
> 
>  
> Is this expected behavior?
> 
Definitely not expected behaviour. If you can reproduce with the latest in HEAD,
then there’s definitely something for us to address (quite easily).

Cheers

-- Dean

Henry Zhu via llvm-dev

2018-Jun-25 15:01 UTC

head link

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

I've updated xray and the problem has been fixed.

On Mon, Jun 11, 2018 at 8:22 PM, Dean Michael Berris <dean.berris at
gmail.com>
wrote:
>
>
> > On 9 Jun 2018, at 06:23, Henry Zhu via llvm-dev <llvm-dev at
lists.llvm.org>
> wrote:
> >
> > 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.
> >
>
> Yes, this is definitely a bug, but one that I thought we’ve already fixed.
> Can you say whether the latest in HEAD is still exhibiting the same
problem?
>
> If not, this one should be easy to reproduce and fix (with a test,
> upstream in particular).
>
> If you can file a bug (as well) through https://llvm.org/bugs then Keith
> and I can probably track this better/easier.
>
> >
> >
> >
> > Is this expected behavior?
> >
>
> Definitely not expected behaviour. If you can reproduce with the latest in
> HEAD, then there’s definitely something for us to address (quite easily).
>
> Cheers
>
> -- Dean
>
>-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20180625/ccc4beff/attachment.html>

llvm dev - Jun 2018 - XRay FDR mode doesn’t log main thread calls

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

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

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