Bug 173584 – Speedometer 2.0 Inferno test spends a lot of time updating layout while focusing an element

• Status: RESOLVED
• Resolution: CONFIGURATION CHANGED
• Component: Layout and Rendering

[Yusuke Suzuki]

Looking the sampling profiler result of Speedometer 2.0, I found that super large part of Inferno test just executes focus() function in deleting test(sync delete test).
https://perf.webkit.org/v3/#/charts?since=1496638276950&paneList=((18-895))

And it seems that focus() in this test repeatedly falls into frame->layout().

[Ryosuke Niwa]

Do you have the stack trace?

[Yusuke Suzuki]

(In reply to Ryosuke Niwa from comment #1)
> Do you have the stack trace?

Here is the C++ stack trace. JS focus() call falls into RenderView::layout().
This happens super frequently in Inferno Sync Delete test, which occupies large part of the execution time.

* thread #1, queue = 'com.apple.main-thread', stop reason = step in
  * frame #0: 0x0000000106842f50 WebCore`WebCore::RenderView::layout(this=0x000000011e9b2340) at RenderView.cpp:340
    frame #1: 0x0000000104e8d9e4 WebCore`WebCore::FrameView::layout(this=0x000000011e9f4900, allowSubtree=true) at FrameView.cpp:1491
    frame #2: 0x0000000104a9590c WebCore`WebCore::Document::updateLayout(this=0x000000013be7c000) at Document.cpp:1937
    frame #3: 0x0000000104a9a44e WebCore`WebCore::Document::updateLayoutIgnorePendingStylesheets(this=0x000000013be7c000, runPostLayoutTasks=Asynchronously) at Document.cpp:1951
    frame #4: 0x0000000104c3fdde WebCore`WebCore::Element::focus(this=0x0000000145464380, restorePreviousSelection=true, direction=FocusDirectionNone) at Element.cpp:2384
    frame #5: 0x00000001058b12d8 WebCore`WebCore::jsHTMLElementPrototypeFunctionFocusBody(state=0x00007fff5fbf8250, castedThis=0x000000013c76ece0, throwScope=0x00007fff5fbf81d8) at JSHTMLElement.cpp:3122
    frame #6: 0x00000001058ab2de WebCore`long long WebCore::IDLOperation<WebCore::JSHTMLElement>::call<&(state=0x00007fff5fbf8250, operationName="focus")), (WebCore::CastedThisErrorBehavior)0>(JSC::ExecState&, char const*) at JSDOMOperation.h:53
    frame #7: 0x00000001058ab06c WebCore`WebCore::jsHTMLElementPrototypeFunctionFocus(state=0x00007fff5fbf8250) at JSHTMLElement.cpp:3128
    frame #8: 0x00003eb19a001028
    frame #9: 0x00003eb19a080fdc
    frame #10: 0x00003eb19a10f589
    frame #11: 0x00003eb19a044634
    frame #12: 0x00003eb19a0f46c0
    frame #13: 0x00003eb19a07ced7
    frame #14: 0x00003eb19a10f4dd
    frame #15: 0x00003eb19a0e55a8
    frame #16: 0x00003eb19a0f46c0
    frame #17: 0x00003eb19a07ced7
    frame #18: 0x00003eb19a10f4dd
    frame #19: 0x00003eb19a0e55a8
    frame #20: 0x00003eb19a0f46c0
    frame #21: 0x00003eb19a07ced7
    frame #22: 0x00003eb19a10f4dd
    frame #23: 0x00003eb19a0d3aff
    frame #24: 0x00003eb19a104d60
    frame #25: 0x00003eb19a101f2f
    frame #26: 0x00003eb19a0cb599
    frame #27: 0x00003eb19a0fb041
    frame #28: 0x000000011151b4ae JavaScriptCore`vmEntryToJavaScript at LowLevelInterpreter64.asm:254
    frame #29: 0x00000001112e453e JavaScriptCore`JSC::JITCode::execute(this=0x000000011b5c58e8, vm=0x0000000123600000, protoCallFrame=0x00007fff5fbf9ae8) at JITCode.cpp:81
    frame #30: 0x0000000111294635 JavaScriptCore`JSC::Interpreter::executeCall(this=0x000000011b5d0100, callFrame=0x00000001237de088, function=0x000000013c07faf0, callType=JS, callData=0x00007fff5fbfa100, thisValue=JSValue @ 0x00007fff5fbf9c00, args=0x00007fff5fbf9fe8) at Interpreter.cpp:971
    frame #31: 0x0000000110a35f68 JavaScriptCore`JSC::call(exec=0x00000001237de088, functionObject=JSValue @ 0x00007fff5fbf9c80, callType=JS, callData=0x00007fff5fbfa100, thisValue=JSValue @ 0x00007fff5fbf9c78, args=0x00007fff5fbf9fe8) at CallData.cpp:40
    frame #32: 0x0000000110a36079 JavaScriptCore`JSC::call(exec=0x00000001237de088, functionObject=JSValue @ 0x00007fff5fbf9d70, callType=JS, callData=0x00007fff5fbfa100, thisValue=JSValue @ 0x00007fff5fbf9d68, args=0x00007fff5fbf9fe8, returnedException=0x00007fff5fbfa010) at CallData.cpp:47
    frame #33: 0x0000000110a3630d JavaScriptCore`JSC::profiledCall(exec=0x00000001237de088, reason=Other, functionObject=JSValue @ 0x00007fff5fbf9e00, callType=JS, callData=0x00007fff5fbfa100, thisValue=JSValue @ 0x00007fff5fbf9df8, args=0x00007fff5fbf9fe8, returnedException=0x00007fff5fbfa010) at CallData.cpp:66
    frame #34: 0x00000001055019cb WebCore`WebCore::JSMainThreadExecState::profiledCall(exec=0x00000001237de088, reason=Other, functionObject=JSValue @ 0x00007fff5fbf9e90, callType=JS, callData=0x00007fff5fbfa100, thisValue=JSValue @ 0x00007fff5fbf9e88, args=0x00007fff5fbf9fe8, returnedException=0x00007fff5fbfa010) at JSMainThreadExecState.h:72
    frame #35: 0x00000001057d7c29 WebCore`WebCore::JSEventListener::handleEvent(this=0x000000012c05aee0, scriptExecutionContext=0x000000013be7c000, event=0x000000013ba82320) at JSEventListener.cpp:155
    frame #36: 0x0000000104c9d526 WebCore`WebCore::EventTarget::fireEventListeners(this=0x000000013be7c000, event=0x000000013ba82320, listeners=WebCore::EventListenerVector @ 0x00007fff5fbfa308) at EventTarget.cpp:264
    frame #37: 0x0000000104c9d0ee WebCore`WebCore::EventTarget::fireEventListeners(this=0x000000013be7c000, event=0x000000013ba82320) at EventTarget.cpp:209
    frame #38: 0x0000000106350411 WebCore`WebCore::Node::handleLocalEvents(this=0x000000013be7c000, event=0x000000013ba82320) at Node.cpp:2368
    frame #39: 0x0000000104c6deab WebCore`WebCore::EventContext::handleLocalEvents(this=0x000000012c066a50, event=0x000000013ba82320) const at EventContext.cpp:54
    frame #40: 0x0000000104c6e17a WebCore`WebCore::MouseOrFocusEventContext::handleLocalEvents(this=0x000000012c066a50, event=0x000000013ba82320) const at EventContext.cpp:85
    frame #41: 0x0000000104c6eba8 WebCore`WebCore::dispatchEventInDOM(event=0x000000013ba82320, path=0x00007fff5fbfa508) at EventDispatcher.cpp:104
    frame #42: 0x0000000104c6e647 WebCore`WebCore::EventDispatcher::dispatchEvent(node=0x000000013c1c9540, event=0x000000013ba82320) at EventDispatcher.cpp:162
    frame #43: 0x0000000106a9a6b7 WebCore`WebCore::simulateMouseEvent(eventType=0x000000011b56a150, element=0x000000013c1c9540, underlyingEvent=0x0000000000000000, source=Bindings) at SimulatedClick.cpp:84
    frame #44: 0x0000000106a9a5b4 WebCore`WebCore::simulateClick(element=0x000000013c1c9540, underlyingEvent=0x0000000000000000, mouseEventOptions=SendNoEvents, visualOptions=DoNotShowPressedLook, creationOptions=Bindings) at SimulatedClick.cpp:106
    frame #45: 0x000000010503d742 WebCore`WebCore::HTMLElement::click(this=0x000000013c1c9540) at HTMLElement.cpp:679
    frame #46: 0x00000001058b123a WebCore`WebCore::jsHTMLElementPrototypeFunctionClickBody(state=0x00007fff5fbfa890, castedThis=0x000000013c0a5f40, throwScope=0x00007fff5fbfa818) at JSHTMLElement.cpp:3108
    frame #47: 0x00000001058ab02e WebCore`long long WebCore::IDLOperation<WebCore::JSHTMLElement>::call<&(state=0x00007fff5fbfa890, operationName="click")), (WebCore::CastedThisErrorBehavior)0>(JSC::ExecState&, char const*) at JSDOMOperation.h:53
    frame #48: 0x00000001058aadbc WebCore`WebCore::jsHTMLElementPrototypeFunctionClick(state=0x00007fff5fbfa890) at JSHTMLElement.cpp:3114
    frame #49: 0x00003eb19a001028
    frame #50: 0x0000000111522e02 JavaScriptCore`llint_entry at LowLevelInterpreter.asm:795
    frame #51: 0x0000000111522e02 JavaScriptCore`llint_entry at LowLevelInterpreter.asm:795
    frame #52: 0x0000000111522e02 JavaScriptCore`llint_entry at LowLevelInterpreter.asm:795
    frame #53: 0x000000011151b4ae JavaScriptCore`vmEntryToJavaScript at LowLevelInterpreter64.asm:254
    frame #54: 0x00000001112e453e JavaScriptCore`JSC::JITCode::execute(this=0x000000012c066848, vm=0x0000000123600000, protoCallFrame=0x00007fff5fbfac18) at JITCode.cpp:81
    frame #55: 0x0000000111294635 JavaScriptCore`JSC::Interpreter::executeCall(this=0x000000011b5d0100, callFrame=0x00000001237df058, function=0x000000013c07ff40, callType=JS, callData=0x00007fff5fbfb138, thisValue=JSValue @ 0x00007fff5fbfad30, args=0x00007fff5fbfb070) at Interpreter.cpp:971
    frame #56: 0x0000000110a35f68 JavaScriptCore`JSC::call(exec=0x00000001237df058, functionObject=JSValue @ 0x00007fff5fbfadb0, callType=JS, callData=0x00007fff5fbfb138, thisValue=JSValue @ 0x00007fff5fbfada8, args=0x00007fff5fbfb070) at CallData.cpp:40
    frame #57: 0x0000000110a36079 JavaScriptCore`JSC::call(exec=0x00000001237df058, functionObject=JSValue @ 0x00007fff5fbfaea0, callType=JS, callData=0x00007fff5fbfb138, thisValue=JSValue @ 0x00007fff5fbfae98, args=0x00007fff5fbfb070, returnedException=0x00007fff5fbfb090) at CallData.cpp:47
    frame #58: 0x0000000110a3630d JavaScriptCore`JSC::profiledCall(exec=0x00000001237df058, reason=Other, functionObject=JSValue @ 0x00007fff5fbfaf30, callType=JS, callData=0x00007fff5fbfb138, thisValue=JSValue @ 0x00007fff5fbfaf28, args=0x00007fff5fbfb070, returnedException=0x00007fff5fbfb090) at CallData.cpp:66
    frame #59: 0x00000001055019cb WebCore`WebCore::JSMainThreadExecState::profiledCall(exec=0x00000001237df058, reason=Other, functionObject=JSValue @ 0x00007fff5fbfafc0, callType=JS, callData=0x00007fff5fbfb138, thisValue=JSValue @ 0x00007fff5fbfafb8, args=0x00007fff5fbfb070, returnedException=0x00007fff5fbfb090) at JSMainThreadExecState.h:72
    frame #60: 0x00000001069217ca WebCore`WebCore::ScheduledAction::executeFunctionInContext(this=0x000000012c066730, globalObject=0x00000001237df010, thisValue=JSValue @ 0x00007fff5fbfb168, context=0x000000013be71000) at ScheduledAction.cpp:105
    frame #61: 0x00000001069213c1 WebCore`WebCore::ScheduledAction::execute(this=0x000000012c066730, document=0x000000013be71000) at ScheduledAction.cpp:126
    frame #62: 0x0000000106921283 WebCore`WebCore::ScheduledAction::execute(this=0x000000012c066730, context=0x000000013be71000) at ScheduledAction.cpp:79
    frame #63: 0x0000000104ba05f9 WebCore`WebCore::DOMTimer::fired(this=0x000000013c1c9888) at DOMTimer.cpp:368
    frame #64: 0x0000000106e19f80 WebCore`WebCore::ThreadTimers::sharedTimerFiredInternal(this=0x000000011b5a1e10) at ThreadTimers.cpp:118
    frame #65: 0x0000000106e1a6f1 WebCore`WebCore::ThreadTimers::setSharedTimer(this=0x000000011b57ff58)::$_0::operator()() const at ThreadTimers.cpp:70
    frame #66: 0x0000000106e1a6a9 WebCore`WTF::Function<void ()>::CallableWrapper<WebCore::ThreadTimers::setSharedTimer(this=0x000000011b57ff50)::$_0>::call() at Function.h:102
    frame #67: 0x00000001043a9a7e WebCore`WTF::Function<void ()>::operator(this=0x000000010826c5c0)() const at Function.h:56
    frame #68: 0x00000001060fd0f5 WebCore`WebCore::MainThreadSharedTimer::fired(this=0x000000010826c5b8) at MainThreadSharedTimer.cpp:52
    frame #69: 0x00000001060fd489 WebCore`WebCore::timerFired((null)=0x0000610000166c00, (null)=0x0000000000000000) at MainThreadSharedTimerCF.cpp:74
    frame #70: 0x00007fff98b9fe04 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__ + 20
    frame #71: 0x00007fff98b9fa93 CoreFoundation`__CFRunLoopDoTimer + 1075
    frame #72: 0x00007fff98b9f5ea CoreFoundation`__CFRunLoopDoTimers + 298
    frame #73: 0x00007fff98b96fc1 CoreFoundation`__CFRunLoopRun + 2081
    frame #74: 0x00007fff98b96544 CoreFoundation`CFRunLoopRunSpecific + 420
    frame #75: 0x00007fff980f6ebc HIToolbox`RunCurrentEventLoopInMode + 240
    frame #76: 0x00007fff980f6cf1 HIToolbox`ReceiveNextEventCommon + 432
    frame #77: 0x00007fff980f6b26 HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71
    frame #78: 0x00007fff9668fa54 AppKit`_DPSNextEvent + 1120
    frame #79: 0x00007fff96e0b7ee AppKit`-[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 2796
    frame #80: 0x00007fff966843db AppKit`-[NSApplication run] + 926
    frame #81: 0x00007fff9664ee0e AppKit`NSApplicationMain + 1237
    frame #82: 0x0000000100008f49 MiniBrowser`main(argc=5, argv=0x00007fff5fbfdd38) at main.m:32
    frame #83: 0x00007fffae8c4235 libdyld.dylib`start + 1
    frame #84: 0x00007fffae8c4235 libdyld.dylib`start + 1

[Yusuke Suzuki]

JS stack trace seems like this.

patchComponent() -> componentDidUpdate() -> focus().

[Yusuke Suzuki]

Created attachment 313817 [details]
JS stack trace screenshot

[Yusuke Suzuki]

For example, commenting out dist/bundle.js L3237 `return _this3.editor.focus()` changes the execution time from

Inferno-TodoMVC : DeletingItems : Sync: 1160.5999999999985 ms

to

Inferno-TodoMVC : DeletingItems : Sync: 403 ms

[Ryosuke Niwa]

Oh, focus() is called by JS. That's going to be a bit tricky because there's some logic in determining whether an element is focusable or not which involves the computation of the height.

[Radar WebKit Bug Importer]

<rdar://problem/36422933>

[Ryosuke Niwa]

This has been fixed.