aprantl created this revision.
aprantl added reviewers: JDevlieghere, dsanders, jroelofs.
Herald added subscribers: dexonsmith, hiraditya.
aprantl requested review of this revision.
Herald added a project: LLVM.
This is more an RFC at this point. I'm curious about feedback!
One nice feature of the os_signpost API is that format string substitutions
happen in the consumer, not the logging application. LLVM's current Signpost
class doesn't take advantage of this though and instead always uses a static
`"Begin/End %s" ` format string.
This patch is proof of concept for how to use variadic macros to allow the API
to be used as intended. Unfortunately, the primary use-case I had in mind (the
`LLDB_SCOPED_TIMER()` macro) does not get much better from this, because
`__PRETTY_FUNCTION__` is *not* a macro, but a static string, so signposts
created by `LLDB_SCOPED_TIMER()` still use a static `"%s"` format string. At
least `LLDB_SCOPED_TIMERF()` works as intended.
https://reviews.llvm.org/D103575
Files:
lldb/include/lldb/Utility/Timer.h
lldb/source/Utility/Timer.cpp
lldb/unittests/Utility/TimerTest.cpp
llvm/include/llvm/Support/Signposts.h
llvm/lib/Support/Signposts.cpp
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 <Availability.h>
-#include <os/signpost.h>
#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<os_log_t, LogDeleter>;
- using LogTy = LogPtrTy::element_type;
LogPtrTy SignpostLog;
DenseMap<const void *, os_signpost_id_t> Signposts;
sys::SmartMutex<true> Mutex;
- LogTy &getLogger() const { return *SignpostLog; }
+public:
+ os_log_t &getLogger() const { return *SignpostLog; }
os_signpost_id_t getSignpostForObject(const void *O) {
sys::SmartScopedLock<true> 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)
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 <memory>
+#if LLVM_SUPPORT_XCODE_SIGNPOSTS
+#include <Availability.h>
+#include <os/signpost.h>
+#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: 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: 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<llvm::SignpostEmitter> Signposts;
+llvm::SignpostEmitter &lldb_private::GetSignposts() { return *Signposts; }
+
std::atomic<bool> Timer::g_quiet(true);
std::atomic<unsigned> 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/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 <atomic>
#include <cstdint>
+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
_______________________________________________
lldb-commits mailing list
lldb-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-commits
