[compiler-rt] r298977 - [XRay][compiler-rt] Add an end-to-end test for FDR Logging
Dean Michael Berris via llvm-commits
llvm-commits at lists.llvm.org
Tue Apr 18 15:22:03 PDT 2017
Thanks Evgenii -- can you provide reproduction steps (do you enable CFI
checking in the build?) so that I can try and debug this myself too?
On Wed, Apr 19, 2017 at 7:05 AM Evgenii Stepanov <eugeni.stepanov at gmail.com>
wrote:
> And __xray_FunctionEntry has the same alignment problem, too. Also,
> SAVE_REGISTERS reserves extra 16 bytes of stack at the bottom that
> seem to be left unused for some reason.
>
> On Tue, Apr 18, 2017 at 1:19 PM, Evgenii Stepanov
> <eugeni.stepanov at gmail.com> wrote:
> > .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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.llvm.org/pipermail/llvm-commits/attachments/20170418/4957ba18/attachment.html>
More information about the llvm-commits
mailing list