From 20cf903d60d99af9751139c33d88547928180e4c Mon Sep 17 00:00:00 2001 From: Daniel Sanders Date: Tue, 19 Feb 2019 18:18:31 +0000 Subject: [PATCH] Annotate timeline in Instruments with passes and other timed regions. Summary: Instruments is a useful tool for finding performance issues in LLVM but it can be difficult to identify regions of interest on the timeline that we can use to filter the profiler or allocations instrument. Xcode 10 and the latest macOS/iOS/etc. added support for the os_signpost() API which allows us to annotate the timeline with information that's meaningful to LLVM. This patch causes timer start and end events to emit signposts. When used with -time-passes, this causes the passes to be annotated on the Instruments timeline. In addition to visually showing the duration of passes on the timeline, it also allows us to filter the profile and allocations instrument down to an individual pass allowing us to find the issues within that pass without being drowned out by the noise from other parts of the compiler. Using this in conjunction with the Time Profiler (in high frequency mode) and the Allocations instrument is how I found the SparseBitVector that should have been a BitVector and the DenseMap that could be replaced by a sorted vector a couple months ago. I added NamedRegionTimers to TableGen and used the resulting annotations to identify the slow portions of the Register Info Emitter. Some of these were placed according to educated guesses while others were placed according to hot functions from a previous profile. From there I filtered the profile to a slow portion and the aforementioned issues stood out in the profile. To use this feature enable LLVM_SUPPORT_XCODE_SIGNPOSTS in CMake and run the compiler under Instruments with -time-passes like so: instruments -t 'Time Profiler' bin/llc -time-passes -o - input.ll' Then open the resulting trace in Instruments. There was a talk at WWDC 2018 that explained the feature which can be found at https://developer.apple.com/videos/play/wwdc2018/405/ if you'd like to know more about it. Reviewers: bogner Reviewed By: bogner Subscribers: jdoerfert, mgorny, kristina, llvm-commits Tags: #llvm Differential Revision: https://reviews.llvm.org/D52954 git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@354365 91177308-0d34-0410-b5e6-96231b3b80d8 --- cmake/modules/HandleLLVMOptions.cmake | 23 +++++ include/llvm/Config/config.h.cmake | 3 + include/llvm/Support/Signposts.h | 43 ++++++++++ lib/Support/CMakeLists.txt | 1 + lib/Support/Signposts.cpp | 119 ++++++++++++++++++++++++++ lib/Support/Timer.cpp | 6 ++ 6 files changed, 195 insertions(+) create mode 100644 include/llvm/Support/Signposts.h create mode 100644 lib/Support/Signposts.cpp diff --git a/cmake/modules/HandleLLVMOptions.cmake b/cmake/modules/HandleLLVMOptions.cmake index ca53f7f38ee..f60b457679e 100644 --- a/cmake/modules/HandleLLVMOptions.cmake +++ b/cmake/modules/HandleLLVMOptions.cmake @@ -916,3 +916,26 @@ endfunction() get_compile_definitions() option(LLVM_FORCE_ENABLE_STATS "Enable statistics collection for builds that wouldn't normally enable it" OFF) + +check_symbol_exists(os_signpost_interval_begin "os/signpost.h" _signposts_available) +if(_signposts_available) + set(LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS "WITH_ASSERTS" CACHE STRING + "Enable support for Xcode signposts. Can be WITH_ASSERTS, FORCE_ON, FORCE_OFF") + string(TOUPPER "${LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS}" + uppercase_LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS) + if( uppercase_LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS STREQUAL "WITH_ASSERTS" ) + if( LLVM_ENABLE_ASSERTIONS ) + set( LLVM_SUPPORT_XCODE_SIGNPOSTS 1 ) + endif() + elseif( uppercase_LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS STREQUAL "FORCE_ON" ) + set( LLVM_SUPPORT_XCODE_SIGNPOSTS 1 ) + elseif( uppercase_LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS STREQUAL "FORCE_OFF" ) + # We don't need to do anything special to turn off signposts. + elseif( NOT DEFINED LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS ) + # Treat LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS like "FORCE_OFF" when it has not been + # defined. + else() + message(FATAL_ERROR "Unknown value for LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS:" + " \"${LLVM_ENABLE_SUPPORT_XCODE_SIGNPOSTS}\"!") + endif() +endif() diff --git a/include/llvm/Config/config.h.cmake b/include/llvm/Config/config.h.cmake index 53e6c202d13..80131de048e 100644 --- a/include/llvm/Config/config.h.cmake +++ b/include/llvm/Config/config.h.cmake @@ -350,4 +350,7 @@ /* Define to the default GlobalISel coverage file prefix */ #cmakedefine LLVM_GISEL_COV_PREFIX "${LLVM_GISEL_COV_PREFIX}" +/* Whether Timers signpost passes in Xcode Instruments */ +#cmakedefine01 LLVM_SUPPORT_XCODE_SIGNPOSTS + #endif diff --git a/include/llvm/Support/Signposts.h b/include/llvm/Support/Signposts.h new file mode 100644 index 00000000000..b5a8c3d61e3 --- /dev/null +++ b/include/llvm/Support/Signposts.h @@ -0,0 +1,43 @@ +//===-- llvm/Support/Signposts.h - Interval debug annotations ---*- C++ -*-===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +/// \file Some OS's provide profilers that allow applications to provide custom +/// annotations to the profiler. For example, on Xcode 10 and later 'signposts' +/// can be emitted by the application and these will be rendered to the Points +/// of Interest track on the instruments timeline. +// +//===----------------------------------------------------------------------===// + +#ifndef LLVM_SUPPORT_SIGNPOSTS_H +#define LLVM_SUPPORT_SIGNPOSTS_H + +namespace llvm { +class SignpostEmitterImpl; +class Timer; + +/// Manages the emission of signposts into the recording method supported by +/// the OS. +class SignpostEmitter { + SignpostEmitterImpl *Impl; + +public: + SignpostEmitter(); + ~SignpostEmitter(); + + bool isEnabled() const; + + /// Begin a signposted interval for the given timer. + void startTimerInterval(Timer *T); + /// End a signposted interval for the given timer. + void endTimerInterval(Timer *T); +}; + +} // end namespace llvm + +#endif // ifndef LLVM_SUPPORT_SIGNPOSTS_H diff --git a/lib/Support/CMakeLists.txt b/lib/Support/CMakeLists.txt index 7e791594587..234db82a0c2 100644 --- a/lib/Support/CMakeLists.txt +++ b/lib/Support/CMakeLists.txt @@ -116,6 +116,7 @@ add_llvm_library(LLVMSupport ScaledNumber.cpp ScopedPrinter.cpp SHA1.cpp + Signposts.cpp SmallPtrSet.cpp SmallVector.cpp SourceMgr.cpp diff --git a/lib/Support/Signposts.cpp b/lib/Support/Signposts.cpp new file mode 100644 index 00000000000..d456f41d2fa --- /dev/null +++ b/lib/Support/Signposts.cpp @@ -0,0 +1,119 @@ +//===-- Signposts.cpp - Interval debug annotations ------------------------===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// + +#include "llvm/Support/Signposts.h" +#include "llvm/Support/Timer.h" + +#include "llvm/Config/config.h" +#if LLVM_SUPPORT_XCODE_SIGNPOSTS +#include "llvm/ADT/DenseMap.h" +#include +#endif // if LLVM_SUPPORT_XCODE_SIGNPOSTS + +using namespace llvm; + +#if LLVM_SUPPORT_XCODE_SIGNPOSTS +namespace { +os_log_t *LogCreator() { + os_log_t *X = new os_log_t; + *X = os_log_create("org.llvm.signposts", OS_LOG_CATEGORY_POINTS_OF_INTEREST); + return X; +} +void LogDeleter(os_log_t *X) { + os_release(*X); + delete X; +} +} // end anonymous namespace + +namespace llvm { +class SignpostEmitterImpl { + using LogPtrTy = + std::unique_ptr>; + using LogTy = LogPtrTy::element_type; + + LogPtrTy SignpostLog; + DenseMap Signposts; + + LogTy &getLogger() const { return *SignpostLog; } + os_signpost_id_t getSignpostForTimer(const Timer *T) { + const auto &I = Signposts.find(T); + if (I != Signposts.end()) + return I->second; + + const auto &Inserted = Signposts.insert( + std::make_pair(T, os_signpost_id_make_with_pointer(getLogger(), T))); + return Inserted.first->second; + } + +public: + SignpostEmitterImpl() : SignpostLog(LogCreator(), LogDeleter), Signposts() {} + + bool isEnabled() const { return os_signpost_enabled(*SignpostLog); } + + void startTimerInterval(Timer *T) { + if (isEnabled()) { + // Both strings used here are required to be constant literal strings + os_signpost_interval_begin(getLogger(), getSignpostForTimer(T), + "Pass Timers", "Begin %s", + T->getName().c_str()); + } + } + + void endTimerInterval(Timer *T) { + if (isEnabled()) { + // Both strings used here are required to be constant literal strings + os_signpost_interval_end(getLogger(), getSignpostForTimer(T), + "Pass Timers", "End %s", T->getName().c_str()); + } + } +}; +} // end namespace llvm +#endif // if LLVM_SUPPORT_XCODE_SIGNPOSTS + +#if LLVM_SUPPORT_XCODE_SIGNPOSTS +#define HAVE_ANY_SIGNPOST_IMPL 1 +#endif + +SignpostEmitter::SignpostEmitter() { +#if HAVE_ANY_SIGNPOST_IMPL + Impl = new SignpostEmitterImpl(); +#else // if HAVE_ANY_SIGNPOST_IMPL + Impl = nullptr; +#endif // if !HAVE_ANY_SIGNPOST_IMPL +} + +SignpostEmitter::~SignpostEmitter() { +#if HAVE_ANY_SIGNPOST_IMPL + delete Impl; +#endif // if HAVE_ANY_SIGNPOST_IMPL +} + +bool SignpostEmitter::isEnabled() const { +#if HAVE_ANY_SIGNPOST_IMPL + return Impl->isEnabled(); +#else + return false; +#endif // if !HAVE_ANY_SIGNPOST_IMPL +} + +void SignpostEmitter::startTimerInterval(Timer *T) { +#if HAVE_ANY_SIGNPOST_IMPL + if (Impl == nullptr) + return; + return Impl->startTimerInterval(T); +#endif // if !HAVE_ANY_SIGNPOST_IMPL +} + +void SignpostEmitter::endTimerInterval(Timer *T) { +#if HAVE_ANY_SIGNPOST_IMPL + if (Impl == nullptr) + return; + Impl->endTimerInterval(T); +#endif // if !HAVE_ANY_SIGNPOST_IMPL +} diff --git a/lib/Support/Timer.cpp b/lib/Support/Timer.cpp index 0e634b392b5..3cf907d7067 100644 --- a/lib/Support/Timer.cpp +++ b/lib/Support/Timer.cpp @@ -19,6 +19,7 @@ #include "llvm/Support/ManagedStatic.h" #include "llvm/Support/Mutex.h" #include "llvm/Support/Process.h" +#include "llvm/Support/Signposts.h" #include "llvm/Support/YAMLTraits.h" #include "llvm/Support/raw_ostream.h" #include @@ -39,6 +40,9 @@ static std::string &getLibSupportInfoOutputFilename() { static ManagedStatic > TimerLock; +/// Allows llvm::Timer to emit signposts when supported. +static ManagedStatic Signposts; + namespace { static cl::opt TrackSpace("track-memory", cl::desc("Enable -time-passes memory " @@ -133,6 +137,7 @@ TimeRecord TimeRecord::getCurrentTime(bool Start) { void Timer::startTimer() { assert(!Running && "Cannot start a running timer"); Running = Triggered = true; + Signposts->startTimerInterval(this); StartTime = TimeRecord::getCurrentTime(true); } @@ -141,6 +146,7 @@ void Timer::stopTimer() { Running = false; Time += TimeRecord::getCurrentTime(false); Time -= StartTime; + Signposts->endTimerInterval(this); } void Timer::clear() { -- 2.50.1