Bug 37643 - new-run-webkit-tests has much higher startup latency than run-webkit-tests
Summary: new-run-webkit-tests has much higher startup latency than run-webkit-tests
Alias: None
Product: WebKit
Classification: Unclassified
Component: Tools / Tests (show other bugs)
Version: 528+ (Nightly build)
Hardware: PC OS X 10.5
: P2 Normal
Assignee: Nobody
Depends on: 37780
  Show dependency treegraph
Reported: 2010-04-15 00:51 PDT by Maciej Stachowiak
Modified: 2010-04-20 23:56 PDT (History)
4 users (show)

See Also:

Patch (7.06 KB, patch)
2010-04-19 02:25 PDT, Eric Seidel (no email)
no flags Details | Formatted Diff | Diff
Added small speedup to test gathering (9.12 KB, patch)
2010-04-19 03:50 PDT, Eric Seidel (no email)
abarth: review-
commit-queue: commit-queue-
Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Maciej Stachowiak 2010-04-15 00:51:26 PDT
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.
Comment 1 Dirk Pranke 2010-04-16 16:16:14 PDT
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.
Comment 2 Adam Barth 2010-04-17 11:09:12 PDT
Seems like we could benefit from using Python's profiler to figure out what's taking the time.
Comment 3 Eric Seidel (no email) 2010-04-19 01:45:40 PDT
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}
Comment 4 Eric Seidel (no email) 2010-04-19 02:02:39 PDT
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.
Comment 5 Eric Seidel (no email) 2010-04-19 02:25:19 PDT
Created attachment 53662 [details]
Comment 6 Eric Seidel (no email) 2010-04-19 02:29:02 PDT
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.
Comment 7 Eric Seidel (no email) 2010-04-19 03:08:21 PDT
This will also get easier to debug once bug 37780 lands.
Comment 8 Eric Seidel (no email) 2010-04-19 03:47:37 PDT
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().
Comment 9 Eric Seidel (no email) 2010-04-19 03:50:50 PDT
Created attachment 53667 [details]
Added small speedup to test gathering
Comment 10 Adam Barth 2010-04-19 14:06:23 PDT
Comment on attachment 53667 [details]
Added small speedup to test gathering

Comment 11 Dirk Pranke 2010-04-19 14:19:49 PDT
Comment on attachment 53667 [details]
Added small speedup to test gathering

LGTM, apart from your removal of my beloved one-character variable names ;)
Comment 12 WebKit Commit Bot 2010-04-20 06:34:56 PDT
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
Comment 13 Dirk Pranke 2010-04-20 10:20:31 PDT
weird ... is the commit queue bot running an unusual version of python?
Comment 14 Adam Barth 2010-04-20 12:26:04 PDT
Comment on attachment 53667 [details]
Added small speedup to test gathering

Btw, this patch doesn't comply with our new unicode overlords.
Comment 15 Eric Seidel (no email) 2010-04-20 23:01:37 PDT
I wrote this patch on SL which has python 2.6.  I suspect I need to fix it for 2.5.
Comment 16 Eric Seidel (no email) 2010-04-20 23:21:54 PDT
from __future__ import with_statement
which fixed it.
Comment 17 Eric Seidel (no email) 2010-04-20 23:23:53 PDT
I'll make our unicode overlords happy an re-post before I commit.
Comment 18 Eric Seidel (no email) 2010-04-20 23:56:34 PDT
Landed as r57956.