Annotate timeline in Instruments with passes and other timed regions.

[dsanders]

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.

[dsanders]

ping

[dsanders]

ping

[bogner]

Is there a more generic term for this than "signpost"? If so, it might be nice to use that to avoid confusion when/if other implementations show up. If not, that's fine.

Overall, looks reasonable to me, other than a few nitpicks.

cmake/modules/HandleLLVMOptions.cmake

893

Can we detect when this is available rather than make it an option?

include/llvm/Support/Timer.h

16

Public headers can't include config.h. We don't install it, so folks using llvm as a library can't see it. That said, do we even need this include?

lib/Support/Signposts.cpp

84–87

Better to do #if/#else here, in case any compilers warn about the redundant assignment (I'm not sure if they do)

98–99

Can Impl ever be null if HAVE_ANY_SIGNPOST_IMPL? I think we can remove these checks.

[dsanders]

Updated before commit

[dsanders]

In D52954#1397449, @bogner wrote:

Is there a more generic term for this than "signpost"? If so, it might be nice to use that to avoid confusion when/if other implementations show up. If not, that's fine.

ProfilerAnnotations would fit, it's possibly too generic though

cmake/modules/HandleLLVMOptions.cmake

893

We can test for os_signpost_interval_begin() and only offer it when it's available but I think it should be optional. The os_signpost family are very cheap (mostly due to the constant literal string requirements) but they do have a run-time cost.

lib/Support/Signposts.cpp

98–99

It shouldn't be possible. I'll remove them

[bogner]

cmake/modules/HandleLLVMOptions.cmake

893

Makes sense, though I think defaulting the option to on when it's available makes sense. It may also make sense to default this to match asserts and allow it to be forced on or off (that's done elsewhere, IIRC)

[dsanders]

cmake/modules/HandleLLVMOptions.cmake

893

I've gone with the WITH_ASSERTS mechanism like ABI-breaking checks

cmake/modules/HandleLLVMOptions.cmake

else()
       set(result "-D${definition}")
     endif()
   endforeach()
   set(LLVM_DEFINITIONS "${result}" PARENT_SCOPE)
 endfunction()
 get_compile_definitions()
 
 option(LLVM_FORCE_ENABLE_STATS "Enable statistics collection for builds that wouldn't normally enable it" OFF)
+
+option(LLVM_SUPPORT_XCODE_SIGNPOSTS "Enable support for Xcode signposts" OFF)

include/llvm/Config/config.h.cmake

 #cmakedefine strdup ${strdup}
 
 /* Whether GlobalISel rule coverage is being collected */
 #cmakedefine01 LLVM_GISEL_COV_ENABLED
 
 /* 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

+//===-- 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

include/llvm/Support/Timer.h

 //===-- llvm/Support/Timer.h - Interval Timing Support ----------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef LLVM_SUPPORT_TIMER_H
 #define LLVM_SUPPORT_TIMER_H
 
 #include "llvm/ADT/StringMap.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/DataTypes.h"
+#include "llvm/Config/config.h"
 #include <cassert>
 #include <string>
 #include <utility>
 #include <vector>
 
 namespace llvm {
 
 class Timer;

lib/Support/CMakeLists.txt

add_llvm_library(LLVMSupport
   Parallel.cpp
   PluginLoader.cpp
   PrettyStackTrace.cpp
   RandomNumberGenerator.cpp
   Regex.cpp
   ScaledNumber.cpp
   ScopedPrinter.cpp
   SHA1.cpp
+  Signposts.cpp
   SmallPtrSet.cpp
   SmallVector.cpp
   SourceMgr.cpp
   SpecialCaseList.cpp
   Statistic.cpp
   StringExtras.cpp
   StringMap.cpp
   StringPool.cpp

lib/Support/Signposts.cpp

+//===-- 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() {
+  Impl = nullptr;
+#if HAVE_ANY_SIGNPOST_IMPL
+  Impl = new SignpostEmitterImpl();
+#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
+  if (Impl == nullptr)
+    return false;
+  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

 #include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Format.h"
 #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>
 
 using namespace llvm;
 
 // This ugly hack is brought to you courtesy of constructor/destructor ordering
 // being unspecified by C++.  Basically the problem is that a Statistic object
 // gets destroyed, which ends up calling 'GetLibSupportInfoOutputFile()'
 // (below), which calls this function.  LibSupportInfoOutputFilename used to be
 // a global variable, but sometimes it would get destroyed before the Statistic,
 // causing havoc to ensue.  We "fix" this by creating the string the first time
 // it is needed and never destroying it.
 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
 static std::string &getLibSupportInfoOutputFilename() {
   return *LibSupportInfoOutputFilename;
 }
 
 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 "
                                       "tracking (this may be slow)"),
              cl::Hidden);
 
   static cl::opt<std::string, true>
   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
TimeRecord TimeRecord::getCurrentTime(bool Start) {
   Result.UserTime = Seconds(user).count();
   Result.SystemTime = Seconds(sys).count();
   return Result;
 }
 
 void Timer::startTimer() {
   assert(!Running && "Cannot start a running timer");
   Running = Triggered = true;
+  Signposts->startTimerInterval(this);
   StartTime = TimeRecord::getCurrentTime(true);
 }
 
 void Timer::stopTimer() {
   assert(Running && "Cannot stop a paused timer");
   Running = false;
   Time += TimeRecord::getCurrentTime(false);
   Time -= StartTime;
+  Signposts->endTimerInterval(this);
 }
 
 void Timer::clear() {
   Running = Triggered = false;
   Time = StartTime = TimeRecord();
 }
 
 static void printVal(double Val, double Total, raw_ostream &OS) {