[lldb-vscode] only report long running progress events

When the number of shared libs is massive, there could be hundreds of
thousands of short lived progress events sent to the IDE, which makes it
irresponsive while it's processing all this data. As these small jobs
take less than a second to process, the user doesn't even see them,
because the IDE only display the progress of long operations. So it's
better not to send these events.

I'm fixing that by sending only the events that are taking longer than 5
seconds to process.
In a specific run, I got the number of events from ~500k to 100, because
there was only 1 big lib to parse.

I've tried this on several small and massive targets, and it seems to
work fine.

Differential Revision: https://reviews.llvm.org/D101128

lldb/tools/lldb-vscode/ProgressEvent.cpp

@@ -13,43 +13,88 @@
 using namespace lldb_vscode;
 using namespace llvm;
 
-ProgressEvent::ProgressEvent(uint64_t progress_id, const char *message,
-                             uint64_t completed, uint64_t total)
-    : m_progress_id(progress_id), m_message(message) {
-  if (completed == total)
-    m_event_type = progressEnd;
-  else if (completed == 0)
-    m_event_type = progressStart;
-  else if (completed < total)
-    m_event_type = progressUpdate;
-  else
-    m_event_type = progressInvalid;
+// The minimum duration of an event for it to be reported
+const std::chrono::duration<double> kStartProgressEventReportDelay =
+    std::chrono::seconds(1);
+// The minimum time interval between update events for reporting. If multiple
+// updates fall within the same time interval, only the latest is reported.
+const std::chrono::duration<double> kUpdateProgressEventReportDelay =
+    std::chrono::milliseconds(250);
 
-  if (0 < total && total < UINT64_MAX)
-    m_percentage = (uint32_t)(((float)completed / (float)total) * 100.0);
+ProgressEvent::ProgressEvent(uint64_t progress_id, Optional<StringRef> message,
+                             uint64_t completed, uint64_t total,
+                             const ProgressEvent *prev_event)
+    : m_progress_id(progress_id) {
+  if (message)
+    m_message = message->str();
+
+  const bool calculate_percentage = total != UINT64_MAX;
+  if (completed == 0) {
+    // Start event
+    m_event_type = progressStart;
+    // Wait a bit before reporting the start event in case in completes really
+    // quickly.
+    m_minimum_allowed_report_time =
+        m_creation_time + kStartProgressEventReportDelay;
+    if (calculate_percentage)
+      m_percentage = 0;
+  } else if (completed == total) {
+    // End event
+    m_event_type = progressEnd;
+    // We should report the end event right away.
+    m_minimum_allowed_report_time = std::chrono::seconds::zero();
+    if (calculate_percentage)
+      m_percentage = 100;
+  } else {
+    // Update event
+    assert(prev_event);
+    m_percentage = std::min(
+        (uint32_t)((double)completed / (double)total * 100.0), (uint32_t)99);
+    if (prev_event->Reported()) {
+      // Add a small delay between reports
+      m_minimum_allowed_report_time =
+          prev_event->m_minimum_allowed_report_time +
+          kUpdateProgressEventReportDelay;
+    } else {
+      // We should use the previous timestamp, as it's still pending
+      m_minimum_allowed_report_time = prev_event->m_minimum_allowed_report_time;
+    }
+  }
 }
 
-bool ProgressEvent::operator==(const ProgressEvent &other) const {
+Optional<ProgressEvent> ProgressEvent::Create(uint64_t progress_id,
+                                              Optional<StringRef> message,
+                                              uint64_t completed,
+                                              uint64_t total,
+                                              const ProgressEvent *prev_event) {
+  ProgressEvent event(progress_id, message, completed, total, prev_event);
+  // We shouldn't show unnamed start events in the IDE
+  if (event.GetEventType() == progressStart && event.GetEventName().empty())
+    return None;
+
+  if (prev_event && prev_event->EqualsForIDE(event))
+    return None;
+
+  return event;
+}
+
+bool ProgressEvent::EqualsForIDE(const ProgressEvent &other) const {
   return m_progress_id == other.m_progress_id &&
          m_event_type == other.m_event_type &&
          m_percentage == other.m_percentage;
 }
 
-const char *ProgressEvent::GetEventName() const {
+ProgressEventType ProgressEvent::GetEventType() const { return m_event_type; }
+
+StringRef ProgressEvent::GetEventName() const {
   if (m_event_type == progressStart)
     return "progressStart";
   else if (m_event_type == progressEnd)
     return "progressEnd";
-  else if (m_event_type == progressUpdate)
-    return "progressUpdate";
   else
-    return "progressInvalid";
+    return "progressUpdate";
 }
 
-bool ProgressEvent::IsValid() const { return m_event_type != progressInvalid; }
-
-uint64_t ProgressEvent::GetID() const { return m_progress_id; }
-
 json::Value ProgressEvent::ToJSON() const {
   llvm::json::Object event(CreateEventObject(GetEventName()));
   llvm::json::Object body;
@@ -65,9 +110,7 @@ json::Value ProgressEvent::ToJSON() const {
     body.try_emplace("cancellable", false);
   }
 
-  auto now = std::chrono::duration<double>(
-      std::chrono::system_clock::now().time_since_epoch());
-  std::string timestamp(llvm::formatv("{0:f9}", now.count()));
+  std::string timestamp(llvm::formatv("{0:f9}", m_creation_time.count()));
   EmplaceSafeString(body, "timestamp", timestamp);
 
   if (m_percentage)
@@ -77,17 +120,108 @@ json::Value ProgressEvent::ToJSON() const {
   return json::Value(std::move(event));
 }
 
-ProgressEventFilterQueue::ProgressEventFilterQueue(
-    std::function<void(ProgressEvent)> callback)
-    : m_callback(callback) {}
+bool ProgressEvent::Report(ProgressEventReportCallback callback) {
+  if (Reported())
+    return true;
+  if (std::chrono::system_clock::now().time_since_epoch() <
+      m_minimum_allowed_report_time)
+    return false;
 
-void ProgressEventFilterQueue::Push(const ProgressEvent &event) {
-  if (!event.IsValid())
-    return;
+  m_reported = true;
+  callback(*this);
+  return true;
+}
 
-  auto it = m_last_events.find(event.GetID());
-  if (it == m_last_events.end() || !(it->second == event)) {
-    m_last_events[event.GetID()] = event;
-    m_callback(event);
+bool ProgressEvent::Reported() const { return m_reported; }
+
+ProgressEventManager::ProgressEventManager(
+    const ProgressEvent &start_event,
+    ProgressEventReportCallback report_callback)
+    : m_start_event(start_event), m_finished(false),
+      m_report_callback(report_callback) {}
+
+bool ProgressEventManager::ReportIfNeeded() {
+  // The event finished before we were able to report it.
+  if (!m_start_event.Reported() && Finished())
+    return true;
+
+  if (!m_start_event.Report(m_report_callback))
+    return false;
+
+  if (m_last_update_event)
+    m_last_update_event->Report(m_report_callback);
+  return true;
+}
+
+const ProgressEvent &ProgressEventManager::GetMostRecentEvent() const {
+  return m_last_update_event ? *m_last_update_event : m_start_event;
+}
+
+void ProgressEventManager::Update(uint64_t progress_id, uint64_t completed,
+                                  uint64_t total) {
+  if (Optional<ProgressEvent> event = ProgressEvent::Create(
+          progress_id, None, completed, total, &GetMostRecentEvent())) {
+    if (event->GetEventType() == progressEnd)
+      m_finished = true;
+
+    m_last_update_event = *event;
+    ReportIfNeeded();
+  }
+}
+
+bool ProgressEventManager::Finished() const { return m_finished; }
+
+ProgressEventReporter::ProgressEventReporter(
+    ProgressEventReportCallback report_callback)
+    : m_report_callback(report_callback) {
+  m_thread_should_exit = false;
+  m_thread = std::thread([&] {
+    while (!m_thread_should_exit) {
+      std::this_thread::sleep_for(kUpdateProgressEventReportDelay);
+      ReportStartEvents();
+    }
+  });
+}
+
+ProgressEventReporter::~ProgressEventReporter() {
+  m_thread_should_exit = true;
+  m_thread.join();
+}
+
+void ProgressEventReporter::ReportStartEvents() {
+  std::lock_guard<std::mutex> locker(m_mutex);
+
+  while (!m_unreported_start_events.empty()) {
+    ProgressEventManagerSP event_manager = m_unreported_start_events.front();
+    if (event_manager->Finished())
+      m_unreported_start_events.pop();
+    else if (event_manager->ReportIfNeeded())
+      m_unreported_start_events
+          .pop(); // we remove it from the queue as it started reporting
+                  // already, the Push method will be able to continue its
+                  // reports.
+    else
+      break; // If we couldn't report it, then the next event in the queue won't
+             // be able as well, as it came later.
+  }
+}
+
+void ProgressEventReporter::Push(uint64_t progress_id, const char *message,
+                                 uint64_t completed, uint64_t total) {
+  std::lock_guard<std::mutex> locker(m_mutex);
+
+  auto it = m_event_managers.find(progress_id);
+  if (it == m_event_managers.end()) {
+    if (Optional<ProgressEvent> event =
+            ProgressEvent::Create(progress_id, StringRef(message), completed, total)) {
+      ProgressEventManagerSP event_manager =
+          std::make_shared<ProgressEventManager>(*event, m_report_callback);
+      m_event_managers.insert({progress_id, event_manager});
+      m_unreported_start_events.push(event_manager);
+    }
+  } else {
+    it->second->Update(progress_id, completed, total);
+    if (it->second->Finished())
+      m_event_managers.erase(it);
   }
 }

lldb/tools/lldb-vscode/ProgressEvent.h

@@ -6,6 +6,10 @@
 //
 //===----------------------------------------------------------------------===//
 
+#include <mutex>
+#include <queue>
+#include <thread>
+
 #include "VSCodeForward.h"
 
 #include "llvm/Support/JSON.h"
@@ -13,50 +17,142 @@
 namespace lldb_vscode {
 
 enum ProgressEventType {
-  progressInvalid,
   progressStart,
   progressUpdate,
   progressEnd
 };
 
+class ProgressEvent;
+using ProgressEventReportCallback = std::function<void(ProgressEvent &)>;
+
 class ProgressEvent {
 public:
-  ProgressEvent() {}
-
-  ProgressEvent(uint64_t progress_id, const char *message, uint64_t completed,
-                uint64_t total);
+  /// Actual constructor to use that returns an optional, as the event might be
+  /// not apt for the IDE, e.g. an unnamed start event, or a redundant one.
+  ///
+  /// \param[in] progress_id
+  ///   ID for this event.
+  ///
+  /// \param[in] message
+  ///   Message to display in the UI. Required for start events.
+  ///
+  /// \param[in] completed
+  ///   Number of jobs completed.
+  ///
+  /// \param[in] total
+  ///   Total number of jobs, or \b UINT64_MAX if not determined.
+  ///
+  /// \param[in] prev_event
+  ///   Previous event if this one is an update. If \b nullptr, then a start
+  ///   event will be created.
+  static llvm::Optional<ProgressEvent>
+  Create(uint64_t progress_id, llvm::Optional<llvm::StringRef> message,
+         uint64_t completed, uint64_t total,
+         const ProgressEvent *prev_event = nullptr);
 
   llvm::json::Value ToJSON() const;
 
-  /// This operator returns \b true if two event messages
-  /// would result in the same event for the IDE, e.g.
-  /// same rounded percentage.
-  bool operator==(const ProgressEvent &other) const;
+  /// \return
+  ///       \b true if two event messages would result in the same event for the
+  ///       IDE, e.g. same rounded percentage.
+  bool EqualsForIDE(const ProgressEvent &other) const;
 
-  const char *GetEventName() const;
+  llvm::StringRef GetEventName() const;
 
-  bool IsValid() const;
+  ProgressEventType GetEventType() const;
 
-  uint64_t GetID() const;
+  /// Report this progress event to the provided callback only if enough time
+  /// has passed since the creation of the event and since the previous reported
+  /// update.
+  bool Report(ProgressEventReportCallback callback);
+
+  bool Reported() const;
 
 private:
+  ProgressEvent(uint64_t progress_id, llvm::Optional<llvm::StringRef> message,
+                uint64_t completed, uint64_t total,
+                const ProgressEvent *prev_event);
+
   uint64_t m_progress_id;
-  const char *m_message;
+  std::string m_message;
   ProgressEventType m_event_type;
   llvm::Optional<uint32_t> m_percentage;
+  std::chrono::duration<double> m_creation_time =
+      std::chrono::system_clock::now().time_since_epoch();
+  std::chrono::duration<double> m_minimum_allowed_report_time;
+  bool m_reported = false;
 };
 
-/// Class that filters out progress event messages that shouldn't be reported
-/// to the IDE, either because they are invalid or because they are too chatty.
-class ProgressEventFilterQueue {
+/// Class that keeps the start event and its most recent update.
+/// It controls when the event should start being reported to the IDE.
+class ProgressEventManager {
 public:
-  ProgressEventFilterQueue(std::function<void(ProgressEvent)> callback);
+  ProgressEventManager(const ProgressEvent &start_event,
+                       ProgressEventReportCallback report_callback);
 
-  void Push(const ProgressEvent &event);
+  /// Report the start event and the most recent update if the event has lasted
+  /// for long enough.
+  ///
+  /// \return
+  ///     \b false if the event hasn't finished and hasn't reported anything
+  ///     yet.
+  bool ReportIfNeeded();
+
+  /// Receive a new progress event for the start event and try to report it if
+  /// appropriate.
+  void Update(uint64_t progress_id, uint64_t completed, uint64_t total);
+
+  /// \return
+  ///     \b true if a \a progressEnd event has been notified. There's no
+  ///     need to try to report manually an event that has finished.
+  bool Finished() const;
+
+  const ProgressEvent &GetMostRecentEvent() const;
 
 private:
-  std::function<void(ProgressEvent)> m_callback;
-  std::map<uint64_t, ProgressEvent> m_last_events;
+  ProgressEvent m_start_event;
+  llvm::Optional<ProgressEvent> m_last_update_event;
+  bool m_finished;
+  ProgressEventReportCallback m_report_callback;
+};
+
+using ProgressEventManagerSP = std::shared_ptr<ProgressEventManager>;
+
+/// Class that filters out progress event messages that shouldn't be reported
+/// to the IDE, because they are invalid, they carry no new information, or they
+/// don't last long enough.
+///
+/// We need to limit the amount of events that are sent to the IDE, as they slow
+/// the render thread of the UI user, and they end up spamming the DAP
+/// connection, which also takes some processing time out of the IDE.
+class ProgressEventReporter {
+public:
+  /// \param[in] report_callback
+  ///     Function to invoke to report the event to the IDE.
+  ProgressEventReporter(ProgressEventReportCallback report_callback);
+
+  ~ProgressEventReporter();
+
+  /// Add a new event to the internal queue and report the event if
+  /// appropriate.
+  void Push(uint64_t progress_id, const char *message, uint64_t completed,
+            uint64_t total);
+
+private:
+  /// Report to the IDE events that haven't been reported to the IDE and have
+  /// lasted long enough.
+  void ReportStartEvents();
+
+  ProgressEventReportCallback m_report_callback;
+  std::map<uint64_t, ProgressEventManagerSP> m_event_managers;
+  /// Queue of start events in chronological order
+  std::queue<ProgressEventManagerSP> m_unreported_start_events;
+  /// Thread used to invoke \a ReportStartEvents periodically.
+  std::thread m_thread;
+  bool m_thread_should_exit;
+  /// Mutex that prevents running \a Push and \a ReportStartEvents
+  /// simultaneously, as both read and modify the same underlying objects.
+  std::mutex m_mutex;
 };
 
 } // namespace lldb_vscode

lldb/tools/lldb-vscode/VSCode.cpp

@@ -42,7 +42,7 @@ VSCode::VSCode()
       focus_tid(LLDB_INVALID_THREAD_ID), sent_terminated_event(false),
       stop_at_entry(false), is_attach(false), reverse_request_seq(0),
       waiting_for_run_in_terminal(false),
-      progress_event_queue(
+      progress_event_reporter(
           [&](const ProgressEvent &event) { SendJSON(event.ToJSON()); }) {
   const char *log_file_path = getenv("LLDBVSCODE_LOG");
 #if defined(_WIN32)
@@ -322,8 +322,9 @@ void VSCode::SendOutput(OutputType o, const llvm::StringRef output) {
 //   };
 // }
 
-void VSCode::SendProgressEvent(const ProgressEvent &event) {
-  progress_event_queue.Push(event);
+void VSCode::SendProgressEvent(uint64_t progress_id, const char *message,
+                               uint64_t completed, uint64_t total) {
+  progress_event_reporter.Push(progress_id, message, completed, total);
 }
 
 void __attribute__((format(printf, 3, 4)))

lldb/tools/lldb-vscode/VSCode.h

@@ -114,7 +114,7 @@ struct VSCode {
   uint32_t reverse_request_seq;
   std::map<std::string, RequestCallback> request_handlers;
   bool waiting_for_run_in_terminal;
-  ProgressEventFilterQueue progress_event_queue;
+  ProgressEventReporter progress_event_reporter;
   // Keep track of the last stop thread index IDs as threads won't go away
   // unless we send a "thread" event to indicate the thread exited.
   llvm::DenseSet<lldb::tid_t> thread_ids;
@@ -125,10 +125,6 @@ struct VSCode {
   int64_t GetLineForPC(int64_t sourceReference, lldb::addr_t pc) const;
   ExceptionBreakpoint *GetExceptionBreakpoint(const std::string &filter);
   ExceptionBreakpoint *GetExceptionBreakpoint(const lldb::break_id_t bp_id);
-  // Send the JSON in "json_str" to the "out" stream. Correctly send the
-  // "Content-Length:" field followed by the length, followed by the raw
-  // JSON bytes.
-  void SendJSON(const std::string &json_str);
 
   // Serialize the JSON value into a string and send the JSON packet to
   // the "out" stream.
@@ -138,7 +134,8 @@ struct VSCode {
 
   void SendOutput(OutputType o, const llvm::StringRef output);
 
-  void SendProgressEvent(const ProgressEvent &event);
+  void SendProgressEvent(uint64_t progress_id, const char *message,
+                         uint64_t completed, uint64_t total);
 
   void __attribute__((format(printf, 3, 4)))
   SendFormattedOutput(OutputType o, const char *format, ...);
@@ -208,6 +205,12 @@ struct VSCode {
   ///     The callback to execute when the given request is triggered by the
   ///     IDE.
   void RegisterRequestCallback(std::string request, RequestCallback callback);
+
+private:
+  // Send the JSON in "json_str" to the "out" stream. Correctly send the
+  // "Content-Length:" field followed by the length, followed by the raw
+  // JSON bytes.
+  void SendJSON(const std::string &json_str);
 };
 
 extern VSCode g_vsc;

lldb/tools/lldb-vscode/lldb-vscode.cpp

@@ -389,8 +389,7 @@ void ProgressEventThreadFunction() {
         const char *message = lldb::SBDebugger::GetProgressFromEvent(
             event, progress_id, completed, total, is_debugger_specific);
         if (message)
-          g_vsc.SendProgressEvent(
-              ProgressEvent(progress_id, message, completed, total));
+          g_vsc.SendProgressEvent(progress_id, message, completed, total);
       }
     }
   }