205357 2019-12-17 13:41:56 -0800 [ Mac wk1 Debug ] fast/workers/worker-cloneport.html is timing out constantly 2019-12-19 12:32:53 -0800 1 1 1 Unclassified WebKit Tools / Tests WebKit Nightly Build Unspecified Unspecified RESOLVED DUPLICATE 205414 https://bugs.webkit.org/show_bug.cgi?id=182007 https://bugs.webkit.org/show_bug.cgi?id=202296 https://bugs.webkit.org/show_bug.cgi?id=201333 https://bugs.webkit.org/show_bug.cgi?id=205414 InRadar P2 Normal --- 1 tsavell cdumez achristensen beidson cdumez ggaren rniwa webkit-bot-watchers-bugzilla webkit-bug-importer youennf oldest_to_newest 1599546 0 tsavell 2019-12-17 13:41:56 -0800 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 1599549 1 webkit-bug-importer 2019-12-17 13:42:22 -0800 <rdar://problem/58019803> 1599554 2 tsavell 2019-12-17 13:45:15 -0800 This was last touched in https://trac.webkit.org/changeset/244888/webkit 1599913 3 cdumez 2019-12-18 12:12:25 -0800 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 1599936 4 cdumez 2019-12-18 12:43:50 -0800 The test passes locally for me on WK1 Debug Catalina. 1599940 5 cdumez 2019-12-18 12:45:25 -0800 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. 1599941 6 cdumez 2019-12-18 12:46:54 -0800 (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. 1599946 7 cdumez 2019-12-18 12:54:32 -0800 (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. 1599947 8 ap 2019-12-18 12:56:25 -0800 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. 1599950 9 cdumez 2019-12-18 13:00:38 -0800 (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. 1599955 10 cdumez 2019-12-18 13:11:00 -0800 (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())); }); } 1599958 11 cdumez 2019-12-18 13:22:46 -0800 (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. 1599961 12 ap 2019-12-18 13:26:43 -0800 > 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. 1599974 13 386002 cdumez 2019-12-18 13:59:20 -0800 Created attachment 386002 Patch 1600336 14 cdumez 2019-12-19 09:51:07 -0800 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 *** 1600409 15 ap 2019-12-19 11:49:46 -0800 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. 1600416 16 cdumez 2019-12-19 12:03:59 -0800 (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. 1600439 17 cdumez 2019-12-19 12:32:53 -0800 (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>. 386002 2019-12-18 13:59:20 -0800 2019-12-18 20:59:36 -0800 Patch bug-205357-20191218135920.patch text/plain 3496 cdumez U3VidmVyc2lvbiBSZXZpc2lvbjogMjUzNzA0CmRpZmYgLS1naXQgYS9MYXlvdXRUZXN0cy9DaGFu Z2VMb2cgYi9MYXlvdXRUZXN0cy9DaGFuZ2VMb2cKaW5kZXggZjNiNDBiZjkxNmY5ZDU4NjUxODI4 ZmY1YjBmOGI0NmIwYWIxNGE4NC4uMTNmMDAwNzZiNmZhODBkOGIyYmEzNjY0ZGQ5YTU2NjBjMDA0 NTRmZSAxMDA2NDQKLS0tIGEvTGF5b3V0VGVzdHMvQ2hhbmdlTG9nCisrKyBiL0xheW91dFRlc3Rz L0NoYW5nZUxvZwpAQCAtMSwzICsxLDE5IEBACisyMDE5LTEyLTE4ICBDaHJpcyBEdW1leiAgPGNk dW1lekBhcHBsZS5jb20+CisKKyAgICAgICAgWyBNYWMgd2sxIERlYnVnIF0gZmFzdC93b3JrZXJz L3dvcmtlci1jbG9uZXBvcnQuaHRtbCBpcyB0aW1pbmcgb3V0IGNvbnN0YW50bHkKKyAgICAgICAg aHR0cHM6Ly9idWdzLndlYmtpdC5vcmcvc2hvd19idWcuY2dpP2lkPTIwNTM1NworICAgICAgICA8 cmRhcjovL3Byb2JsZW0vNTgwMTk4MDM+CisKKyAgICAgICAgUmV2aWV3ZWQgYnkgTk9CT0RZIChP T1BTISkuCisKKyAgICAgICAgVGhlIHRlc3QgaXMgdmVyeSBzbG93LCBlc3BlY2lhbGx5IGluIGRl YnVnIGJ1aWxkcyAoaXQgd2FzIHRha2luZyAxNiBzZWNvbmRzIG9uIG15IGlNYWMgUHJvKS4KKyAg ICAgICAgVGhpcyB3YXMgY2F1c2luZyB0aGUgdGVzdCB0byB0aW1lIG91dCBpbiBzb21lIGNvbmZp Z3VyYXRpb25zLiBUbyBhZGRyZXNzIHRoZSBpc3N1ZSwgdXBkYXRlCisgICAgICAgIHRoZSB0ZXN0 IHRvIHNlbmQgbGVzcyBtZXNzYWdlcyBzbyB0aGF0IGl0IHJ1bnMgaW4gYSBtb3JlIHJlYXNvbmFi bGUgYW1vdW50IG9mIHRpbWUuCisKKyAgICAgICAgKiBUZXN0RXhwZWN0YXRpb25zOgorICAgICAg ICAqIGZhc3Qvd29ya2Vycy93b3JrZXItY2xvbmVwb3J0LWV4cGVjdGVkLnR4dDoKKyAgICAgICAg KiBmYXN0L3dvcmtlcnMvd29ya2VyLWNsb25lcG9ydC5odG1sOgorCiAyMDE5LTEyLTE4ICBDaHJp cyBEdW1leiAgPGNkdW1lekBhcHBsZS5jb20+CiAKICAgICAgICAgVW5yZXZpZXdlZCwgcmViYXNl bGluZSBhbGwgc2VydmljZSB3b3JrZXJzIHRlc3RzIGFuZCB1bnNraXAgMiB0aGF0IG5vIGxvbmdl ciB0aW1lIG91dC4KZGlmZiAtLWdpdCBhL0xheW91dFRlc3RzL1Rlc3RFeHBlY3RhdGlvbnMgYi9M YXlvdXRUZXN0cy9UZXN0RXhwZWN0YXRpb25zCmluZGV4IDU0OGVhM2VlYzE5YmM4NDk3NzIwYmU5 ZjZiYmZlNWM0ZTQ5MTc1NjMuLjU0NzIyYzZlMTI0NzViYWM1NjA0ZGUzMWI1ZTFkZDZlZmY1YmQ3 NjYgMTAwNjQ0Ci0tLSBhL0xheW91dFRlc3RzL1Rlc3RFeHBlY3RhdGlvbnMKKysrIGIvTGF5b3V0 VGVzdHMvVGVzdEV4cGVjdGF0aW9ucwpAQCAtMTU2MCw4ICsxNTYwLDYgQEAgd2Via2l0Lm9yZy9i LzE4OTY0MSB3ZWJnbC8yLjAuMC9jb25mb3JtYW5jZS9vZ2xlcy9HTC9tYXQvbWF0XzAwMV90b18w MDguaHRtbCBbIFMKIAogd2Via2l0Lm9yZy9iLzE4OTY0MSB3ZWJnbC8yLjAuMC9jb25mb3JtYW5j ZTIvcmVuZGVyaW5nL2JsaXRmcmFtZWJ1ZmZlci1maWx0ZXItb3V0b2Zib3VuZHMuaHRtbCBbIFNs b3cgXQogCi1bIERlYnVnIF0gZmFzdC93b3JrZXJzL3dvcmtlci1jbG9uZXBvcnQuaHRtbCBbIFNs b3cgXQotCiAjIEltcG9ydGVkIFczQyBIVE1ML0RPTSByZWYgdGVzdHMgdGhhdCBhcmUgZmFpbGlu Zy4KIGltcG9ydGVkL3czYy93ZWItcGxhdGZvcm0tdGVzdHMvaHRtbC9kb20vZWxlbWVudHMvZ2xv YmFsLWF0dHJpYnV0ZXMvZGlyX2F1dG8tcHJlLU4tYmV0d2Vlbi1Scy5odG1sIFsgSW1hZ2VPbmx5 RmFpbHVyZSBdCiBpbXBvcnRlZC93M2Mvd2ViLXBsYXRmb3JtLXRlc3RzL2h0bWwvZG9tL2VsZW1l bnRzL2dsb2JhbC1hdHRyaWJ1dGVzL2Rpcl9hdXRvLXRleHRhcmVhLU4tYmV0d2Vlbi1Scy5odG1s IFsgSW1hZ2VPbmx5RmFpbHVyZSBdCmRpZmYgLS1naXQgYS9MYXlvdXRUZXN0cy9mYXN0L3dvcmtl cnMvd29ya2VyLWNsb25lcG9ydC1leHBlY3RlZC50eHQgYi9MYXlvdXRUZXN0cy9mYXN0L3dvcmtl cnMvd29ya2VyLWNsb25lcG9ydC1leHBlY3RlZC50eHQKaW5kZXggZDRjNjAxZjRiOTFlYThiZGVl NDVkNDYzOGVmZTM2ZWVmZDk5ZmUxYi4uNzQzOTRjMWQ0MmI3ZGMwNmI0NjIyYzI1NDBlOTA1YWE2 NDliN2RjMCAxMDA2NDQKLS0tIGEvTGF5b3V0VGVzdHMvZmFzdC93b3JrZXJzL3dvcmtlci1jbG9u ZXBvcnQtZXhwZWN0ZWQudHh0CisrKyBiL0xheW91dFRlc3RzL2Zhc3Qvd29ya2Vycy93b3JrZXIt Y2xvbmVwb3J0LWV4cGVjdGVkLnR4dApAQCAtMSw2ICsxLDYgQEAKIFRlc3QgTWVzc2FnZVBvcnQg bWVzc2FnaW5nL2VudGFuZ2xlL2RldGFuZ2xlIGFjcm9zcyB0aHJlYWRzLiBTaG91bGQgcHJpbnQg IlNVQ0NFU1MiIHdoZW4gZG9uZS4KIAotUEFTUzogUmVjZWl2ZWQgcmVxdWVzdCBmb3IgNTAwMDAg bWVzc2FnZXMKLVNVQ0NFU1MgLSByZWNlaXZlZCA1MDAwMCBtZXNzYWdlcy4KK1BBU1M6IFJlY2Vp dmVkIHJlcXVlc3QgZm9yIDEwMDAgbWVzc2FnZXMKK1NVQ0NFU1MgLSByZWNlaXZlZCAxMDAwIG1l c3NhZ2VzLgogRE9ORQogCmRpZmYgLS1naXQgYS9MYXlvdXRUZXN0cy9mYXN0L3dvcmtlcnMvd29y a2VyLWNsb25lcG9ydC5odG1sIGIvTGF5b3V0VGVzdHMvZmFzdC93b3JrZXJzL3dvcmtlci1jbG9u ZXBvcnQuaHRtbAppbmRleCBmN2YzM2JmMWY1NTJlMzc5NmQ4M2M4YmJhMzY2NTYzODdjOGNiN2Y0 Li42NDY2OTE1NzdjY2U1ODc1ZTdlMWFiZDQwMWM1ZGRlYjA0YmU0N2VjIDEwMDY0NAotLS0gYS9M YXlvdXRUZXN0cy9mYXN0L3dvcmtlcnMvd29ya2VyLWNsb25lcG9ydC5odG1sCisrKyBiL0xheW91 dFRlc3RzL2Zhc3Qvd29ya2Vycy93b3JrZXItY2xvbmVwb3J0Lmh0bWwKQEAgLTE0LDcgKzE0LDcg QEAgaWYgKHdpbmRvdy50ZXN0UnVubmVyKSB7CiAKIAogdmFyIGNoYW5uZWwgPSBuZXcgTWVzc2Fn ZUNoYW5uZWwoKTsKLXZhciBudW1NZXNzYWdlcyA9IDUwMDAwOwordmFyIG51bU1lc3NhZ2VzID0g MTAwMDsKIAogLy8gQ3JlYXRlIGEgY2hhbm5lbCB3aGljaCB3ZSB3aWxsIHVzZSB0byBjbG9uZSBh bmQgcmUtY2xvbmUgb25lIGVuZCBvZiBhCiAvLyBNZXNzYWdlQ2hhbm5lbC4KQEAgLTMwLDcgKzMw LDcgQEAgY2xvbmVDaGFubmVsLnBvcnQxLnBvc3RNZXNzYWdlKCIiLCBbY2hhbm5lbC5wb3J0Ml0p OwogdmFyIHdvcmtlciA9IG5ldyBXb3JrZXIoInJlc291cmNlcy93b3JrZXItY2xvbmVwb3J0Lmpz Iik7CiB3b3JrZXIucG9zdE1lc3NhZ2UoInBvc3RCYWNrICIgKyBudW1NZXNzYWdlcywgW2NoYW5u ZWwucG9ydDFdKTsKIAotLy8gVGVzdCBwb3N0aW5nIGJhY2sgNTAwMDAgbWVzc2FnZXMsIG1ha2Ug c3VyZSBvcmRlcmluZyBpcyBmaW5lCisvLyBUZXN0IHBvc3RpbmcgYmFjayAxMDAwIG1lc3NhZ2Vz LCBtYWtlIHN1cmUgb3JkZXJpbmcgaXMgZmluZQogd29ya2VyLm9ubWVzc2FnZSA9IGZ1bmN0aW9u KGV2dCkgewogICAgIGlmIChldnQuZGF0YSA9PSAicG9zdEJhY2tEb25lIikgewogICAgICAgICBz dG9wQ2xvbmluZyA9IHRydWU7Cg==