[llvm-dev] XRay FDR mode doesn’t log main thread calls
Henry Zhu via llvm-dev
llvm-dev at lists.llvm.org
Fri Jun 8 13:23:29 PDT 2018
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}}
More information about the llvm-dev
mailing list