Bug 37643 – new-run-webkit-tests has much higher startup latency than run-webkit-tests

• Component: Tools / Tests
• Status: RESOLVED FIXED

[Maciej Stachowiak]

Testing with a stopwatch, on my system (2.4GHz Core2 Duo MacBook Pro), the time to the first visible evidence of a test being run is:

run-webkit-tests: 10s
new-run-webkit-tests: 75s

On the other hand, new-run-webkit tests is definitely faster at running through all the layout tests. Total real time (as tested by "time"):

run-webkit-tests: 13m13.386s
new-run-webkit-tests : 18m35.731s

So at the very least, new-run-webkit-tests is giving up a big chunk of its performance advantage to startup latency.

[Dirk Pranke]

wow, that's slow. I wonder if there was something wrong with your configuration. Were all your files on a local filesystem? I've only ever seen that kind of slowness on a windows machine running on top of an SMB share.

It is true that new-run-webkit-tests is slower than run-webkit-tests for a couple of reasons. The first has to do with spawning off multiple threads, which obviously takes time. The second is that there is a certain amount of "all at once" processing that new-run-webkit-tests does to compute statistics at the start. I have been tempted to fix the latter but I've never seen that it's been a real problem.

Either way, your numbers are an order of magnitude slower than I would expect, so we should figure out what's going on. If you could post the log output from --verbose from the beginning to when testing started that would be a big help.

[Adam Barth]

Seems like we could benefit from using Python's profiler to figure out what's taking the time.

[Eric Seidel (no email)]

I ran:
python -m cProfile new-run-webkit-tests

and aborted it about 2 minutes in (20% through the tests on my machine).

We spent a whopping 45 SECONDS in time.sleep:
     3011   45.569    0.015   45.569    0.015 {time.sleep}

And 3 seconds making some 100k stat calls:
   109687    3.603    0.000    3.603    0.000 {posix.stat}

50 seconds were spent reading files:
     5441   50.576    0.009   50.576    0.009 {method 'read' of 'file' objects}

[Eric Seidel (no email)]

We're spending a lot of time reading image hashes up front.

TestInfo.__init__ does:
            self.image_hash = open(expected_hash_file, "r").read()

(which probably leaks a file handle).

run-webkit-tests reads image hashes when it gets to them.  We could to (and probably should).  There shouldn't be a thread-safety issue because only one thread is ever processing any given test.

[Eric Seidel (no email)]

Created attachment 53662 [details]
Patch

[Eric Seidel (no email)]

With that patch I see the code sleeping for 5 seconds and reading for 10s.
      268    5.258    0.020    5.258    0.020 {time.sleep}
       15    9.412    0.627    9.412    0.627 {method 'read' of 'file' objects}

We're also spending 4s in stat,  1s listing directories and 1s calling "startswith":
   109687    4.061    0.000    4.061    0.000 {posix.stat}
  2842147    1.320    0.000    1.320    0.000 {method 'startswith' of 'str' objects}
     1813    1.168    0.001    1.168    0.001 {posix.listdir}

Obviously still more work to do.

[Eric Seidel (no email)]

This will also get easier to debug once bug 37780 lands.

[Eric Seidel (no email)]

One thing that would make this latency much easier to deal with is if the meter updated more frequently during things like "Checking build ...".  It seems that the part of the code which is updating the meter should be aware of the fact that we have to build DRT and build ImageDiff and possibly start helper processes.  We may just want to pass a meter object to the port during check_build().

[Eric Seidel (no email)]

Created attachment 53667 [details]
Added small speedup to test gathering

[Adam Barth]

Comment on attachment 53667 [details]
Added small speedup to test gathering

Nice!

[Dirk Pranke]

Comment on attachment 53667 [details]
Added small speedup to test gathering

LGTM, apart from your removal of my beloved one-character variable names ;)

[WebKit Commit Bot]

Comment on attachment 53667 [details]
Added small speedup to test gathering

Rejecting patch 53667 from commit-queue.

Failed to run "['WebKitTools/Scripts/test-webkitpy']" exit_code: 1
Last 500 characters of output:
e 533, in loadTestsFromName
    module = __import__('.'.join(parts_copy))
  File "/Users/eseidel/Projects/CommitQueue/WebKitTools/Scripts/webkitpy/layout_tests/run_webkit_tests_unittest.py", line 36, in <module>
    import webkitpy.layout_tests.run_webkit_tests as run_webkit_tests
  File "/Users/eseidel/Projects/CommitQueue/WebKitTools/Scripts/webkitpy/layout_tests/run_webkit_tests.py", line 130
    with open(self._expected_hash_path, "r") as hash_file:
            ^
SyntaxError: invalid syntax

Full output: http://webkit-commit-queue.appspot.com/results/1626581

[Dirk Pranke]

weird ... is the commit queue bot running an unusual version of python?

[Adam Barth]

Comment on attachment 53667 [details]
Added small speedup to test gathering

Btw, this patch doesn't comply with our new unicode overlords.

[Eric Seidel (no email)]

I wrote this patch on SL which has python 2.6.  I suspect I need to fix it for 2.5.

[Eric Seidel (no email)]

Add:
from __future__ import with_statement
which fixed it.

[Eric Seidel (no email)]

I'll make our unicode overlords happy an re-post before I commit.

[Eric Seidel (no email)]

Landed as r57956.