Skip to content

[lldb-dap] Speed up TestDAP_Progress #134048

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Apr 2, 2025

Conversation

JDevlieghere
Copy link
Member

While trying to make progress on #133782, I noticed that TestDAP_Progress was taking 90 seconds to complete. This patch brings that down to 10 seocnds by making the following changes:

  1. Don't call wait_for_event with a 15 second timeout. By the time we call this, all progress events have been emitted, which means that we're just sitting there until we hit the timeout.

  2. Don't use 10 steps (= 10 seconds) for indeterminate progress. We have two indeterminate progress tests so that's 6 seconds instead of 20.

  3. Don't launch the process over and over. Once we have a dap session, we can clear the progress vector and emit new progress events.

@JDevlieghere JDevlieghere requested a review from Jlalond April 2, 2025 08:23
@llvmbot llvmbot added the lldb label Apr 2, 2025
@llvmbot
Copy link
Member

llvmbot commented Apr 2, 2025

@llvm/pr-subscribers-lldb

Author: Jonas Devlieghere (JDevlieghere)

Changes

While trying to make progress on #133782, I noticed that TestDAP_Progress was taking 90 seconds to complete. This patch brings that down to 10 seocnds by making the following changes:

  1. Don't call wait_for_event with a 15 second timeout. By the time we call this, all progress events have been emitted, which means that we're just sitting there until we hit the timeout.

  2. Don't use 10 steps (= 10 seconds) for indeterminate progress. We have two indeterminate progress tests so that's 6 seconds instead of 20.

  3. Don't launch the process over and over. Once we have a dap session, we can clear the progress vector and emit new progress events.


Full diff: https://github.com/llvm/llvm-project/pull/134048.diff

2 Files Affected:

  • (modified) lldb/test/API/tools/lldb-dap/progress/Progress_emitter.py (+5-5)
  • (modified) lldb/test/API/tools/lldb-dap/progress/TestDAP_Progress.py (+7-46)
diff --git a/lldb/test/API/tools/lldb-dap/progress/Progress_emitter.py b/lldb/test/API/tools/lldb-dap/progress/Progress_emitter.py
index 445d1bdf4e496..33dee33e28b23 100644
--- a/lldb/test/API/tools/lldb-dap/progress/Progress_emitter.py
+++ b/lldb/test/API/tools/lldb-dap/progress/Progress_emitter.py
@@ -38,8 +38,8 @@ def create_options(cls):
 
         parser.add_option(
             "--total",
-            dest="total",
-            help="Total items in this progress object. When this option is not specified, this will be an indeterminate progress.",
+            dest="total", help="Total items in this progress object. When this
+            option is not specified, this will be an indeterminate progress.",
             type="int",
             default=None,
         )
@@ -88,11 +88,11 @@ def __call__(self, debugger, command, exe_ctx, result):
             progress = lldb.SBProgress(
                 "Progress tester", "Initial Detail", total, debugger
             )
-        # Check to see if total is set to None to indicate an indeterminate progress
-        # then default to 10 steps.
+        # Check to see if total is set to None to indicate an indeterminate
+        # progress then default to 3 steps.
         with progress:
             if total is None:
-                total = 10
+                total = 3
 
             for i in range(1, total):
                 if cmd_options.no_details:
diff --git a/lldb/test/API/tools/lldb-dap/progress/TestDAP_Progress.py b/lldb/test/API/tools/lldb-dap/progress/TestDAP_Progress.py
index f723a2d254825..ffe3d38eb49a3 100755
--- a/lldb/test/API/tools/lldb-dap/progress/TestDAP_Progress.py
+++ b/lldb/test/API/tools/lldb-dap/progress/TestDAP_Progress.py
@@ -19,7 +19,6 @@ def verify_progress_events(
         expected_not_in_message=None,
         only_verify_first_update=False,
     ):
-        self.dap_server.wait_for_event("progressEnd", 15)
         self.assertTrue(len(self.dap_server.progress_events) > 0)
         start_found = False
         update_found = False
@@ -45,20 +44,18 @@ def verify_progress_events(
         self.assertTrue(start_found)
         self.assertTrue(update_found)
         self.assertTrue(end_found)
+        self.dap_server.progress_events.clear()
 
     @skipIfWindows
-    def test_output(self):
+    def test(self):
         program = self.getBuildArtifact("a.out")
         self.build_and_launch(program)
         progress_emitter = os.path.join(os.getcwd(), "Progress_emitter.py")
-        source = "main.cpp"
-        breakpoint_ids = self.set_source_breakpoints(
-            source, [line_number(source, "// break here")]
-        )
-        self.continue_to_breakpoints(breakpoint_ids)
         self.dap_server.request_evaluate(
             f"`command script import {progress_emitter}", context="repl"
         )
+
+        # Test details.
         self.dap_server.request_evaluate(
             "`test-progress --total 3 --seconds 1", context="repl"
         )
@@ -68,19 +65,7 @@ def test_output(self):
             expected_not_in_message="Progress tester",
         )
 
-    @skipIfWindows
-    def test_output_nodetails(self):
-        program = self.getBuildArtifact("a.out")
-        self.build_and_launch(program)
-        progress_emitter = os.path.join(os.getcwd(), "Progress_emitter.py")
-        source = "main.cpp"
-        breakpoint_ids = self.set_source_breakpoints(
-            source, [line_number(source, "// break here")]
-        )
-        self.continue_to_breakpoints(breakpoint_ids)
-        self.dap_server.request_evaluate(
-            f"`command script import {progress_emitter}", context="repl"
-        )
+        # Test no details.
         self.dap_server.request_evaluate(
             "`test-progress --total 3 --seconds 1 --no-details", context="repl"
         )
@@ -90,19 +75,7 @@ def test_output_nodetails(self):
             expected_message="Initial Detail",
         )
 
-    @skipIfWindows
-    def test_output_indeterminate(self):
-        program = self.getBuildArtifact("a.out")
-        self.build_and_launch(program)
-        progress_emitter = os.path.join(os.getcwd(), "Progress_emitter.py")
-        source = "main.cpp"
-        breakpoint_ids = self.set_source_breakpoints(
-            source, [line_number(source, "// break here")]
-        )
-        self.continue_to_breakpoints(breakpoint_ids)
-        self.dap_server.request_evaluate(
-            f"`command script import {progress_emitter}", context="repl"
-        )
+        # Test details indeterminate.
         self.dap_server.request_evaluate("`test-progress --seconds 1", context="repl")
 
         self.verify_progress_events(
@@ -111,19 +84,7 @@ def test_output_indeterminate(self):
             only_verify_first_update=True,
         )
 
-    @skipIfWindows
-    def test_output_nodetails_indeterminate(self):
-        program = self.getBuildArtifact("a.out")
-        self.build_and_launch(program)
-        progress_emitter = os.path.join(os.getcwd(), "Progress_emitter.py")
-        source = "main.cpp"
-        breakpoint_ids = self.set_source_breakpoints(
-            source, [line_number(source, "// break here")]
-        )
-        self.dap_server.request_evaluate(
-            f"`command script import {progress_emitter}", context="repl"
-        )
-
+        # Test no details indeterminate.
         self.dap_server.request_evaluate(
             "`test-progress --seconds 1 --no-details", context="repl"
         )

While trying to make progress on llvm#133782, I noticed that
TestDAP_Progress was taking 90 seconds to complete. This patch brings
that down to 10 seocnds by making the following changes:

1. Don't call `wait_for_event` with a 15 second timeout. By the time we
   call this, all progress events have been emitted, which means that
   we're just sitting there until we hit the timeout.

2. Don't use 10 steps (= 10 seconds) for indeterminate progress. We have
   two indeterminate progress tests so that's 6 seconds instead of 20.

3. Don't launch the process over and over. Once we have a dap session,
   we can clear the progress vector and emit new progress events.
Copy link
Contributor

@Jlalond Jlalond left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM! Thanks for fixing

@JDevlieghere
Copy link
Member Author

I wonder if there's a potential race between lldb emitting the last progress event and lldb-dap ingesting it. If we see that this test becomes flakey, we can add the self.dap_server.wait_for_event call again with a short timeout, something like 250ms. If the event comes in late, that'll return sooner. If it was already received, we wait at most 4*250ms = 1s.

@JDevlieghere JDevlieghere merged commit c87dc2b into llvm:main Apr 2, 2025
10 checks passed
@JDevlieghere JDevlieghere deleted the TestDAP_Progress branch April 2, 2025 19:41
@llvm-ci
Copy link
Collaborator

llvm-ci commented Apr 2, 2025

LLVM Buildbot has detected a new failure on builder lldb-arm-ubuntu running on linaro-lldb-arm-ubuntu while building lldb at step 6 "test".

Full details are available at: https://lab.llvm.org/buildbot/#/builders/18/builds/13904

Here is the relevant piece of the build log for the reference
Step 6 (test) failure: build (failure)
...
PASS: lldb-api :: tools/lldb-dap/locations/TestDAP_locations.py (1166 of 2934)
PASS: lldb-api :: tools/lldb-dap/memory/TestDAP_memory.py (1167 of 2934)
PASS: lldb-api :: tools/lldb-dap/optimized/TestDAP_optimized.py (1168 of 2934)
PASS: lldb-api :: tools/lldb-dap/output/TestDAP_output.py (1169 of 2934)
PASS: lldb-api :: tools/lldb-dap/launch/TestDAP_launch.py (1170 of 2934)
PASS: lldb-api :: tools/lldb-dap/evaluate/TestDAP_evaluate.py (1171 of 2934)
PASS: lldb-api :: tools/lldb-dap/repl-mode/TestDAP_repl_mode_detection.py (1172 of 2934)
UNSUPPORTED: lldb-api :: tools/lldb-dap/restart/TestDAP_restart_runInTerminal.py (1173 of 2934)
UNSUPPORTED: lldb-api :: tools/lldb-dap/runInTerminal/TestDAP_runInTerminal.py (1174 of 2934)
UNSUPPORTED: lldb-api :: tools/lldb-dap/save-core/TestDAP_save_core.py (1175 of 2934)
FAIL: lldb-api :: tools/lldb-dap/progress/TestDAP_Progress.py (1176 of 2934)
******************** TEST 'lldb-api :: tools/lldb-dap/progress/TestDAP_Progress.py' FAILED ********************
Script:
--
/usr/bin/python3.10 /home/tcwg-buildbot/worker/lldb-arm-ubuntu/llvm-project/lldb/test/API/dotest.py -u CXXFLAGS -u CFLAGS --env LLVM_LIBS_DIR=/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./lib --env LLVM_INCLUDE_DIR=/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/include --env LLVM_TOOLS_DIR=/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin --arch armv8l --build-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex --lldb-module-cache-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-lldb/lldb-api --clang-module-cache-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-clang/lldb-api --executable /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin/lldb --compiler /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin/clang --dsymutil /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin/dsymutil --make /usr/bin/gmake --llvm-tools-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./bin --lldb-obj-root /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/tools/lldb --lldb-libs-dir /home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/./lib /home/tcwg-buildbot/worker/lldb-arm-ubuntu/llvm-project/lldb/test/API/tools/lldb-dap/progress -p TestDAP_Progress.py
--
Exit Code: 1

Command Output (stdout):
--
lldb version 21.0.0git (https://github.com/llvm/llvm-project.git revision c87dc2b7d4ac0131cb97f096be522a50a4b3068b)
  clang revision c87dc2b7d4ac0131cb97f096be522a50a4b3068b
  llvm revision c87dc2b7d4ac0131cb97f096be522a50a4b3068b
Skipping the following test categories: ['libc++', 'dsym', 'gmodules', 'debugserver', 'objc']

--
Command Output (stderr):
--
========= DEBUG ADAPTER PROTOCOL LOGS =========
1743624515.163093090 --> (stdin/stdout) {"command":"initialize","type":"request","arguments":{"adapterID":"lldb-native","clientID":"vscode","columnsStartAt1":true,"linesStartAt1":true,"locale":"en-us","pathFormat":"path","supportsRunInTerminalRequest":true,"supportsVariablePaging":true,"supportsVariableType":true,"supportsStartDebuggingRequest":true,"supportsProgressReporting":true,"$__lldb_sourceInitFile":false},"seq":1}
1743624515.165662050 <-- (stdin/stdout) {"body":{"$__lldb_version":"lldb version 21.0.0git (https://github.com/llvm/llvm-project.git revision c87dc2b7d4ac0131cb97f096be522a50a4b3068b)\n  clang revision c87dc2b7d4ac0131cb97f096be522a50a4b3068b\n  llvm revision c87dc2b7d4ac0131cb97f096be522a50a4b3068b","completionTriggerCharacters":["."," ","\t"],"exceptionBreakpointFilters":[{"default":false,"filter":"cpp_catch","label":"C++ Catch"},{"default":false,"filter":"cpp_throw","label":"C++ Throw"},{"default":false,"filter":"objc_catch","label":"Objective-C Catch"},{"default":false,"filter":"objc_throw","label":"Objective-C Throw"}],"supportTerminateDebuggee":true,"supportsBreakpointLocationsRequest":true,"supportsCompletionsRequest":true,"supportsConditionalBreakpoints":true,"supportsConfigurationDoneRequest":true,"supportsDataBreakpoints":true,"supportsDelayedStackTraceLoading":true,"supportsDisassembleRequest":true,"supportsEvaluateForHovers":true,"supportsExceptionInfoRequest":true,"supportsExceptionOptions":true,"supportsFunctionBreakpoints":true,"supportsHitConditionalBreakpoints":true,"supportsInstructionBreakpoints":true,"supportsLogPoints":true,"supportsModulesRequest":true,"supportsReadMemoryRequest":true,"supportsRestartRequest":true,"supportsSetVariable":true,"supportsStepInTargetsRequest":true,"supportsSteppingGranularity":true,"supportsValueFormattingOptions":true},"command":"initialize","request_seq":1,"seq":0,"success":true,"type":"response"}
1743624515.165984869 --> (stdin/stdout) {"command":"launch","type":"request","arguments":{"program":"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/tools/lldb-dap/progress/TestDAP_Progress.test/a.out","initCommands":["settings clear -all","settings set symbols.enable-external-lookup false","settings set target.inherit-tcc true","settings set target.disable-aslr false","settings set target.detach-on-error false","settings set target.auto-apply-fixits false","settings set plugin.process.gdb-remote.packet-timeout 60","settings set symbols.clang-modules-cache-path \"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-lldb/lldb-api\"","settings set use-color false","settings set show-statusline false"],"disableASLR":false,"enableAutoVariableSummaries":false,"enableSyntheticChildDebugging":false,"displayExtendedBacktrace":false,"commandEscapePrefix":null},"seq":2}
1743624515.166332722 <-- (stdin/stdout) {"body":{"category":"console","output":"Running initCommands:\n"},"event":"output","seq":0,"type":"event"}
1743624515.166363239 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings clear -all\n"},"event":"output","seq":0,"type":"event"}
1743624515.166375160 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set symbols.enable-external-lookup false\n"},"event":"output","seq":0,"type":"event"}
1743624515.166386127 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.inherit-tcc true\n"},"event":"output","seq":0,"type":"event"}
1743624515.166396856 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.disable-aslr false\n"},"event":"output","seq":0,"type":"event"}
1743624515.166407585 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.detach-on-error false\n"},"event":"output","seq":0,"type":"event"}
1743624515.166418791 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set target.auto-apply-fixits false\n"},"event":"output","seq":0,"type":"event"}
1743624515.166429520 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set plugin.process.gdb-remote.packet-timeout 60\n"},"event":"output","seq":0,"type":"event"}
1743624515.166458368 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set symbols.clang-modules-cache-path \"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/module-cache-lldb/lldb-api\"\n"},"event":"output","seq":0,"type":"event"}
1743624515.166469097 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set use-color false\n"},"event":"output","seq":0,"type":"event"}
1743624515.166479349 <-- (stdin/stdout) {"body":{"category":"console","output":"(lldb) settings set show-statusline false\n"},"event":"output","seq":0,"type":"event"}
1743624515.310166359 <-- (stdin/stdout) {"command":"launch","request_seq":2,"seq":0,"success":true,"type":"response"}
1743624515.310291052 <-- (stdin/stdout) {"body":{"isLocalProcess":true,"name":"/home/tcwg-buildbot/worker/lldb-arm-ubuntu/build/lldb-test-build.noindex/tools/lldb-dap/progress/TestDAP_Progress.test/a.out","startMethod":"launch","systemProcessId":1276196},"event":"process","seq":0,"type":"event"}
1743624515.310313940 <-- (stdin/stdout) {"event":"initialized","seq":0,"type":"event"}
1743624515.311068535 --> (stdin/stdout) {"command":"threads","type":"request","arguments":{},"seq":3}
1743624515.311187267 <-- (stdin/stdout) {"body":{"threads":[{"id":1276196,"name":"a.out"}]},"command":"threads","request_seq":3,"seq":0,"success":true,"type":"response"}
1743624515.311352491 --> (stdin/stdout) {"command":"stackTrace","type":"request","arguments":{"threadId":1276196,"startFrame":0,"levels":1},"seq":4}

@dmpots
Copy link
Contributor

dmpots commented Apr 2, 2025

I wonder if there's a potential race between lldb emitting the last progress event and lldb-dap ingesting it. If we see that this test becomes flakey, we can add the self.dap_server.wait_for_event call again with a short timeout, something like 250ms. If the event comes in late, that'll return sooner. If it was already received, we wait at most 4*250ms = 1s.

It looks like the test may indeed be flakey. It looks like it hit a failure on lldb-arm-ubuntu attributed to this PR
#134048 (comment)

And also failed on lldb-aarch64-ubuntu when testing my PR. I don't think my PR should be impacting this test.
#133794 (comment)

I am unable to reproduce the failure locally on x86_64 linux.

@JDevlieghere
Copy link
Member Author

I wonder if there's a potential race between lldb emitting the last progress event and lldb-dap ingesting it. If we see that this test becomes flakey, we can add the self.dap_server.wait_for_event call again with a short timeout, something like 250ms. If the event comes in late, that'll return sooner. If it was already received, we wait at most 4*250ms = 1s.

It looks like the test may indeed be flakey. It looks like it hit a failure on lldb-arm-ubuntu attributed to this PR #134048 (comment)

And also failed on lldb-aarch64-ubuntu when testing my PR. I don't think my PR should be impacting this test. #133794 (comment)

I am unable to reproduce the failure locally on x86_64 linux.

Alright, let me add self.dap_server.wait_for_event again and see if that improves the situation.

JDevlieghere added a commit to JDevlieghere/llvm-project that referenced this pull request Apr 2, 2025
Before llvm#134048, TestDAP_Progress would wait up to 15 seconds before
checking whether the events came in. Now the test is a lot faster, but
we risk checking the events before they've all arrived. Make up to 10
attempts to find the end event, with a 100ms sleep in between, giving
the test up to a second for the event to arrive after it has been
broadcast.
@JDevlieghere
Copy link
Member Author

I ended up addressing this slightly differently because I really hate the idea of waiting on an event we already received: #134157

JDevlieghere added a commit to JDevlieghere/llvm-project that referenced this pull request Apr 2, 2025
Before llvm#134048, TestDAP_Progress relied on wait_for_event to block until
the progressEnd came in. However, progress events were not added to the
packet list, so this call would always time out. This PR makes it so
that packets are added to the packet list, and you can block on them.
JDevlieghere added a commit that referenced this pull request Apr 2, 2025
Before #134048, TestDAP_Progress relied on wait_for_event to block until
the progressEnd came in. However, progress events were not added to the
packet list, so this call would always time out. This PR makes it so
that packets are added to the packet list, and you can block on them.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants