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

llvm-svn: 354365

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()

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

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

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

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
+}

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() {