| Summary: | new-run-webkit-tests has much higher startup latency than run-webkit-tests | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | WebKit | Reporter: | Maciej Stachowiak <mjs> | ||||||
| Component: | Tools / Tests | Assignee: | Nobody <webkit-unassigned> | ||||||
| Status: | RESOLVED FIXED | ||||||||
| Severity: | Normal | CC: | abarth, commit-queue, dpranke, eric | ||||||
| Priority: | P2 | ||||||||
| Version: | 528+ (Nightly build) | ||||||||
| Hardware: | PC | ||||||||
| OS: | OS X 10.5 | ||||||||
| Bug Depends on: | 37780 | ||||||||
| Bug Blocks: | |||||||||
| Attachments: |
|
||||||||
|
Description
Maciej Stachowiak
2010-04-15 00:51:26 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. Seems like we could benefit from using Python's profiler to figure out what's taking the time. 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}
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.
Created attachment 53662 [details]
Patch
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.
This will also get easier to debug once bug 37780 lands. 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(). Created attachment 53667 [details]
Added small speedup to test gathering
Comment on attachment 53667 [details]
Added small speedup to test gathering
Nice!
Comment on attachment 53667 [details]
Added small speedup to test gathering
LGTM, apart from your removal of my beloved one-character variable names ;)
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 weird ... is the commit queue bot running an unusual version of python? Comment on attachment 53667 [details]
Added small speedup to test gathering
Btw, this patch doesn't comply with our new unicode overlords.
I wrote this patch on SL which has python 2.6. I suspect I need to fix it for 2.5. Add: from __future__ import with_statement which fixed it. I'll make our unicode overlords happy an re-post before I commit. Landed as r57956. |