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

diff --git a/cmake/modules/HandleLLVMOptions.cmake b/cmake/modules/HandleLLVMOptions.cmake
index ca53f7f38ee06a16690023652c15811048554f6f..f60b457679ea2cf2d097695c6e06797fe0e9c7d4 100644 (file)
--- 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 53e6c202d13a5fe55a5b71e41241a207c437d145..80131de048e1c800b9c58dee38359737e939d8e8 100644 (file)
--- 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 (file)
index 0000000..b5a8c3d
--- /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 7e791594587e43aea1de92a85dea4b14d558eb99..234db82a0c2a0e0994e38ee55913d98e9cb25544 100644 (file)
--- 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 (file)
index 0000000..d456f41
--- /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 <os/signpost.h>
+#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<os_log_t, std::function<void(os_log_t *)>>;
+  using LogTy = LogPtrTy::element_type;
+
+  LogPtrTy SignpostLog;
+  DenseMap<const Timer *, os_signpost_id_t> 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 0e634b392b5cfcfa112493b6a2f0105a3054c500..3cf907d706799e4720018a8a01e1fc237eca2d57 100644 (file)
--- 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 <limits>
@@ -39,6 +40,9 @@ static std::string &getLibSupportInfoOutputFilename() {
 
 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
 
+/// Allows llvm::Timer to emit signposts when supported.
+static ManagedStatic<SignpostEmitter> Signposts;
+
 namespace {
   static cl::opt<bool>
   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() {