76003 2012-01-10 15:54:24 -0800 REGRESSION (r104210): WebProcess spins at 100% CPU for several minutes when loading an internal Apple site 2012-01-10 23:11:02 -0800 1 1 1 Unclassified WebKit DOM 528+ (Nightly build) Unspecified Unspecified RESOLVED FIXED InRadar, Regression P1 Normal --- 76032 1 mrowe webkit-unassigned kling koivisto oliver rniwa sam oldest_to_newest 533441 0 mrowe 2012-01-10 15:54:24 -0800 After r104210 we're seeing WebProcess spin at 100% CPU for several minutes after loading pages on an internal Apple site. A sample shows that almost all of the time is being spent in DynamicSubtreeNodeList::length below calls to WebCore::JSNodeList::getOwnPropertySlotByIndex. I'll attach a reduction that demonstrates the regression. <rdar://problem/10672251> 533443 1 121927 mrowe 2012-01-10 15:55:37 -0800 Created attachment 121927 Reduction (may hang your browser for 30+ seconds!) This reduction demonstrates the issue. The iteration step took ~200ms pre-r104210 but now takes around 30 seconds. 533506 2 rniwa 2012-01-10 17:18:55 -0800 (In reply to comment #0) > After r104210 we're seeing WebProcess spin at 100% CPU for several minutes after loading pages on an internal Apple site. A sample shows that almost all of the time is being spent in DynamicSubtreeNodeList::length below calls to WebCore::JSNodeList::getOwnPropertySlotByIndex. I'll attach a reduction that demonstrates the regression. According to my research people rarely modified DOM while hanging onto node list. This regression is the most pathological case where you're looping over node list and modifying DOM. I suppose such code wasn't as unusual as I initially thought but you can get the same hang even before r104210 if you had modified the class name of any element inside the loop; e.g. element.className = 'hide'; 533560 3 rniwa 2012-01-10 18:40:06 -0800 Oh man... JSNodeList::getOwnPropertySlotByIndex is always calling NodeList::length() before calling NodeList::item(). This would mean that we'll end up iterating through the entire subtree whenever we call DynamicSubtreeNodeList::item from JavaScript unless the length is cached :( 533562 4 rniwa 2012-01-10 18:45:56 -0800 Could you tell me what getOwnPropertySlotByIndex is doing and if there's way to avoid calling length there? I'm guessing that we just need to verify that the specified index exists. Is that right? In that case, we can probably add new methods like isIndexValid(unsigned) that only looks for the specified index. 533580 5 mrowe 2012-01-10 19:30:04 -0800 Perhaps I'm missing something, but how would isIndexValid help? It seems as though you'd still have to walk over the subtree in order to return an answer. 533609 6 oliver 2012-01-10 20:58:39 -0800 (In reply to comment #2) > (In reply to comment #0) > > After r104210 we're seeing WebProcess spin at 100% CPU for several minutes after loading pages on an internal Apple site. A sample shows that almost all of the time is being spent in DynamicSubtreeNodeList::length below calls to WebCore::JSNodeList::getOwnPropertySlotByIndex. I'll attach a reduction that demonstrates the regression. > > According to my research people rarely modified DOM while hanging onto node list. This regression is the most pathological case where you're looping over node list and modifying DOM. > > I suppose such code wasn't as unusual as I initially thought but you can get the same hang even before r104210 if you had modified the class name of any element inside the loop; e.g. element.className = 'hide'; To me it seems like a fairly obvious pattern to get a nodelist and then iterate over that list modifying attributes. This seems like a fairly significant reason for them to exist at all. 533637 7 121977 rniwa 2012-01-10 22:14:19 -0800 Created attachment 121977 reduction for pre r104210 (In reply to comment #6) > To me it seems like a fairly obvious pattern to get a nodelist and then iterate over that list modifying attributes. This seems like a fairly significant reason for them to exist at all. According to my study on the bug 73853, this accounts for less than 1% of the real world usage of node list API. Also this behavior existed prior to r104210 as well. You just need to touch the right attribute. 533639 8 rniwa 2012-01-10 22:20:26 -0800 If we want to optimize for this case and keep caches as long as we can, then we should completely abandon (revert) the approach took in r104263. 533643 9 mrowe 2012-01-10 22:24:28 -0800 I don't agree with your retitling of this bug. It hides the most important fact here: that the change in r104210 broke a real-world website. 533644 10 rniwa 2012-01-10 22:27:38 -0800 (In reply to comment #9) > I don't agree with your retitling of this bug. It hides the most important fact here: that the change in r104210 broke a real-world website. I knew I was regressing the performance on some websites as a trade off, and the example I gave here demonstrates that the same behavior can be replicated prior to r104210. I don't think I need to demonstrate the fact some websites would be hitting the case I posted. 533645 11 rniwa 2012-01-10 22:30:32 -0800 (In reply to comment #5) > Perhaps I'm missing something, but how would isIndexValid help? It seems as though you'd still have to walk over the subtree in order to return an answer. At least then we wouldn't have to traverse through the entire subtree on every iteration of the loop. 533647 12 mrowe 2012-01-10 22:33:09 -0800 (In reply to comment #10) > (In reply to comment #9) > > I don't agree with your retitling of this bug. It hides the most important fact here: that the change in r104210 broke a real-world website. > > I knew I was regressing the performance on some websites as a trade off, and the example I gave here demonstrates that the same behavior can be replicated prior to r104210. I don't think I need to demonstrate the fact some websites would be hitting the case I posted. Existing websites are much less likely to be doing something along the lines of your posted example because it already had terrible performance in shipping versions of WebKit. Existing websites could easily be doing something along the lines of the reduction because until r104210 it was sufficiently fast. When your trade-off makes code that formerly ran in O(N) time now run in O(N ** 2) time, perhaps it's not the right one. 533651 13 rniwa 2012-01-10 22:36:59 -0800 (In reply to comment #12) > Existing websites are much less likely to be doing something along the lines of your posted example because it already had terrible performance in shipping versions of WebKit. Existing websites could easily be doing something along the lines of the reduction because until r104210 it was sufficiently fast. > > When your trade-off makes code that formerly ran in O(N) time now run in O(N ** 2) time, perhaps it's not the right one. I completely disagree with either one of your points but I'm rolling out r104210 anyway to improve the node lists performance. 533665 14 121927 rniwa 2012-01-10 23:05:33 -0800 Comment on attachment 121927 Reduction (may hang your browser for 30+ seconds!) Now that the patch has been rolled out in http://trac.webkit.org/changeset/104674, this reduction is obsolete. 533666 15 mrowe 2012-01-10 23:06:27 -0800 Thanks for fixing this issue. 121927 2012-01-10 15:55:37 -0800 2012-01-10 23:06:59 -0800 Reduction (may hang your browser for 30+ seconds!) rdar-10672251.html text/html 1197 mrowe PGh0bWw+CjxoZWFkPgogICAgPG1ldGEgY2hhcnNldD0idXRmLTgiPgo8L2hlYWQ+Cjxib2R5Pgog ICAgPGRpdiBpZD0ibG9nIj48L2Rpdj4KICAgIDxzY3JpcHQ+CgpmdW5jdGlvbiBsb2cobWVzc2Fn ZSkKewogICAgdmFyIG1lc3NhZ2VFbGVtZW50ID0gZG9jdW1lbnQuY3JlYXRlRWxlbWVudCgncCcp OwogICAgbWVzc2FnZUVsZW1lbnQuYXBwZW5kQ2hpbGQoZG9jdW1lbnQuY3JlYXRlVGV4dE5vZGUo bWVzc2FnZSkpOwogICAgZG9jdW1lbnQuZ2V0RWxlbWVudEJ5SWQoJ2xvZycpLmFwcGVuZENoaWxk KG1lc3NhZ2VFbGVtZW50KTsKfQoKZnVuY3Rpb24gaW5pdGlhbGl6ZSgpCnsKICAgIHZhciBzdGFy dCA9ICtuZXcgRGF0ZSgpOwoKICAgIHZhciBjb250YWluZXIgPSBkb2N1bWVudC5jcmVhdGVFbGVt ZW50KCdkaXYnKTsKICAgIGZvciAodmFyIGkgPSAwOyBpIDwgMjAwMDA7ICsraSkgewogICAgICAg IHZhciBzcGFuID0gZG9jdW1lbnQuY3JlYXRlRWxlbWVudCgnc3BhbicpOwogICAgICAgIHNwYW4u Y2xhc3NOYW1lID0gInRlc3QiOwogICAgICAgIGNvbnRhaW5lci5hcHBlbmRDaGlsZChzcGFuKTsK ICAgIH0KICAgIGRvY3VtZW50LmJvZHkuYXBwZW5kQ2hpbGQoY29udGFpbmVyKTsKCiAgICBsb2co J0NyZWF0aW5nIGVsZW1lbnRzIHRvb2sgJyArICgrKG5ldyBEYXRlKCkpIC0gc3RhcnQpICsgJ21z Jyk7CgogICAgc2V0VGltZW91dChydW5UZXN0LCAxMDApOwogICAgbG9nKCdUZXN0aW5nIGl0ZXJh dGlvbiBvZiBOb2RlTGlzdCwgcGxlYXNlIHdhaXTigKYnKTsKfQoKZnVuY3Rpb24gcnVuVGVzdCgp CnsKICAgIHZhciBzdGFydCA9ICtuZXcgRGF0ZSgpOwoKICAgIHZhciBub2RlTGlzdCA9IGRvY3Vt ZW50LmdldEVsZW1lbnRzQnlDbGFzc05hbWUoInRlc3QiKTsKICAgIGZvciAodmFyIGkgPSAwLCBj b3VudCA9IG5vZGVMaXN0Lmxlbmd0aDsgaSA8IGNvdW50OyArK2kpIHsKICAgICAgICB2YXIgZWxl bWVudCA9IG5vZGVMaXN0W2ldOwogICAgICAgIGVsZW1lbnQuc2V0QXR0cmlidXRlKCdzdHlsZScs ICJkaXNwbGF5OiBub25lIik7CiAgICB9CgogICAgbG9nKCdJdGVyYXRpbmcgYW5kIHNldHRpbmcg dGhlaXIgc3R5bGUgdG8gZGlzcGxheTpub25lIHRvb2sgJyArICgrKG5ldyBEYXRlKCkpIC0gc3Rh cnQpICsgJ21zJyk7Cn0KCiAgICBpbml0aWFsaXplKCk7CgogICAgPC9zY3JpcHQ+CjwvYm9keT4K 121977 2012-01-10 22:14:19 -0800 2012-01-10 22:14:19 -0800 reduction for pre r104210 test.html text/html 1186 rniwa PGh0bWw+CjxoZWFkPgogICAgPG1ldGEgY2hhcnNldD0idXRmLTgiPgo8L2hlYWQ+Cjxib2R5Pgog ICAgPGRpdiBpZD0ibG9nIj48L2Rpdj4KICAgIDxzY3JpcHQ+CgpmdW5jdGlvbiBsb2cobWVzc2Fn ZSkKewogICAgdmFyIG1lc3NhZ2VFbGVtZW50ID0gZG9jdW1lbnQuY3JlYXRlRWxlbWVudCgncCcp OwogICAgbWVzc2FnZUVsZW1lbnQuYXBwZW5kQ2hpbGQoZG9jdW1lbnQuY3JlYXRlVGV4dE5vZGUo bWVzc2FnZSkpOwogICAgZG9jdW1lbnQuZ2V0RWxlbWVudEJ5SWQoJ2xvZycpLmFwcGVuZENoaWxk KG1lc3NhZ2VFbGVtZW50KTsKfQoKZnVuY3Rpb24gaW5pdGlhbGl6ZSgpCnsKICAgIHZhciBzdGFy dCA9ICtuZXcgRGF0ZSgpOwoKICAgIHZhciBjb250YWluZXIgPSBkb2N1bWVudC5jcmVhdGVFbGVt ZW50KCdkaXYnKTsKICAgIGZvciAodmFyIGkgPSAwOyBpIDwgMjAwMDA7ICsraSkgewogICAgICAg IHZhciBzcGFuID0gZG9jdW1lbnQuY3JlYXRlRWxlbWVudCgnc3BhbicpOwogICAgICAgIHNwYW4u Y2xhc3NOYW1lID0gInRlc3QiOwogICAgICAgIGNvbnRhaW5lci5hcHBlbmRDaGlsZChzcGFuKTsK ICAgIH0KICAgIGRvY3VtZW50LmJvZHkuYXBwZW5kQ2hpbGQoY29udGFpbmVyKTsKCiAgICBsb2co J0NyZWF0aW5nIGVsZW1lbnRzIHRvb2sgJyArICgrKG5ldyBEYXRlKCkpIC0gc3RhcnQpICsgJ21z Jyk7CgogICAgc2V0VGltZW91dChydW5UZXN0LCAxMDApOwogICAgbG9nKCdUZXN0aW5nIGl0ZXJh dGlvbiBvZiBOb2RlTGlzdCwgcGxlYXNlIHdhaXTigKYnKTsKfQoKZnVuY3Rpb24gcnVuVGVzdCgp CnsKICAgIHZhciBzdGFydCA9ICtuZXcgRGF0ZSgpOwoKICAgIHZhciBub2RlTGlzdCA9IGRvY3Vt ZW50LmdldEVsZW1lbnRzQnlDbGFzc05hbWUoInRlc3QiKTsKICAgIGZvciAodmFyIGkgPSAwLCBj b3VudCA9IG5vZGVMaXN0Lmxlbmd0aDsgaSA8IGNvdW50OyArK2kpIHsKICAgICAgICB2YXIgZWxl bWVudCA9IG5vZGVMaXN0W2ldOwogICAgICAgIGVsZW1lbnQuc2V0QXR0cmlidXRlKCduYW1lJywg InRlc3QiKTsKICAgIH0KCiAgICBsb2coJ0l0ZXJhdGluZyBhbmQgc2V0dGluZyB0aGVpciBzdHls ZSB0byBkaXNwbGF5Om5vbmUgdG9vayAnICsgKCsobmV3IERhdGUoKSkgLSBzdGFydCkgKyAnbXMn KTsKfQoKICAgIGluaXRpYWxpemUoKTsKCiAgICA8L3NjcmlwdD4KPC9ib2R5Pg==