Index: lldb/include/lldb/Utility/Timer.h =================================================================== --- lldb/include/lldb/Utility/Timer.h +++ lldb/include/lldb/Utility/Timer.h @@ -11,9 +11,14 @@ #include "lldb/lldb-defines.h" #include "llvm/Support/Chrono.h" +#include "llvm/Support/Signposts.h" #include #include +namespace llvm { + class SignpostEmitter; +} + namespace lldb_private { class Stream; @@ -40,8 +45,8 @@ }; /// Default constructor. - Timer(Category &category, const char *format, ...) - __attribute__((format(printf, 3, 4))); + Timer(Category &category, bool emit_signpost, const char *format, ...) + __attribute__((format(printf, 4, 5))); /// Destructor ~Timer(); @@ -72,15 +77,23 @@ const Timer &operator=(const Timer &) = delete; }; +llvm::SignpostEmitter &GetSignposts(); + } // namespace lldb_private // Use a format string because LLVM_PRETTY_FUNCTION might not be a string // literal. #define LLDB_SCOPED_TIMER() \ static ::lldb_private::Timer::Category _cat(LLVM_PRETTY_FUNCTION); \ - ::lldb_private::Timer _scoped_timer(_cat, "%s", LLVM_PRETTY_FUNCTION) -#define LLDB_SCOPED_TIMERF(...) \ + ::lldb_private::Timer _scoped_timer(_cat, false, "%s", \ + LLVM_PRETTY_FUNCTION); \ + SIGNPOST_EMITTER_START_INTERVAL(::lldb_private::GetSignposts(), \ + &_scoped_timer, "%s", LLVM_PRETTY_FUNCTION) + +#define LLDB_SCOPED_TIMERF(FMT, ...) \ static ::lldb_private::Timer::Category _cat(LLVM_PRETTY_FUNCTION); \ - ::lldb_private::Timer _scoped_timer(_cat, __VA_ARGS__) + ::lldb_private::Timer _scoped_timer(_cat, false, FMT, __VA_ARGS__); \ + SIGNPOST_EMITTER_START_INTERVAL(::lldb_private::GetSignposts(), \ + &_scoped_timer, FMT, __VA_ARGS__) #endif // LLDB_UTILITY_TIMER_H Index: lldb/source/Utility/Timer.cpp =================================================================== --- lldb/source/Utility/Timer.cpp +++ lldb/source/Utility/Timer.cpp @@ -33,6 +33,8 @@ /// Allows llvm::Timer to emit signposts when supported. static llvm::ManagedStatic Signposts; +llvm::SignpostEmitter &lldb_private::GetSignposts() { return *Signposts; } + std::atomic Timer::g_quiet(true); std::atomic Timer::g_display_depth(0); static std::mutex &GetFileMutex() { @@ -57,9 +59,13 @@ void Timer::SetQuiet(bool value) { g_quiet = value; } -Timer::Timer(Timer::Category &category, const char *format, ...) +Timer::Timer(Timer::Category &category, bool emit_signpost, const char *format, ...) : m_category(category), m_total_start(std::chrono::steady_clock::now()) { - Signposts->startInterval(this, m_category.GetName()); + // The LLDB_SCOPED_TIMER macro does this for us to benefit from + // os_log string optimizations. + if (emit_signpost) + Signposts->startInterval(this, m_category.GetName()); + TimerStack &stack = GetTimerStackForCurrentThread(); stack.push_back(this); Index: lldb/unittests/Utility/TimerTest.cpp =================================================================== --- lldb/unittests/Utility/TimerTest.cpp +++ lldb/unittests/Utility/TimerTest.cpp @@ -17,7 +17,7 @@ Timer::ResetCategoryTimes(); { static Timer::Category tcat("CAT1"); - Timer t(tcat, "."); + Timer t(tcat, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(10)); } StreamString ss; @@ -32,10 +32,10 @@ Timer::ResetCategoryTimes(); { static Timer::Category tcat1("CAT1"); - Timer t1(tcat1, "."); + Timer t1(tcat1, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(10)); // Explicitly testing the same category as above. - Timer t2(tcat1, "."); + Timer t2(tcat1, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(10)); } StreamString ss; @@ -52,10 +52,10 @@ Timer::ResetCategoryTimes(); { static Timer::Category tcat1("CAT1"); - Timer t1(tcat1, "."); + Timer t1(tcat1, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(100)); static Timer::Category tcat2("CAT2"); - Timer t2(tcat2, "."); + Timer t2(tcat2, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(10)); } StreamString ss; @@ -76,15 +76,15 @@ Timer::ResetCategoryTimes(); { static Timer::Category tcat1("CAT1"); - Timer t1(tcat1, "."); + Timer t1(tcat1, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(100)); static Timer::Category tcat2("CAT2"); { - Timer t2(tcat2, "."); + Timer t2(tcat2, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(10)); } { - Timer t3(tcat2, "."); + Timer t3(tcat2, false, "."); std::this_thread::sleep_for(std::chrono::milliseconds(10)); } } Index: llvm/include/llvm/Support/Signposts.h =================================================================== --- llvm/include/llvm/Support/Signposts.h +++ llvm/include/llvm/Support/Signposts.h @@ -18,8 +18,17 @@ #define LLVM_SUPPORT_SIGNPOSTS_H #include "llvm/ADT/StringRef.h" +#include "llvm/Config/config.h" #include +#if LLVM_SUPPORT_XCODE_SIGNPOSTS +#include +#include +#endif + +#define SIGNPOSTS_AVAILABLE() \ + __builtin_available(macos 10.14, iOS 12, tvOS 12, watchOS 5, *) + namespace llvm { class SignpostEmitterImpl; @@ -36,8 +45,27 @@ /// Begin a signposted interval for a given object. void startInterval(const void *O, StringRef Name); + +#if LLVM_SUPPORT_XCODE_SIGNPOSTS + os_log_t &getLogger() const; + os_signpost_id_t getSignpostForObject(const void *O); +#endif + + /// A macro to take advantage of the special format string handling + /// in the os_signpost API. The format string substitution is + /// deferred to the log consumer and done outside of the + /// application. +#define SIGNPOST_EMITTER_START_INTERVAL(SIGNPOST_EMITTER, O, ...) \ + do { \ + if ((SIGNPOST_EMITTER).isEnabled()) \ + if (SIGNPOSTS_AVAILABLE()) \ + os_signpost_interval_begin((SIGNPOST_EMITTER).getLogger(), \ + (SIGNPOST_EMITTER).getSignpostForObject(O), \ + "LLVM Timers", __VA_ARGS__); \ + } while (0) + /// End a signposted interval for a given object. - void endInterval(const void *O, StringRef Name); + void endInterval(const void *O, StringRef Name = StringRef()); }; } // end namespace llvm Index: llvm/lib/Support/Signposts.cpp =================================================================== --- llvm/lib/Support/Signposts.cpp +++ llvm/lib/Support/Signposts.cpp @@ -10,19 +10,14 @@ #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 "llvm/Support/Mutex.h" -#include -#include #endif // if LLVM_SUPPORT_XCODE_SIGNPOSTS using namespace llvm; #if LLVM_SUPPORT_XCODE_SIGNPOSTS -#define SIGNPOSTS_AVAILABLE() \ - __builtin_available(macos 10.14, iOS 12, tvOS 12, watchOS 5, *) namespace { os_log_t *LogCreator() { os_log_t *X = new os_log_t; @@ -40,13 +35,13 @@ namespace llvm { class SignpostEmitterImpl { using LogPtrTy = std::unique_ptr; - using LogTy = LogPtrTy::element_type; LogPtrTy SignpostLog; DenseMap Signposts; sys::SmartMutex Mutex; - LogTy &getLogger() const { return *SignpostLog; } +public: + os_log_t &getLogger() const { return *SignpostLog; } os_signpost_id_t getSignpostForObject(const void *O) { sys::SmartScopedLock Lock(Mutex); const auto &I = Signposts.find(O); @@ -60,7 +55,6 @@ return Inserted.first->second; } -public: SignpostEmitterImpl() : SignpostLog(LogCreator()) {} bool isEnabled() const { @@ -83,8 +77,12 @@ if (isEnabled()) { if (SIGNPOSTS_AVAILABLE()) { // Both strings used here are required to be constant literal strings. - os_signpost_interval_end(getLogger(), getSignpostForObject(O), - "LLVM Timers", "End %s", Name.data()); + if (Name.empty()) + os_signpost_interval_end(getLogger(), getSignpostForObject(O), + "LLVM Timers", ""); + else + os_signpost_interval_end(getLogger(), getSignpostForObject(O), + "LLVM Timers", "End %s", Name.data()); } } } @@ -125,6 +123,13 @@ #endif // if !HAVE_ANY_SIGNPOST_IMPL } +#if HAVE_ANY_SIGNPOST_IMPL +os_log_t &SignpostEmitter::getLogger() const { return Impl->getLogger(); } +os_signpost_id_t SignpostEmitter::getSignpostForObject(const void *O) { + return Impl->getSignpostForObject(O); +} +#endif + void SignpostEmitter::endInterval(const void *O, StringRef Name) { #if HAVE_ANY_SIGNPOST_IMPL if (Impl == nullptr)