Bug 187547 - [WinCairo] run-api-tests is timing out for almost all test cases
Summary: [WinCairo] run-api-tests is timing out for almost all test cases
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Tools / Tests (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Ross Kirsling
URL:
Keywords: InRadar
Depends on: 187581
Blocks:
  Show dependency treegraph
 
Reported: 2018-07-10 22:14 PDT by Fujii Hironori
Modified: 2018-07-17 03:14 PDT (History)
8 users (show)

See Also:


Attachments
WIP patch (1.30 KB, patch)
2018-07-10 22:25 PDT, Fujii Hironori
no flags Details | Formatted Diff | Diff
WIP patch (2.51 KB, patch)
2018-07-12 01:12 PDT, Fujii Hironori
no flags Details | Formatted Diff | Diff
Patch (3.65 KB, patch)
2018-07-13 14:21 PDT, Ross Kirsling
no flags Details | Formatted Diff | Diff
Patch (3.60 KB, patch)
2018-07-13 20:39 PDT, Ross Kirsling
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Fujii Hironori 2018-07-10 22:14:16 PDT
[WinCairo] run-api-tests is failing for almost all test cases

https://build.webkit.org/builders/WinCairo%2064-bit%20WKL%20Release%20%28Tests%29/builds/551

(...)
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_list_tests']
> "C:\WebKit-BuildWorker\wincairo-wkl-release-tests\build\WebKitBuild\Release\bin64\TestWTF.exe --gtest_list_tests" took 0.10s
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWebCore.exe', '--gtest_list_tests']
> "C:\WebKit-BuildWorker\wincairo-wkl-release-tests\build\WebKitBuild\Release\bin64\TestWebCore.exe --gtest_list_tests" took 0.12s
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWebKitLegacy.exe', '--gtest_list_tests']
> "C:\WebKit-BuildWorker\wincairo-wkl-release-tests\build\WebKitBuild\Release\bin64\TestWebKitLegacy.exe --gtest_list_tests" took 0.09s
> Found 860 tests
> Running tests
> Sharding tests ...
> worker/0 starting
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.DeletedAddressOfOperator']
> TestWTF.WTF_HashMap.DeletedAddressOfOperator Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.DoubleHashCollisions']
> TestWTF.WTF_HashMap.DoubleHashCollisions Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.EfficientGetter']
> TestWTF.WTF_HashMap.EfficientGetter Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.Ensure']
> TestWTF.WTF_HashMap.Ensure Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.Ensure_LambdasCapturingByReference']
> TestWTF.WTF_HashMap.Ensure_LambdasCapturingByReference Timeout
> Looking at [u'C:\\WebKit-BuildWorker\\wincairo-wkl-release-tests\\build\\WebKitBuild\\Release\\bin64\\TestWTF.exe', '--gtest_filter=WTF_HashMap.Ensure_MoveOnlyValues']
> TestWTF.WTF_HashMap.Ensure_MoveOnlyValues Passed
(...)
Comment 1 Fujii Hironori 2018-07-10 22:25:28 PDT
Created attachment 344751 [details]
WIP patch
Comment 2 Fujii Hironori 2018-07-11 00:59:12 PDT
It seems that ServerProcess is designed for interactive commands which basically never exits.
https://trac.webkit.org/browser/webkit/trunk/Tools/Scripts/webkitpy/port/server_process.py

But, TestWebKitAPI is not an interactive command, and it exits as soon as it finishes.

I think the reason webkitpy/api_tests/runner.py is using ServerProcess is non-blocking read for timeout.

'subprocess' module of Python 3 has timeout.
https://docs.python.org/3.7/library/subprocess.html

But, unfortunately, Python 2 doesn't.
Comment 3 Fujii Hironori 2018-07-12 01:12:06 PDT
Created attachment 344835 [details]
WIP patch

This WIP patch introduces new test failures.
PeekNamedPipe fails because MockFile returns invalid file descriptors.
Umm, :-(

> C:\webkit>python Tools\Scripts\test-webkitpy -v webkitpy.port.server_process_unittest
> Skipping lldb_webkit tests; could not find path to lldb.py ''.
> Skipping QueueStatusServer tests; the Google AppEngine Python SDK is not installed.
> Suppressing most webkitpy logging while running unit tests.
> [1/6] webkitpy.port.server_process_unittest.TestServerProcess.test_basic passed
> [2/6] webkitpy.port.server_process_unittest.TestServerProcess.test_broken_pipe erred:
>   Traceback (most recent call last):
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process_unittest.py", line 207, in test_broken_pipe
>       server_process.write("should break")
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 170, in write
>       self.stop(0.0)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 372, in stop
>       return self._wait_for_stop(timeout_secs)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 392, in _wait_for_stop
>       self._wait_for_data_and_update_buffers_using_win32_apis(now)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 301, in _wait_for_data_and_update_buffers_using_win32_apis
>       output = self._non_blocking_read_win32(out_fh)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 315, in _non_blocking_read_win32
>       _, avail, _ = win32pipe.PeekNamedPipe(handle, 0)
>   error: (1, 'PeekNamedPipe', '????????????????')
> 
> [3/6] webkitpy.port.server_process_unittest.TestServerProcess.test_cleanup erred:
>   Traceback (most recent call last):
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process_unittest.py", line 197, in test_cleanup
>       server_process.stop()
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 372, in stop
>       return self._wait_for_stop(timeout_secs)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 392, in _wait_for_stop
>       self._wait_for_data_and_update_buffers_using_win32_apis(now)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 301, in _wait_for_data_and_update_buffers_using_win32_apis
>       output = self._non_blocking_read_win32(out_fh)
>     File "C:\webkit\Tools\Scripts\webkitpy\port\server_process.py", line 315, in _non_blocking_read_win32
>       _, avail, _ = win32pipe.PeekNamedPipe(handle, 0)
>   error: (1, 'PeekNamedPipe', '????????????????')
> 
> [4/6] webkitpy.port.server_process_unittest.TestServerProcess.test_process_crashing passed
> [5/6] webkitpy.port.server_process_unittest.TestServerProcess.test_process_crashing_no_data passed
> [6/6] webkitpy.port.server_process_unittest.TestServerProcess.test_read_after_process_exits passed
> Ran 6 tests in 0.750s
> FAILED (failures=0, errors=2)
> 
> C:\webkit>
Comment 4 Ross Kirsling 2018-07-12 17:13:08 PDT
It appears that simply removing the `time.sleep(0.01)` is enough to fix the issue for run-api-tests.

The PeekNamedPipe errors seem to occur when we do the non-blocking read even though poll() is no longer None (i.e. the result of moving the while condition).

---

Note that there is an *existing* error with TestServerProcess.test_basic -- first, this condition appears to be bogus(?):
https://github.com/WebKit/webkit/blob/master/Tools/Scripts/webkitpy/port/server_process_unittest.py#L110-L112

Once we fix that though, we get...
> [1/5] webkitpy.port.server_process_unittest.TestServerProcess.test_basic erred:
>   Traceback (most recent call last):
>     File "C:\...\Tools\Scripts\webkitpy\port\server_process_unittest.py", line 123, in test_basic
>       self.assertEqual(line.strip(), "stderr")
>   AttributeError: 'NoneType' object has no attribute 'strip'

...which I still don't understand, but could probably be tracked in a separate ticket.
Comment 5 Ross Kirsling 2018-07-12 18:01:53 PDT
(In reply to Ross Kirsling from comment #4)
> ...which I still don't understand, but could probably be tracked in a
> separate ticket.

Oops, looks like there's already a patch for this in https://bugs.webkit.org/show_bug.cgi?id=187581. :D
Comment 6 Ross Kirsling 2018-07-13 14:21:37 PDT
Created attachment 344980 [details]
Patch
Comment 7 Ross Kirsling 2018-07-13 14:28:05 PDT
For some enigmatic reason, the issue was caused by calling Popen.poll immediately after time.sleep (or even win32api.Sleep).

The solution, however, was simple enough in hindsight:
- do NOT return immediately if we're still before the deadline (even if the process has exited)
- do NOT sleep if the process has already exited
Comment 8 Fujii Hironori 2018-07-13 15:43:17 PDT
(In reply to Ross Kirsling from comment #7)
> For some enigmatic reason, the issue was caused by calling Popen.poll
> immediately after time.sleep (or even win32api.Sleep).

What is the issue? What will happen if Popen.poll is called immediately after time.sleep?


> The solution, however, was simple enough in hindsight:
> - do NOT return immediately if we're still before the deadline (even if the
> process has exited)
> - do NOT sleep if the process has already exited

So simple. Nice.
Comment 9 Fujii Hironori 2018-07-13 15:45:33 PDT
Comment on attachment 344980 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=344980&action=review

> Tools/Scripts/webkitpy/port/server_process.py:308
>                  return

You should put the condition here instead of above.

self._proc.poll() is not None:
  return

> Tools/Scripts/webkitpy/port/server_process_unittest.py:131
> +        cmd = [sys.executable, '-c', 'import sys; print "stdout"; sys.stdout.flush(); print >>sys.stderr, "stderr"; sys.stderr.flush();']

All files are flushed when the process exits. You don't need to flush.
Comment 10 Ross Kirsling 2018-07-13 20:39:21 PDT
Created attachment 345018 [details]
Patch
Comment 11 Ross Kirsling 2018-07-13 22:13:33 PDT
Note: WinCairo failure here is of course unrelated. (I think it went red because I manually fixed the issue on the bot between the first and second checks.)
Comment 12 Fujii Hironori 2018-07-13 23:11:35 PDT
Comment on attachment 345018 [details]
Patch

r+
Comment 13 WebKit Commit Bot 2018-07-13 23:48:16 PDT
Comment on attachment 345018 [details]
Patch

Clearing flags on attachment: 345018

Committed r233834: <https://trac.webkit.org/changeset/233834>
Comment 14 WebKit Commit Bot 2018-07-13 23:48:18 PDT
All reviewed patches have been landed.  Closing bug.
Comment 15 Radar WebKit Bug Importer 2018-07-14 00:13:14 PDT
<rdar://problem/42194916>
Comment 16 Fujii Hironori 2018-07-17 03:14:43 PDT
Here is the WinCairo EWS error message:

> midl : command line error MIDL1016 : cannot create intermediate file C:\Users\ContainerAdministrator\AppData\Local\Temp\MIDEFA7.tmp

Filed Bug 187725.