[compiler-rt] r298977 - [XRay][compiler-rt] Add an end-to-end test for FDR Logging

Evgenii Stepanov via llvm-commits llvm-commits at lists.llvm.org
Tue Apr 18 13:19:45 PDT 2017


        .cfi_def_cfa_offset 16
        subq    $56, %rsp
        .cfi_def_cfa_offset 32

This is also wrong. CFA offset should change by the same amount as
%rsp, i.e. 72 instead of 32. This fixes stack unwinding for me.

On Tue, Apr 18, 2017 at 12:01 PM, Evgenii Stepanov
<eugeni.stepanov at gmail.com> wrote:
> Hi,
>
> this test is reliably failing on the bots and on my desktop (x86_64).
>
> __xray_FunctionExit:
>         .cfi_startproc
>         pushq   %rbp
>         .cfi_def_cfa_offset 16
>         subq    $56, %rsp
>         .cfi_def_cfa_offset 32
>         movupd  %xmm0, 40(%rsp)
>         movupd  %xmm1, 24(%rsp)
>         movq    %rax, 16(%rsp)
>         movq    %rdx, 8(%rsp)
> movq    _ZN6__xray19XRayPatchedFunctionE(%rip), %rax
>         testq %rax,%rax
> je      .Ltmp2
>
>         movl    %r10d, %edi
>         movl    $1, %esi
>         callq   *%rax
>
> This moves the stack pointer by 8 (pushq %rbp) + 56 + 8 (call *%rax) =
> 72 bytes. The callee gets an unaligned stack pointer.
>
> The actual crash:
> 0x000000000041dae3 in readValueFromFile () at
> /code/llvm/projects/compiler-rt/lib/xray/xray_x86_64.cc:43
> 43  char Line[BufSize] = {};
> (gdb) bt
> #0  0x000000000041dae3 in readValueFromFile () at
> /code/llvm/projects/compiler-rt/lib/xray/xray_x86_64.cc:43
> #1  0x000000000041da7b in __xray::getTSCFrequency() () at
> /code/llvm/projects/compiler-rt/lib/xray/xray_x86_64.cc:65
> #2  0x0000000000421789 in __xray::__xray_fdr_internal::thresholdTicks() ()
>     at /code/llvm/projects/compiler-rt/lib/xray/xray_fdr_logging_impl.h:349
> #3  0x0000000000420f65 in processFunctionHook () at
> /code/llvm/projects/compiler-rt/lib/xray/xray_fdr_logging_impl.h:618
> #4  fdrLoggingHandleArg0 () at
> /code/llvm/projects/compiler-rt/lib/xray/xray_fdr_logging.cc:213
> #5  0x000000000041de81 in __xray_FunctionExit () at
> /code/llvm/projects/compiler-rt/lib/xray/xray_trampoline_x86_64.S:113
> #6  0x0000000000000101 in ?? ()
> #7  0x0000000000000000 in ?? ()
>
> Dump of assembler code for function readValueFromFile():
>    0x000000000041dab0 <+0>: push   %rbp
>    0x000000000041dab1 <+1>: push   %r15
>    0x000000000041dab3 <+3>: push   %r14
>    0x000000000041dab5 <+5>: push   %rbx
>    0x000000000041dab6 <+6>: sub    $0x118,%rsp
>    0x000000000041dabd <+13>: mov    %rsi,%r14
>    0x000000000041dac0 <+16>: xor    %ebx,%ebx
>    0x000000000041dac2 <+18>: mov    $0x80000,%esi
>    0x000000000041dac7 <+23>: xor    %eax,%eax
>    0x000000000041dac9 <+25>: callq  0x4026b0 <open at plt>
>    0x000000000041dace <+30>: mov    %eax,%r15d
>    0x000000000041dad1 <+33>: cmp    $0xffffffff,%r15d
>    0x000000000041dad5 <+37>: je     0x41dbee <readValueFromFile()+318>
>    0x000000000041dadb <+43>: lea    0x10(%rsp),%rbx
>    0x000000000041dae0 <+48>: xorps  %xmm0,%xmm0
> => 0x000000000041dae3 <+51>: movaps %xmm0,0x100(%rsp)
>    0x000000000041daeb <+59>: movaps %xmm0,0xf0(%rsp)
>    0x000000000041daf3 <+67>: movaps %xmm0,0xe0(%rsp)
>    0x000000000041dafb <+75>: movaps %xmm0,0xd0(%rsp)
>
> Also, as can be seen above, there is a stack unwinding issue (frame
> #6). I'm not sure what's the problem there.
>
>
> On Tue, Mar 28, 2017 at 10:19 PM, Dean Michael Berris via llvm-commits
> <llvm-commits at lists.llvm.org> wrote:
>> Author: dberris
>> Date: Wed Mar 29 00:19:24 2017
>> New Revision: 298977
>>
>> URL: http://llvm.org/viewvc/llvm-project?rev=298977&view=rev
>> Log:
>> [XRay][compiler-rt] Add an end-to-end test for FDR Logging
>>
>> Summary:
>> This change exercises the end-to-end functionality defined in the FDR
>> logging implementation. We also prepare for being able to run traces
>> generated by the FDR logging implementation from being analysed with the
>> llvm-xray command that comes with the LLVM distribution.
>>
>> This also unblocks D31385, D31384, and D31345.
>>
>> Reviewers: kpw, pelikan
>>
>> Subscribers: llvm-commits, mgorny
>>
>> Differential Revision: https://reviews.llvm.org/D31452
>>
>> Added:
>>     compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc
>> Modified:
>>     compiler-rt/trunk/include/CMakeLists.txt
>>     compiler-rt/trunk/include/xray/xray_log_interface.h
>>     compiler-rt/trunk/lib/xray/xray_fdr_logging.cc
>>     compiler-rt/trunk/lib/xray/xray_fdr_logging.h
>>     compiler-rt/trunk/lib/xray/xray_log_interface.cc
>>     compiler-rt/trunk/lib/xray/xray_utils.cc
>>     compiler-rt/trunk/test/xray/lit.cfg
>>
>> Modified: compiler-rt/trunk/include/CMakeLists.txt
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/include/CMakeLists.txt?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/include/CMakeLists.txt (original)
>> +++ compiler-rt/trunk/include/CMakeLists.txt Wed Mar 29 00:19:24 2017
>> @@ -12,7 +12,8 @@ set(SANITIZER_HEADERS
>>    sanitizer/tsan_interface_atomic.h)
>>
>>  set(XRAY_HEADERS
>> -  xray/xray_interface.h)
>> +  xray/xray_interface.h
>> +  xray/xray_log_interface.h)
>>
>>  set(COMPILER_RT_HEADERS
>>    ${SANITIZER_HEADERS}
>>
>> Modified: compiler-rt/trunk/include/xray/xray_log_interface.h
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/include/xray/xray_log_interface.h?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/include/xray/xray_log_interface.h (original)
>> +++ compiler-rt/trunk/include/xray/xray_log_interface.h Wed Mar 29 00:19:24 2017
>> @@ -48,4 +48,13 @@ XRayLogFlushStatus __xray_log_flushLog()
>>
>>  } // extern "C"
>>
>> +namespace __xray {
>> +// Options used by the LLVM XRay FDR implementation.
>> +struct FDRLoggingOptions {
>> +  bool ReportErrors = false;
>> +  int Fd = -1;
>> +};
>> +
>> +} // namespace __xray
>> +
>>  #endif // XRAY_XRAY_LOG_INTERFACE_H
>>
>> Modified: compiler-rt/trunk/lib/xray/xray_fdr_logging.cc
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/xray_fdr_logging.cc?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/lib/xray/xray_fdr_logging.cc (original)
>> +++ compiler-rt/trunk/lib/xray/xray_fdr_logging.cc Wed Mar 29 00:19:24 2017
>> @@ -51,19 +51,18 @@ std::unique_ptr<FDRLoggingOptions> FDROp
>>  XRayLogInitStatus fdrLoggingInit(std::size_t BufferSize, std::size_t BufferMax,
>>                                   void *Options,
>>                                   size_t OptionsSize) XRAY_NEVER_INSTRUMENT {
>> -  assert(OptionsSize == sizeof(FDRLoggingOptions));
>> +  if (OptionsSize != sizeof(FDRLoggingOptions))
>> +    return static_cast<XRayLogInitStatus>(__sanitizer::atomic_load(
>> +        &LoggingStatus, __sanitizer::memory_order_acquire));
>>    s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
>> -  if (__sanitizer::atomic_compare_exchange_strong(
>> +  if (!__sanitizer::atomic_compare_exchange_strong(
>>            &LoggingStatus, &CurrentStatus,
>>            XRayLogInitStatus::XRAY_LOG_INITIALIZING,
>>            __sanitizer::memory_order_release))
>>      return static_cast<XRayLogInitStatus>(CurrentStatus);
>>
>>    FDROptions.reset(new FDRLoggingOptions());
>> -  *FDROptions = *reinterpret_cast<FDRLoggingOptions *>(Options);
>> -  if (FDROptions->ReportErrors)
>> -    SetPrintfAndReportCallback(printToStdErr);
>> -
>> +  memcpy(FDROptions.get(), Options, OptionsSize);
>>    bool Success = false;
>>    BQ = std::make_shared<BufferQueue>(BufferSize, BufferMax, Success);
>>    if (!Success) {
>> @@ -77,6 +76,7 @@ XRayLogInitStatus fdrLoggingInit(std::si
>>    __sanitizer::atomic_store(&LoggingStatus,
>>                              XRayLogInitStatus::XRAY_LOG_INITIALIZED,
>>                              __sanitizer::memory_order_release);
>> +  Report("XRay FDR init successful.\n");
>>    return XRayLogInitStatus::XRAY_LOG_INITIALIZED;
>>  }
>>
>> @@ -88,7 +88,7 @@ XRayLogFlushStatus fdrLoggingFlush() XRA
>>      return XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
>>
>>    s32 Result = XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
>> -  if (__sanitizer::atomic_compare_exchange_strong(
>> +  if (!__sanitizer::atomic_compare_exchange_strong(
>>            &LogFlushStatus, &Result, XRayLogFlushStatus::XRAY_LOG_FLUSHING,
>>            __sanitizer::memory_order_release))
>>      return static_cast<XRayLogFlushStatus>(Result);
>> @@ -140,7 +140,7 @@ XRayLogFlushStatus fdrLoggingFlush() XRA
>>
>>  XRayLogInitStatus fdrLoggingFinalize() XRAY_NEVER_INSTRUMENT {
>>    s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_INITIALIZED;
>> -  if (__sanitizer::atomic_compare_exchange_strong(
>> +  if (!__sanitizer::atomic_compare_exchange_strong(
>>            &LoggingStatus, &CurrentStatus,
>>            XRayLogInitStatus::XRAY_LOG_FINALIZING,
>>            __sanitizer::memory_order_release))
>> @@ -168,8 +168,7 @@ XRayLogInitStatus fdrLoggingReset() XRAY
>>    BQ.reset();
>>
>>    // Spin until the flushing status is flushed.
>> -  s32 CurrentFlushingStatus =
>> -      XRayLogFlushStatus::XRAY_LOG_FLUSHED;
>> +  s32 CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED;
>>    while (__sanitizer::atomic_compare_exchange_weak(
>>        &LogFlushStatus, &CurrentFlushingStatus,
>>        XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING,
>>
>> Modified: compiler-rt/trunk/lib/xray/xray_fdr_logging.h
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/xray_fdr_logging.h?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/lib/xray/xray_fdr_logging.h (original)
>> +++ compiler-rt/trunk/lib/xray/xray_fdr_logging.h Wed Mar 29 00:19:24 2017
>> @@ -26,14 +26,6 @@
>>  // default mode of always writing fixed-size records.
>>
>>  namespace __xray {
>> -
>> -// Options used by the FDR implementation.
>> -struct FDRLoggingOptions {
>> -  bool ReportErrors = false;
>> -  int Fd = -1;
>> -};
>> -
>> -// Flight Data Recorder mode implementation interfaces.
>>  XRayLogInitStatus fdrLoggingInit(size_t BufferSize, size_t BufferMax,
>>                                   void *Options, size_t OptionsSize);
>>  XRayLogInitStatus fdrLoggingFinalize();
>>
>> Modified: compiler-rt/trunk/lib/xray/xray_log_interface.cc
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/xray_log_interface.cc?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/lib/xray/xray_log_interface.cc (original)
>> +++ compiler-rt/trunk/lib/xray/xray_log_interface.cc Wed Mar 29 00:19:24 2017
>> @@ -35,8 +35,9 @@ void __xray_set_log_impl(XRayLogImpl Imp
>>    *GlobalXRayImpl = Impl;
>>  }
>>
>> -XRayLogInitStatus __xray_init(size_t BufferSize, size_t MaxBuffers, void *Args,
>> -                              size_t ArgsSize) XRAY_NEVER_INSTRUMENT {
>> +XRayLogInitStatus __xray_log_init(size_t BufferSize, size_t MaxBuffers,
>> +                                  void *Args,
>> +                                  size_t ArgsSize) XRAY_NEVER_INSTRUMENT {
>>    __sanitizer::SpinMutexLock Guard(&XRayImplMutex);
>>    if (!GlobalXRayImpl)
>>      return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
>>
>> Modified: compiler-rt/trunk/lib/xray/xray_utils.cc
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/xray_utils.cc?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/lib/xray/xray_utils.cc (original)
>> +++ compiler-rt/trunk/lib/xray/xray_utils.cc Wed Mar 29 00:19:24 2017
>> @@ -93,8 +93,6 @@ bool readValueFromFile(const char *Filen
>>  }
>>
>>  int getLogFD() XRAY_NEVER_INSTRUMENT {
>> -  // FIXME: Figure out how to make this less stderr-dependent.
>> -  SetPrintfAndReportCallback(printToStdErr);
>>    // Open a temporary file once for the log.
>>    static char TmpFilename[256] = {};
>>    static char TmpWildcardPattern[] = "XXXXXX";
>> @@ -119,8 +117,7 @@ int getLogFD() XRAY_NEVER_INSTRUMENT {
>>             TmpFilename);
>>      return -1;
>>    }
>> -  if (Verbosity())
>> -    fprintf(stderr, "XRay: Log file in '%s'\n", TmpFilename);
>> +  Report("XRay: Log file in '%s'\n", TmpFilename);
>>
>>    return Fd;
>>  }
>>
>> Added: compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc?rev=298977&view=auto
>> ==============================================================================
>> --- compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc (added)
>> +++ compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc Wed Mar 29 00:19:24 2017
>> @@ -0,0 +1,62 @@
>> +// RUN: %clangxx_xray -std=c++11 %s -o %t
>> +// RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-logging-test- xray_fdr_log=true verbosity=1" %run %t 2>&1 | FileCheck %s
>> +// FIXME: %llvm_xray convert -instr_map=%t "`ls fdr-logging-test-* | head -1`" | FileCheck %s --check-prefix TRACE
>> +// RUN: rm fdr-logging-test-*
>> +
>> +#include "xray/xray_log_interface.h"
>> +#include <cassert>
>> +#include <chrono>
>> +#include <cstdio>
>> +#include <iostream>
>> +#include <stdlib.h>
>> +#include <thread>
>> +#include <time.h>
>> +
>> +constexpr auto kBufferSize = 16384;
>> +constexpr auto kBufferMax = 10;
>> +
>> +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(); }
>> +
>> +int main(int argc, char *argv[]) {
>> +  using namespace __xray;
>> +  FDRLoggingOptions Options;
>> +  std::cout << "Logging before init." << std::endl;
>> +  // CHECK: Logging before init.
>> +  auto status = __xray_log_init(kBufferSize, kBufferMax, &Options,
>> +                                sizeof(FDRLoggingOptions));
>> +  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();
>> +  });
>> +  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;
>> +}
>> +
>> +// TRACE: { function }
>>
>> Modified: compiler-rt/trunk/test/xray/lit.cfg
>> URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/test/xray/lit.cfg?rev=298977&r1=298976&r2=298977&view=diff
>> ==============================================================================
>> --- compiler-rt/trunk/test/xray/lit.cfg (original)
>> +++ compiler-rt/trunk/test/xray/lit.cfg Wed Mar 29 00:19:24 2017
>> @@ -16,6 +16,9 @@ clang_xray_cxxflags = config.cxx_mode_fl
>>  def build_invocation(compile_flags):
>>    return ' ' + ' '.join([config.clang] + compile_flags) + ' '
>>
>> +# Assume that llvm-xray is in the config.llvm_tools_dir.
>> +llvm_xray = os.path.join(config.llvm_tools_dir, 'llvm-xray')
>> +
>>  # Setup substitutions.
>>  config.substitutions.append(
>>      ('%clang ', build_invocation([config.target_cflags])))
>> @@ -26,6 +29,8 @@ config.substitutions.append(
>>      ('%clang_xray ', build_invocation(clang_xray_cflags)))
>>  config.substitutions.append(
>>      ('%clangxx_xray', build_invocation(clang_xray_cxxflags)))
>> +config.substitutions.append(
>> +    ('%llvm_xray', llvm_xray))
>>
>>  # Default test suffixes.
>>  config.suffixes = ['.c', '.cc', '.cpp']
>>
>>
>> _______________________________________________
>> llvm-commits mailing list
>> llvm-commits at lists.llvm.org
>> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-commits


More information about the llvm-commits mailing list