[lldb] Instrument SB API with signposts

[JDevlieghere]

Summary

Instrument the SB API with signposts on Darwin. This gives us a time profile on whose behalf LLDB spends time (particularly when run via the SBAPI from an IDE).

[jingham]

I was about to say this shouldn't matter, since most people don't run with timers enabled and the timers should be no-ops when timing is off. But LLDB_SCOPED_TIMER seems to do a bunch of work even when the timers are disabled. The work includes "look up the Category in the map of categories, making a new one if not found", get the current time of day and stash that away, and do whatever the Signpost chooses to do on entry & exit. So this would be adding non-trivial work for everybody for every SB API call.

Is this really necessary? Seems like you could have LLDB_SCOPED_TIMER do nothing if the Timer::g_display_depth == 0. That would mean that you wouldn't get timings for the remaining bit of any timers that would have been active when you enabled the timers, but that doesn't seem particularly wrong to me...

I'm a little confused about what you want to achieve as well. You said you want to see "on whose behalf LLDB spends time". This change will tell you that during the course of the debug session, SBWatchpoint::SetSP consumed N seconds, and SBWatchpoint::GetSP M seconds. It will also dump some text to the console when an SB API is called, but I'm not sure how you would get access to that info and attribute it back to the caller.

But the timers don't record stacks, so you won't know anything about the callers, you will just know that that SB API consumed N seconds. I'm not sure how that tells you "on whose behalf lldb spends time". Of course, the Signpost call could do anything you want, so you could have a variant that captures stacks, but then these calls are going to get even more expensive...

[labath]

In D117632#3253445, @jingham wrote:

I was about to say this shouldn't matter, since most people don't run with timers enabled and the timers should be no-ops when timing is off. But LLDB_SCOPED_TIMER seems to do a bunch of work even when the timers are disabled. The work includes "look up the Category in the map of categories, making a new one if not found", get the current time of day and stash that away, and do whatever the Signpost chooses to do on entry & exit. So this would be adding non-trivial work for everybody for every SB API call.

Is this really necessary? Seems like you could have LLDB_SCOPED_TIMER do nothing if the Timer::g_display_depth == 0. That would mean that you wouldn't get timings for the remaining bit of any timers that would have been active when you enabled the timers, but that doesn't seem particularly wrong to me...

The way that timers currently work is that they are always active and measuring and can always be retrieved via log timers dump. g_display_depth (and log timers enable) only control whether their information gets dumped to stdout.

Apart from that, I don't have any particular opinion on this. I can't say I have found the lldb timers particularly useful. I think we could make then sufficiently cheap so that they could be added to every SB method (and hidden in the LLDB_RECORD_METHOD macro, since we already have it), but if I wanted to do some performance analysis, I'd probably use a profiler.

[JDevlieghere]

Do you actually care about the timers or is this really about getting these methods instrumented with signposts on our platform? If it's the latter, I think it would make more sense to put that call in the LLDB_RECORD_* macros (which I'm planning to rename imminently). If this is about instrumenting the API, we can use the old reproducer logic to differentiate between calls made across the API boundary. Maybe it would make sense to only instrument external calls.

If it's just the signposts I'm not worried about performance, there's no way that's slower than the old reproducer instrumentation :-)

[aprantl]

In D117632#3255158, @JDevlieghere wrote:

Do you actually care about the timers or is this really about getting these methods instrumented with signposts on our platform? If it's the latter, I think it would make more sense to put that call in the LLDB_RECORD_* macros (which I'm planning to rename imminently). If this is about instrumenting the API, we can use the old reproducer logic to differentiate between calls made across the API boundary. Maybe it would make sense to only instrument external calls.

If it's just the signposts I'm not worried about performance, there's no way that's slower than the old reproducer instrumentation :-)

That's right, I'm only interested in signposts. I'll put this patch aside for now, it would make sense to integrate this functionality into the properly renamed macros!

[aprantl]

I'm a little confused about what you want to achieve as well.

With signposts you get a flamegraph of all nested signposted functions, which is really intuitive to look at.

[JDevlieghere]

I can do this after the rename.

[aprantl]

Assuming UpdateBoundary is only called in the destructor this looks nice!

lldb/source/Utility/Instrumentation.cpp

22

///

[JDevlieghere]

Yup, at this point I might as well inline it.

lldb/include/lldb/Utility/Instrumentation.h

 class Instrumenter {
 public:
   Instrumenter(llvm::StringRef pretty_func, std::string &&pretty_args = {});
   ~Instrumenter();
 
 private:
   void UpdateBoundary();
 
+  llvm::StringRef m_pretty_func;
+
   /// Whether this function call was the one crossing the API boundary.
   bool m_local_boundary = false;
 };
 } // namespace instrumentation
 } // namespace lldb_private
 
 #define LLDB_INSTRUMENT()                                                      \
   lldb_private::instrumentation::Instrumenter _instr(LLVM_PRETTY_FUNCTION);
 
 #define LLDB_INSTRUMENT_VA(...)                                                \
   lldb_private::instrumentation::Instrumenter _instr(                          \
       LLVM_PRETTY_FUNCTION,                                                    \
       lldb_private::instrumentation::stringify_args(__VA_ARGS__));
 
 #endif // LLDB_UTILITY_INSTRUMENTATION_H

lldb/source/Utility/Instrumentation.cpp

 //===-- Instrumentation.cpp -----------------------------------------------===//
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
 #include "lldb/Utility/Instrumentation.h"
+#include "llvm/Support/Signposts.h"
+
 #include <cstdio>
 #include <cstdlib>
 #include <limits>
 #include <thread>
 
 using namespace lldb_private;
 using namespace lldb_private::instrumentation;
 
 // Whether we're currently across the API boundary.
 static thread_local bool g_global_boundary = false;
 
+// Instrument SB API calls with singposts when supported.
+static llvm::ManagedStatic<llvm::SignpostEmitter> g_api_signposts;
+
 Instrumenter::Instrumenter(llvm::StringRef pretty_func,
                            std::string &&pretty_args)
-    : m_local_boundary(false) {
+    : m_pretty_func(pretty_func), m_local_boundary(false) {
   if (!g_global_boundary) {
     g_global_boundary = true;
     m_local_boundary = true;
+    g_api_signposts->startInterval(this, m_pretty_func);
   }
   LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "[{0}] {1} ({2})",
-           m_local_boundary ? "external" : "internal", pretty_func,
+           m_local_boundary ? "external" : "internal", m_pretty_func,
            pretty_args);
 }
 
-Instrumenter::~Instrumenter() { UpdateBoundary(); }
-
-void Instrumenter::UpdateBoundary() {
-  if (m_local_boundary)
+Instrumenter::~Instrumenter() {
+  if (m_local_boundary) {
     g_global_boundary = false;
+    g_api_signposts->endInterval(this, m_pretty_func);
+  }
 }