<div dir="ltr"><br><br><br><div class="gmail_quote"><div dir="ltr">On Thu, 8 Mar 2018 at 18:40, Davide Italiano <<a href="mailto:dccitaliano@gmail.com">dccitaliano@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On Thu, Mar 8, 2018 at 10:29 AM, Greg Clayton <<a href="mailto:clayborg@gmail.com" target="_blank">clayborg@gmail.com</a>> wrote:<br>
> It would be great to look into these and see what is taking so long. Some tests are doing way too much work and should be split up. But it would be great to see if we have any tests that are not good tests and are just taking too much time for no reason (like the watchpoint tests were that Pavel fixed).<br>
><br>
<br>
I tend to agree with you. This is important. Pavel, is there a<br>
systematic way you use to profile test cases?<br>
Maybe we should consider having a testsuite mode where we warn for<br>
slow tests (or revamp the profiling mechanism, if there's one).<br>
<br>
Thanks!<br></blockquote><div><br></div><div>I don't have any fancy mechanism for profiling this. I just hacked the process_file function in dosep.py to measure the time each test takes and report it if it exceeds a certain threshold. Then I just looked at the tests that seemed like they are taking more time than they ought to.</div><div><br></div><div>This is the patch, in it's entirety:</div><div><div>--- a/packages/Python/lldbsuite/test/dosep.py</div><div>+++ b/packages/Python/lldbsuite/test/dosep.py</div><div>@@ -489,8 +489,13 @@ def process_file(test_file, dotest_argv, inferior_pid_events):</div><div> timeout = (os.getenv("LLDB_%s_TIMEOUT" % timeout_name) or</div><div> getDefaultTimeout(dotest_options.lldb_platform_name))</div><div> </div><div>+ import time</div><div>+ t = time.time()</div><div> results.append(call_with_timeout(</div><div> command, timeout, base_name, inferior_pid_events, test_file))</div><div>+ t = time.time() - t</div><div>+ if t > 20:</div><div>+ print("XXXXXXXXXXXXXXXXXX %s: %f"%(base_name, t))</div><div> </div><div> # result = (name, status, passes, failures, unexpected_successes)</div><div> timed_out = [name for name, status, _, _, _ in results</div></div><div><br></div><div>We could try to make this more fancy, but I'm not sure worth it. It just occurred to me you can achieve a similar effect by running the test suite with a reduced timeout threshold. Something like "LLDB_TEST_TIMEOUT=20s ninja check-lldb" should do the trick. At one point Todd also implemented a mechanism for recording what the test is doing before we time out and kill it. The idea was that this would help us determine what the test was doing when it was killed (and whether it was really stuck, or just slow). However, I've never used this, so I have no idea what's the state of it.</div><div><br></div><div>I am not opposed to raising the timeout threshold, but before we do that, we should check whether it will actually help. I.e., whether the test is just slow, or it sometimes hangs (I think <span style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">TestMultith</span><span style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">readed is a good candidate for the latter). Can you check what is the time those tests take to run individually? Current osx timeout (dosep.py:getDefaultTimeout) is set to 6 minutes, so if the tests normally take much shorter than this (less than 2 minutes?), I think there is something else going on, and increasing the timeout will not help.</span></div><div><span style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline"><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:small;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial"><span style="text-align:start;text-indent:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline"><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px"><br></div><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px">Another interesting thing may be to check the system load while running the test suite. Nowadays, lldb will sometimes spawn N (where N is the number of cpus) threads to do debug info parsing, so when we run N tests in parallel, we may end up with N^2 threads competing for N cpus. I've never seen this to be an issue as our tests generally don't have that much debug info to begin with, but I don't think we've ever investigated this either...</div><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px"><br></div></span></div></span></div><div><span style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline">BTW: This is my list of tests that take over 20 seconds (I ran it on linux so it does not include any osx-specific ones):</span></div><div><span style="text-align:start;text-indent:0px;background-color:rgb(255,255,255);text-decoration-style:initial;text-decoration-color:initial;float:none;display:inline"><div><span style="font-size:12.8px">20.729438 TestWatchpointCommands.py</span></div><div><span style="font-size:12.8px">21.158373 TestMiData.py</span></div><div><span style="font-size:12.8px">22.018853 TestRecursiveInferior.py</span></div><div><span style="font-size:12.8px">22.692744 TestInferiorCrashing.py</span></div><div><span style="font-size:12.8px">22.986511 TestLinuxCore.py</span></div><div><span style="font-size:12.8px">23.073790 TestInferiorAssert.py</span></div><div><span style="font-size:12.8px">23.193351 TestAnonymous.py</span></div><div><span style="font-size:12.8px">24.539430 TestMiStack.py</span></div><div><span style="font-size:12.8px">25.232940 TestUnwindExpression.py</span></div><div><span style="font-size:12.8px">26.608233 TestSetWatchlocation.py</span></div><div><span style="font-size:12.8px">28.977390 TestWatchLocation.py</span></div><div><span style="font-size:12.8px">29.057234 TestMultithreaded.py</span></div><div><span style="font-size:12.8px">29.813142 TestCPP11EnumTypes.py</span></div><div><span style="font-size:12.8px">30.830618 TestWatchLocationWithWatchSet.py</span></div><div><span style="font-size:12.8px">32.979785 TestThreadStates.py</span></div><div><span style="font-size:12.8px">33.435421 TestTargetWatchAddress.py</span></div><div><span style="font-size:12.8px">36.902618 TestNamespaceLookup.py</span></div><div><span style="font-size:12.8px">37.705945 TestMiSymbol.py</span></div><div><span style="font-size:12.8px">38.735631 TestValueObjectRecursion.py</span></div><div><span style="font-size:12.8px">46.870848 TestLldbGdbServer.py</span></div><div><span style="font-size:12.8px">49.594663 TestLoadUnload.py</span></div><div><span style="font-size:12.8px">52.186429 TestIntegerTypes.py</span></div><div><span style="font-size:12.8px">55.340360 TestMiExec.py</span></div><div><span style="font-size:12.8px">56.148259 TestIntegerTypesExpr.py</span></div><div><span style="font-size:12.8px">110.121061 TestMiGdbSetShow.py</span></div><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px"><br></div><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px">The top one is an lldb-mi test, and this one takes long for a very silly reason: When a test is xfailed because lldb-mi does not produce the expected output, pexpect will keep waiting, hoping that it will eventually produce a line that matches it's regex. This times out after 30 seconds, so any xfailed lldb-mi test will take at least that long. I'm not sure how to fix this without revamping the way we do lldb-mi testing (which would probably be a good thing, but I don't see anyone queuing up to do that).</div><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px"><br></div><div style="color:rgb(34,34,34);font-family:arial,sans-serif;font-size:12.8px;font-style:normal;font-variant-ligatures:normal;font-variant-caps:normal;font-weight:400;letter-spacing:normal;text-transform:none;white-space:normal;word-spacing:0px"><br></div></span></div></div></div>