Bug 205357 – [ Mac wk1 Debug ] fast/workers/worker-cloneport.html is timing out constantly

• Component: Tools / Tests
• Status: RESOLVED DUPLICATE

[Truitt Savell]

fast/workers/worker-cloneport.html

This test is timing out constantly on Catalina and High Sierra WK1 Debug. This has been occurring for the whole history.

History:
https://results.webkit.org/?suite=layout-tests&test=fast%2Fworkers%2Fworker-cloneport.html

[Radar WebKit Bug Importer]

<rdar://problem/58019803>

[Truitt Savell]

This was last touched in https://trac.webkit.org/changeset/244888/webkit

[Chris Dumez]

Output:
FAIL: Timed out waiting for notifyDone to be called
Test MessagePort messaging/entangle/detangle across threads. Should print "SUCCESS" when done.

PASS: Received request for 50000 messages

[Chris Dumez]

The test passes locally for me on WK1 Debug Catalina.

[Chris Dumez]

It is a very slow test though, especially in Debug and I have a fast machine. Odds are that it is simply the test being slow. It seems to involve sending 50000 messages and cloning message ports.

[Chris Dumez]

(In reply to Chris Dumez from comment #5)
> It is a very slow test though, especially in Debug and I have a fast
> machine. Odds are that it is simply the test being slow. It seems to involve
> sending 50000 messages and cloning message ports.

Given that fact that the test is passing fine in release builds on all the bots makes this even more likely.

[Chris Dumez]

(In reply to Chris Dumez from comment #6)
> (In reply to Chris Dumez from comment #5)
> > It is a very slow test though, especially in Debug and I have a fast
> > machine. Odds are that it is simply the test being slow. It seems to involve
> > sending 50000 messages and cloning message ports.
> 
> Given that fact that the test is passing fine in release builds on all the
> bots makes this even more likely.

The test takes 16 seconds to run on my iMac Pro in debug wk1.

[Alexey Proskuryakov]

This test was taking 20-60 seconds on debug bots before 2019-09-30 (already marked as slow). So it became much slower on that day.

[Chris Dumez]

(In reply to Alexey Proskuryakov from comment #8)
> This test was taking 20-60 seconds on debug bots before 2019-09-30 (already
> marked as slow). So it became much slower on that day.

Could be https://bugs.webkit.org/show_bug.cgi?id=202296 which started using the HTML event loop for dispatching MessageEvents.

[Chris Dumez]

(In reply to Chris Dumez from comment #9)
> (In reply to Alexey Proskuryakov from comment #8)
> > This test was taking 20-60 seconds on debug bots before 2019-09-30 (already
> > marked as slow). So it became much slower on that day.
> 
> Could be https://bugs.webkit.org/show_bug.cgi?id=202296 which started using
> the HTML event loop for dispatching MessageEvents.

Although, if I try to dispatch the messages synchronously again (instead of using the event loop), then the test takes even more time to run on my machine (30 seconds):
cdumezs-iMac-Pro:OpenSource cdumez$ git diff
diff --git a/Source/WebCore/dom/MessagePort.cpp b/Source/WebCore/dom/MessagePort.cpp
index 7f604f4e088..8df6080c1bd 100644
--- a/Source/WebCore/dom/MessagePort.cpp
+++ b/Source/WebCore/dom/MessagePort.cpp
@@ -276,7 +276,8 @@ void MessagePort::dispatchMessages()
                 return;
             auto ports = MessagePort::entanglePorts(*m_scriptExecutionContext, WTFMove(message.transferredPorts));
             // Per specification, each MessagePort object has a task source called the port message queue.
-            queueTaskToDispatchEvent(*this, TaskSource::PostedMessageQueue, MessageEvent::create(WTFMove(ports), message.message.releaseNonNull()));
+            //queueTaskToDispatchEvent(*this, TaskSource::PostedMessageQueue, MessageEvent::create(WTFMove(ports), message.message.releaseNonNull()));
+            dispatchEvent(MessageEvent::create(WTFMove(ports), message.message.releaseNonNull()));
         }
     };
 
diff --git a/Source/WebCore/workers/WorkerMessagingProxy.cpp b/Source/WebCore/workers/WorkerMessagingProxy.cpp
index 46037fa1805..4e1a1235710 100644
--- a/Source/WebCore/workers/WorkerMessagingProxy.cpp
+++ b/Source/WebCore/workers/WorkerMessagingProxy.cpp
@@ -104,7 +104,8 @@ void WorkerMessagingProxy::postMessageToWorkerObject(MessageWithMessagePorts&& m
             return;
 
         auto ports = MessagePort::entanglePorts(context, WTFMove(message.transferredPorts));
-        ActiveDOMObject::queueTaskToDispatchEvent(*workerObject, TaskSource::PostedMessageQueue, MessageEvent::create(WTFMove(ports), message.message.releaseNonNull()));
+        //ActiveDOMObject::queueTaskToDispatchEvent(*workerObject, TaskSource::PostedMessageQueue, MessageEvent::create(WTFMove(ports), message.message.releaseNonNull()));
+        workerObject->dispatchEvent(MessageEvent::create(WTFMove(ports), message.message.releaseNonNull()));
     });
 }

[Chris Dumez]

(In reply to Alexey Proskuryakov from comment #8)
> This test was taking 20-60 seconds on debug bots before 2019-09-30 (already
> marked as slow). So it became much slower on that day.

The test was already consistently timing out on 2019-09-16 on Mac wk1 (over 120 seconds). I do not see the regression on 2019-09-30. Also, since it is debug only and the test is sending 50000 messages, this could have very easily started timing out in debug due to more assertions or logging.

[Alexey Proskuryakov]

> The test was already consistently timing out on 2019-09-16 on Mac wk1 (over 120 seconds). I do not see the regression on 2019-09-30.

I think that you are looking at something else on internal history. I'll e-mail directly.

[Chris Dumez]

Created attachment 386002 [details]
Patch

[Chris Dumez]

It looks like Bug 205414 did the trick so I am keeping the test as is for now.

*** This bug has been marked as a duplicate of bug 205414 ***

[Alexey Proskuryakov]

Perfect! Also seeing ~2x speedup on release.

We still have TestExpectations:

> LayoutTests/TestExpectations:1560:[ Debug ] fast/workers/worker-cloneport.html [ Slow ]

Probably OK to keep, as it still takes 10-12 seconds on debug, so while it's below 30 seconds, random 3x spikes sometimes happen.

> LayoutTests/platform/ios-wk2/TestExpectations:538:fast/workers/worker-cloneport.html

Not sure why it's skipped on iOS.

[Chris Dumez]

(In reply to Alexey Proskuryakov from comment #15)
> Perfect! Also seeing ~2x speedup on release.

Nice.

> 
> We still have TestExpectations:
> 
> > LayoutTests/TestExpectations:1560:[ Debug ] fast/workers/worker-cloneport.html [ Slow ]
> 
> Probably OK to keep, as it still takes 10-12 seconds on debug, so while it's
> below 30 seconds, random 3x spikes sometimes happen.

Yes, this was my thought as well. It is still a slow test as is, I merely fixed the fairly recent perf regression.

> > LayoutTests/platform/ios-wk2/TestExpectations:538:fast/workers/worker-cloneport.html
> 
> Not sure why it's skipped on iOS.

Me neither, it seems like something that should work on iOS. Maybe it was super slow there. I can try to run it on iOS to see what happens.

[Chris Dumez]

(In reply to Chris Dumez from comment #16)
> (In reply to Alexey Proskuryakov from comment #15)
> > Perfect! Also seeing ~2x speedup on release.
> 
> Nice.
> 
> > 
> > We still have TestExpectations:
> > 
> > > LayoutTests/TestExpectations:1560:[ Debug ] fast/workers/worker-cloneport.html [ Slow ]
> > 
> > Probably OK to keep, as it still takes 10-12 seconds on debug, so while it's
> > below 30 seconds, random 3x spikes sometimes happen.
> 
> Yes, this was my thought as well. It is still a slow test as is, I merely
> fixed the fairly recent perf regression.
> 
> > > LayoutTests/platform/ios-wk2/TestExpectations:538:fast/workers/worker-cloneport.html
> > 
> > Not sure why it's skipped on iOS.
> 
> Me neither, it seems like something that should work on iOS. Maybe it was
> super slow there. I can try to run it on iOS to see what happens.

Seems to run fine in iOS debug for me, unskipping in <https://trac.webkit.org/changeset/253782>.