Page MenuHomePhabricator

[lldb-vscode] only report long running progress events
ClosedPublic

Authored by wallace on Apr 22 2021, 8:04 PM.

Details

Summary

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.

Diff Detail

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
clayborg added inline comments.Apr 23 2021, 12:35 PM
lldb/tools/lldb-vscode/ProgressEvent.cpp
125

This might be better named "m_aux_reporter_thread_should_exit". This variable sounds like the thread itself will modify the value when it finishes, but this is a "I want to tell the thread when it is no longer needed when I want it to exit.

135

I would just name this "TaskProgressEventQueue::Update(...)"

136–137

If this is an progressEnd event, we could track if this event did report any progressStart or progressUpdate events and just send the update right away here? That would require that the report_callback is stored during construction though. It would be easy if TaskProgressEventQueue just got a reference to the ProgressEventFilterQueue since it owns these TaskProgressEventQueue. Then we could extract the callback from it.

152

If I am reading this loop correctly, we are going to only notify the progress whose id is m_event_ids.front()? So if we have 10 progress start events we will only report the first one? Can VS Code only handle one progress at a time? If not we need to iterate over all m_event_ids and report any possible progress on all events that have new status as many different threads could be progressing on indexing DWARF.

156

Should we check m_last_update_event here and make sure it isn't a progressEnd event? It is is, we will notify both start and end right away? Edge case, but just wanted to check.

158

ProgressEventFilterQueue::TryReport() returns true if the event was reported even if it didn't finish. Do we always want to pop from m_event_ids even if the task didn't finish? Is this loop only to catch reporting the start event?

217–218

Can't "SetUpdate" just report things if needed? This could be just:

it->second.SetUpdate(event);
lldb/tools/lldb-vscode/ProgressEvent.h
44

Yikes this must have caused some serious bugs in the reporting mechanism as the old string would have been freed!!

121

TaskProgressEventQueue might be better named "ProgressEventManager"? It doesn't have a queue, but it does manage event deliveries

125–128

make private?

150

Should be just be storing this in the ProgressEvent? That way we can accurately track the timestamp for any packets we deliver, like when we deliver one from m_last_update_event

151

After reading the code, this might be more clear if it were named "m_reported_start_event".

152

Curious, when we report events, I remember adding a timestamp to the progress event packet. If we report events later after the timeout that filters quick progress packets, do we send the original timestamp from when the progress was reported? We should make sure we do because we want to be able to use this timing information from the packet log to deduce performance issues.

This revision now requires changes to proceed.Apr 23 2021, 12:35 PM
wallace added inline comments.Apr 29 2021, 9:32 PM
lldb/tools/lldb-vscode/ProgressEvent.cpp
125

+1

128

yes, you are right, at least 1 second should be fine.

132

yes, 1 second is reasonable. I'll test it with a huge binary as well

136–137

good one

152

not quite right, this will report as many as it can until it finds the first one who can't be reported, which means that that event is not old enough, and therefore the other events are also not old enough

156

good catch

158

this is only looping through the start events. I'll make this clearer

lldb/tools/lldb-vscode/ProgressEvent.h
44

well, not really as we were dispatching the event right away, but with async events we need to save the data to a string

150

makes sense

152

i'll put that back!

wallace updated this revision to Diff 342386.May 3 2021, 7:46 AM
wallace marked 12 inline comments as done.

Address all comments

clayborg requested changes to this revision.May 3 2021, 10:59 AM
clayborg added inline comments.
lldb/tools/lldb-vscode/ProgressEvent.cpp
45
128

We have a 1 second timeout before events should be reported, so we should probably sleep a shorter amount of time than 2 seconds as if the events come in such that a progress start event is queued right after this loop sleeps for 2 seconds, it can now be three seconds before an event is reported. How about 250 ms? That way the most we will wait before reporting a start event is 1.25 seconds. Also since we expect the thread to exit in ~ProgressEventFilterQueue, we don't want to have to wait 2 seconds during shut down.

135

remove m_start_event_timestamp as it is no longer needed since ProgressEvent has a timestamp now.

139

rename to "ReportIfNeeded()"?

139

Should this be named "ReportStartEvents()"? Is that the only thing this is doing here?

142–151
147

If we are using m_sorted_event_managers only for reporting start events, we should rename to "m_unreported_start_events"

149–150

We have many places in the code that are reporting progress and then having to manually mark the event as reported. We should make a ProgressEvent::Report() function that looks something like:

void ProgressEvent::Report(ProgressEventReportCallback report_callback) {
  if (!m_reported) {
    m_reported = true;
    report_callback(*this);
  }
}
152

Ok so this class is a start event reporter then?

153–154
lldb/tools/lldb-vscode/ProgressEvent.h
151

m_thread should suffice here.

152

m_thread_should_exit should suffice.

155

m_mutex is fine unless we get more than one mutex in this class.

This revision now requires changes to proceed.May 3 2021, 10:59 AM
wallace updated this revision to Diff 342650.EditedMay 3 2021, 10:55 PM
wallace marked 12 inline comments as done.

Address all comments

  • now the reporting timing conditions are in ProgressEvent, which simplifies the other classes
  • now two subsequent updates are only sent if there's a 0.25 delay between them
  • removed the progressInvalid enum by making sure only valid ProgressEvent instances are created
wallace marked 2 inline comments as done.May 3 2021, 11:00 PM
clayborg requested changes to this revision.May 4 2021, 1:11 PM
clayborg added inline comments.
lldb/tools/lldb-vscode/ProgressEvent.cpp
144–149
196

put in header file

201

init before { with "m_thread_should_exit(false)"

215–216

Why is this returning an optional event? We know we need a start event here and it must be made. The Optional seems like it isn't needed?

222–226
lldb/tools/lldb-vscode/ProgressEvent.h
30–39

Seems like all these constructors are a bit much. We should probably have one that just takes all the needed parameters including the ProgressEventType. It is unclear from each constructor what each one does unless you look very carefully at the header documentation. It will be very clear if we just have:

ProgressEvent(uint64_t progress_id, StringRef message, ProgressEventType event_type, llvm::Optional<uint32_t> percentage = llvm::None);
31

Why is there an optional percentage for a start event?

31

Why do we need this constructor? At the very least we don't need the progress_id since the prev_event will have one

35–36

Don't need progress_id if we have a prev_event. We probably don't need the previous constructor if we have this one. Might be better as:

ProgressEvent(const ProgressEvent &prev_event, uint32_t percentage);

If the percentage is 100, then this is an end event? Otherwise it is an update event?

This revision now requires changes to proceed.May 4 2021, 1:11 PM
wallace added inline comments.May 18 2021, 3:52 PM
lldb/tools/lldb-vscode/ProgressEvent.h
31

if total is INT_MAX, there's nothing to report

wallace updated this revision to Diff 346335.May 18 2021, 9:03 PM

Simplified the constructors

clayborg requested changes to this revision.May 21 2021, 12:11 PM

The only last nit is we are passing the report progress callback around all over the place. I think it would be nicer to just make a static function that we can call and remove the passing of the instance variable for the report callback all over to the event classes.

lldb/tools/lldb-vscode/ProgressEvent.cpp
27

So we are copying the string for every event? I thought we only needed this for the start event?

28–57

I would be nice to simplify this down a bit as we have both "completed" being used along with "prev_event" to try and figure out what the event is. We probably don't need "long double" for calculating the percentage either. It would be clearer to maybe do:

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_precentage = 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_precentage = 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; 
  }
}
206

Should we return the result of "m_last_update_event->Report(m_report_callback);" here?

216

Should we add a safeguard and check m_finished first?

This revision now requires changes to proceed.May 21 2021, 12:11 PM
wallace updated this revision to Diff 350419.Jun 7 2021, 2:42 PM

Addressed the comments except for the "static function that we can call and remove the passing of the instance variable for the report callback all over to the event classes". That's a little bit hard to achieve because the callback requires an instance of VSCode, so it can't easily be fully static. I think it's fine to the callbacks as they are not used in too many places.

https://reviews.llvm.org/P8265 is a sample DAP output with these messages

clayborg accepted this revision.Jun 16 2021, 6:12 PM
This revision is now accepted and ready to land.Jun 16 2021, 6:12 PM
This revision was landed with ongoing or failed builds.Jun 17 2021, 12:13 PM
This revision was automatically updated to reflect the committed changes.

@wallace : Your most recent change to comment out ProgressEventThreadFunction is causing warnings to be generated when building with clang. Please have a look:

/usr/bin/clang++ -DGTEST_HAS_RTTI=0 -DHAVE_ROUND -D_DEBUG -D_GNU_SOURCE -D__STDC_CONSTANT_MACROS -D__STDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS -Itools/lldb/tools/lldb-vscode -I/mnt/vss/_work/1/s/lldb/tools/lldb-vscode -I/mnt/vss/_work/1/s/lldb/include -Itools/lldb/include -Iinclude -I/mnt/vss/_work/1/s/llvm/include -I/mnt/vss/_work/1/s/llvm/../clang/include -Itools/lldb/../clang/include -I/usr/include/libxml2 -fPIC -fvisibility-inlines-hidden -Werror -Werror=date-time -Werror=unguarded-availability-new -Wall -Wextra -Wno-unused-parameter -Wwrite-strings -Wcast-qual -Wmissing-field-initializers -pedantic -Wno-long-long -Wc++98-compat-extra-semi -Wimplicit-fallthrough -Wcovered-switch-default -Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor -Wsuggest-override -Wstring-conversion -Wmisleading-indentation -fdiagnostics-color -ffunction-sections -fdata-sections -Wno-deprecated-declarations -Wno-unknown-pragmas -Wno-strict-aliasing -Wno-deprecated-register -Wno-vla-extension -O3 -DNDEBUG  -fno-exceptions -fno-rtti -UNDEBUG -std=c++14 -MD -MT tools/lldb/tools/lldb-vscode/CMakeFiles/lldb-vscode.dir/lldb-vscode.cpp.o -MF tools/lldb/tools/lldb-vscode/CMakeFiles/lldb-vscode.dir/lldb-vscode.cpp.o.d -o tools/lldb/tools/lldb-vscode/CMakeFiles/lldb-vscode.dir/lldb-vscode.cpp.o -c /mnt/vss/_work/1/s/lldb/tools/lldb-vscode/lldb-vscode.cpp
/mnt/vss/_work/1/s/lldb/tools/lldb-vscode/lldb-vscode.cpp:370:6: error: unused function 'ProgressEventThreadFunction' [-Werror,-Wunused-function]
void ProgressEventThreadFunction() {
     ^
1 error generated.

I'm reverting it asap

Il giorno lun 21 giu 2021 alle ore 10:48 Stella Stamenova via Phabricator <
reviews@reviews.llvm.org> ha scritto:

stella.stamenova added a comment.

@wallace : Your most recent change to comment out
ProgressEventThreadFunction is causing warnings to be generated when
building with clang. Please have a look:

/usr/bin/clang++ -DGTEST_HAS_RTTI=0 -DHAVE_ROUND -D_DEBUG -D_GNU_SOURCE

-DSTDC_CONSTANT_MACROS -DSTDC_FORMAT_MACROS -D__STDC_LIMIT_MACROS
-Itools/lldb/tools/lldb-vscode -I/mnt/vss/_work/1/s/lldb/tools/lldb-vscode
-I/mnt/vss/_work/1/s/lldb/include -Itools/lldb/include -Iinclude
-I/mnt/vss/_work/1/s/llvm/include
-I/mnt/vss/_work/1/s/llvm/../clang/include -Itools/lldb/../clang/include
-I/usr/include/libxml2 -fPIC -fvisibility-inlines-hidden -Werror
-Werror=date-time -Werror=unguarded-availability-new -Wall -Wextra
-Wno-unused-parameter -Wwrite-strings -Wcast-qual
-Wmissing-field-initializers -pedantic -Wno-long-long
-Wc++98-compat-extra-semi -Wimplicit-fallthrough -Wcovered-switch-default
-Wno-noexcept-type -Wnon-virtual-dtor -Wdelete-non-virtual-dtor
-Wsuggest-override -Wstring-conversion -Wmisleading-indentation
-fdiagnostics-color -ffunction-sections -fdata-sections
-Wno-deprecated-declarations -Wno-unknown-pragmas -Wno-strict-aliasing
-Wno-deprecated-register -Wno-vla-extension -O3 -DNDEBUG -fno-exceptions
-fno-rtti -UNDEBUG -std=c++14 -MD -MT
tools/lldb/tools/lldb-vscode/CMakeFiles/lldb-vscode.dir/lldb-vscode.cpp.o
-MF
tools/lldb/tools/lldb-vscode/CMakeFiles/lldb-vscode.dir/lldb-vscode.cpp.o.d
-o
tools/lldb/tools/lldb-vscode/CMakeFiles/lldb-vscode.dir/lldb-vscode.cpp.o
-c /mnt/vss/_work/1/s/lldb/tools/lldb-vscode/lldb-vscode.cpp

/mnt/vss/_work/1/s/lldb/tools/lldb-vscode/lldb-vscode.cpp:370:6: error:

unused function 'ProgressEventThreadFunction' [-Werror,-Wunused-function]

void ProgressEventThreadFunction() {
     ^
1 error generated.

Repository:

rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION

https://reviews.llvm.org/D101128/new/

https://reviews.llvm.org/D101128

I'm reverting it asap

Thanks!