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

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

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

Sam McCall via llvm-dev

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@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@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@OptiPlex-9010:~/build_xray/llvm-instrumented-build/bin$ ./clang++ -fxray-instrument fdr-mode.cc -o fdr-mode

 

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

 

 

 



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

fdr-mode.cc (7K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

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

Sam McCall via llvm-dev


> On 9 Jun 2018, at 06:23, Henry Zhu via llvm-dev <[hidden email]> 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

_______________________________________________
LLVM Developers mailing list
[hidden email]
http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
Reply | Threaded
Open this post in threaded view
|

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

Sam McCall via llvm-dev
I've updated xray and the problem has been fixed.

On Mon, Jun 11, 2018 at 8:22 PM, Dean Michael Berris <[hidden email]> wrote:


> On 9 Jun 2018, at 06:23, Henry Zhu via llvm-dev <[hidden email]> 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



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