Bug 171638 – [iOS Simulator] LayoutTest/http/tests/xmlhttprequest/methods.html is flaky timeout

• Component: Tools / Tests
• Status: NEW

[Matt Lewis]

The test http/tests/xmlhttprequest/methods.html is a flaky timeout.

History:
http/tests/xmlhttprequest/methods.html

The first recent timeout was on 4/28/2017 however looking further back the timeout has been occurring since 4/19


Build Log:
https://build.webkit.org/results/Apple%20iOS%2010%20Simulator%20Release%20WK2%20(Tests)/r216149%20(1142)/results.html

The change at 4/19 timeout was involving xml:
https://trac.webkit.org/changeset/215535/webkit

[Matt Lewis]

Created attachment 308996 [details]
Patch

[Ryan Haddad]

(In reply to Matt Lewis from comment #1)
> Created attachment 308996 [details]
> Patch

Landed this TestExpectations change manually in https://trac.webkit.org/changeset/216164/webkit

[Alexey Proskuryakov]

It seems like this test may be running too slowly indeed. Looking at Apache access log, I see that all expected XMLHttpRequests are being served, but it takes more that 40 seconds.

127.0.0.1 - - [03/May/2017:16:22:21 -0700] "GET /xmlhttprequest/methods.html HTTP/1.1" 200 5543 21230
127.0.0.1 - - [03/May/2017:16:22:21 -0700] "GET /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1124356
127.0.0.1 - - [03/May/2017:16:22:23 -0700] "GET /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1786445
127.0.0.1 - - [03/May/2017:16:22:24 -0700] "GET /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1762792
127.0.0.1 - - [03/May/2017:16:22:26 -0700] "POST /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1717806
127.0.0.1 - - [03/May/2017:16:22:28 -0700] "POST /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2197369
127.0.0.1 - - [03/May/2017:16:22:30 -0700] "POST /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1367520
127.0.0.1 - - [03/May/2017:16:22:31 -0700] "PUT /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2038816
127.0.0.1 - - [03/May/2017:16:22:33 -0700] "PUT /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1729765
127.0.0.1 - - [03/May/2017:16:22:35 -0700] "PUT /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2348214
127.0.0.1 - - [03/May/2017:16:22:37 -0700] "DELETE /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1861489
127.0.0.1 - - [03/May/2017:16:22:39 -0700] "DELETE /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1272580
127.0.0.1 - - [03/May/2017:16:22:41 -0700] "DELETE /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1922963
127.0.0.1 - - [03/May/2017:16:22:43 -0700] "HEAD /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2018892
127.0.0.1 - - [03/May/2017:16:22:45 -0700] "HEAD /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 5230834
127.0.0.1 - - [03/May/2017:16:22:50 -0700] "HEAD /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 4794447
127.0.0.1 - - [03/May/2017:16:22:55 -0700] "WKFOOBAR /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1443188
127.0.0.1 - - [03/May/2017:16:22:56 -0700] "WKFOOBAR /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1404468
127.0.0.1 - - [03/May/2017:16:22:57 -0700] "WKFOOBAR /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2062459
127.0.0.1 - - [03/May/2017:16:23:00 -0700] "SEARCH /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 1859566
127.0.0.1 - - [03/May/2017:16:23:01 -0700] "SEARCH /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2378319
127.0.0.1 - - [03/May/2017:16:23:04 -0700] "SEARCH /xmlhttprequest/methods.cgi HTTP/1.1" 200 - 2657827

The last item in each line tells how long it took to serve the request, in microseconds. It doesn't look good that this simple CGI script takes several seconds each time!

[Alexey Proskuryakov]

Created attachment 309149 [details]
spindump

run-webkit-tests captured a spindump

[Alexey Proskuryakov]

Created attachment 309150 [details]
access log

Full Apache access log for this period of time. HTML files are being served super fast, but cgi scripts (including those for other tests) are very slow.

Perhaps the system is under such stress that it cannot spawn new processes fast, or maybe it's something about how CGI scripts work in Apache.

[Alexey Proskuryakov]

Some timings taken on command line while running tests:

$ time /bin/echo 0
0

real	0m1.142s
user	0m0.001s
sys	0m0.016s

$ time /bin/echo 0
0

real	0m3.265s
user	0m0.001s
sys	0m0.029s

$ time perl -e "print 1;"
1
real	0m5.574s
user	0m0.003s
sys	0m0.846s

That would cause interesting effects for sure.

[Alexey Proskuryakov]

This got much faster when the bot is idle, but it's still 10x slower than on my MacBook Pro (150 ms vs. 15 ms for 'perl -e "print 1;"').

[Alexey Proskuryakov]

And having found that, I think that this is rdar://problem/28219123. It even mentions about the same tests.

We should simply reboot the bots, and make sure that we don't go so long without rebooting (these have 108 days of uptime).

[Ryan Haddad]

(In reply to Alexey Proskuryakov from comment #8)
> And having found that, I think that this is rdar://problem/28219123. It even
> mentions about the same tests.
> 
> We should simply reboot the bots, and make sure that we don't go so long
> without rebooting (these have 108 days of uptime).

I have rebooted all of the iOS test bots.