[lldb/Core] Fix finite progress event reporting

[mib]

Summary

This patch should fix event handling for finite progress reports.

Previously, the event handler would get stuck when receiving a finite
progress report, and stop displaying upcoming reports.
This was due to the fact that we were checking if the progress event was
completed by calling GetCompleted but returns the completion amount
instead of saying whether it's completed.

That caused the current event id to remain the same, preventing all the
following progress reports to be shown to the user.

This patch also adds some logging to facilitate debugging progress events.

rdar://91788326

Signed-off-by: Med Ismail Bennani <[e-mail]>

[JDevlieghere]

The fix looks good but I'm torn about the added logging. On the one hand it'll make finding issues like this easier in the future, but on the other hand, while this code isn't "hot", it is something where performance matters. My concern is that this will potentially cause progress events to get queued. If the progress updates aren't real time they are pretty much useless.

If it were up to me I'd probably remove the logging altogether, but maybe there's a middle ground where we have one log message that we only print in verbose mode? Then the (default) penalty is just checking if the log is enabled and verbose.

What do you think?

[mib]

In D128768#3619349, @JDevlieghere wrote:

The fix looks good but I'm torn about the added logging. On the one hand it'll make finding issues like this easier in the future, but on the other hand, while this code isn't "hot", it is something where performance matters. My concern is that this will potentially cause progress events to get queued. If the progress updates aren't real time they are pretty much useless.

If it were up to me I'd probably remove the logging altogether, but maybe there's a middle ground where we have one log message that we only print in verbose mode? Then the (default) penalty is just checking if the log is enabled and verbose.

What do you think?

Sounds good to me

[mib]

Log only when verbose mode is enabled

[JDevlieghere]

lldb/source/Core/Debugger.cpp

1845–1861

What's m_uid?

I would either fold these two log statements into one, and use LLDB_LOGV(GetLog(LLDBLog::Events), ... or I would use the event's dump method:

if (log && log->GetVerbose()) {
  StreamString log_stream;
  log_stream << "Debugger::HandleProgressEvent" ... 
  data->dump(log_stream);
  log->PutString(log_stream.GetString());
}

[mib]

lldb/source/Core/Debugger.cpp

1845–1861

Since some progress events can be broadcasted to a specific debugger instance, m_uid tells use which debugger id is handling this

[mib]

Refactor logging code

[JDevlieghere]

lldb/source/Core/Debugger.cpp

1840–1841

We should still reset the m_current_event_id here, otherwise we can get out of sync if someone changes the value of GetShowProgress.

[mib]

Address @JDevlieghere comment

[JDevlieghere]

LGTM

lldb/source/Core/Debugger.cpp

 
 lldb::thread_result_t Debugger::IOHandlerThread() {
   RunIOHandlers();
   StopEventHandlerThread();
   return {};
 }
 
 void Debugger::HandleProgressEvent(const lldb::EventSP &event_sp) {
+  Log *log = GetLog(LLDBLog::Events);
+
+  LLDB_LOGF(log, "%p Debugger('%llu')::HandleProgressEvent (event_sp = {%p})",
+            static_cast<void *>(this), m_uid,
+            static_cast<void *>(event_sp.get()));
+
   auto *data = ProgressEventData::GetEventDataFromEvent(event_sp.get());
   if (!data)
     return;
 
   // Do some bookkeeping for the current event, regardless of whether we're
   // going to show the progress.
   const uint64_t id = data->GetID();
   if (m_current_event_id) {
+    if (data->IsFinite())
+      LLDB_LOGF(log,
+                "%p Debugger('%llu')::HandleProgressEvent (m_current_event_id "
+                "= {%llu}, data = {id = %llu, message = %s, completed = %llu, "
+                "total = %llu})",
+                static_cast<void *>(this), m_uid, *m_current_event_id, id,
+                data->GetMessage().data(), data->GetCompleted(),
+                data->GetTotal());
+    else
+      LLDB_LOGF(log,
+                "%p Debugger('%llu')::HandleProgressEvent (m_current_event_id "
+                "= {%llu}, data = {id = %llu, message = %s, infinite = true})",
+                static_cast<void *>(this), m_uid, *m_current_event_id, id,
+                data->GetMessage().data());
     if (id != *m_current_event_id)
       return;
-    if (data->GetCompleted())
-      m_current_event_id.reset();
   } else {
     m_current_event_id = id;
   }
 
   // Decide whether we actually are going to show the progress. This decision
   // can change between iterations so check it inside the loop.
   if (!GetShowProgress())
     return;
 
   // Determine whether the current output file is an interactive terminal with
   // color support. We assume that if we support ANSI escape codes we support
   // vt100 escape codes.
   File &file = GetOutputFile();
   if (!file.GetIsInteractive() || !file.GetIsTerminalWithColors())
     return;
 
   StreamSP output = GetAsyncOutputStream();
 
   // Print over previous line, if any.
   output->Printf("\r");
 
-  if (data->GetCompleted()) {
+  if (data->GetCompleted() == data->GetTotal()) {
     // Clear the current line.
+    m_current_event_id.reset();
     output->Printf("\x1B[2K");
     output->Flush();
     return;
   }
 
   // Trim the progress message if it exceeds the window's width and print it.
   std::string message = data->GetMessage();
   if (data->IsFinite())