Bug 220145 – [Win][DumpRenderTree] Some JS tests are timing out only in Debug builds since r269157

• Component: WebKit Misc.
• Status: RESOLVED FIXED

[Fujii Hironori]

[WinCairo] Some JS tests are timing out only in Debug builds

js/comparison-operators-greater.html
js/comparison-operators-less.html
js/comparison-operators.html
js/dfg-get-by-val-clobber.html
js/dfg-get-by-val-getter-cse.html
js/dfg-inline-arguments-out-of-bounds.html
js/dfg-inline-many-blocks.html
js/dfg-inlining-reg-alloc.html
js/dfg-integer-optimization.html
js/dfg-resolve-global-polymorphic-non-dictionary.html
js/dfg-string-stricteq.html
js/dfg-weak-js-constant-silent-fill.html
js/dom/dfg-put-by-id-reallocate-storage-polymorphic.html
js/dom/dfg-put-by-id-reallocate-storage.html
js/dom/reserved-words-as-property.html
js/dom/toInt32UInt32.html
js/integer-division-neg2tothe32-by-neg1.html
js/math-transforms.html

r269150 (3749) Good
r269175 (3752) Bad

https://build.webkit.org/results/WinCairo-64-bit-WKL-Debug-Tests/r269150%20%283749%29/results.html
https://build.webkit.org/results/WinCairo-64-bit-WKL-Debug-Tests/r269175%20%283752%29/results.html

https://trac.webkit.org/log/webkit/?action=stop_on_copy&mode=stop_on_copy&rev=269175&stop_rev=269150&limit=100

[Fujii Hironori]

This issue is reproducible by invoking DumpRenderTree.exe manually.
DumpRenderTree.exe took 41 seconds, while WebKitTestRunner.exe took 4 seconds.

PS C:\home\webkit\gc> Measure-Command { .\WebKitBuild\Debug\bin64\DumpRenderTree.exe file:///C:/home/webkit/gc/LayoutTests/js/comparison-operators-greater.html }
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 41
Milliseconds      : 762
Ticks             : 417627073
TotalDays         : 0.000483364667824074
TotalHours        : 0.0116007520277778
TotalMinutes      : 0.696045121666667
TotalSeconds      : 41.7627073
TotalMilliseconds : 41762.7073
PS C:\home\webkit\gc> Measure-Command { .\WebKitBuild\Debug\bin64\WebKitTestRunner.exe file:///C:/home/webkit/gc/LayoutTests/js/comparison-operators-greater.html }
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 4
Milliseconds      : 813
Ticks             : 48136172
TotalDays         : 5.5713162037037E-05
TotalHours        : 0.00133711588888889
TotalMinutes      : 0.0802269533333333
TotalSeconds      : 4.8136172
TotalMilliseconds : 4813.6172
PS C:\home\webkit\gc>

[Fujii Hironori]

Here is the callstack of DumpRenderTree.exe after it outputs a test result.

> WebKit.dll!WebCore::Style::BuilderState::applyPropertyToVisitedLinkStyle() Line 82	C++
> WebKit.dll!WebCore::Style::Builder::applyProperty(WebCore::CSSPropertyID id, WebCore::CSSValue & value, WebCore::SelectorChecker::LinkMatchMask linkMatchMask) Line 331	C++
> WebKit.dll!WebCore::Style::Builder::applyCascadeProperty::__l2::<lambda>(WebCore::SelectorChecker::LinkMatchMask linkMatch) Line 253	C++
> WebKit.dll!WebCore::Style::Builder::applyCascadeProperty(const WebCore::Style::PropertyCascade::Property & property) Line 258	C++
> WebKit.dll!WebCore::Style::Builder::applyPropertiesImpl<1>(int firstProperty, int lastProperty) Line 176	C++
> WebKit.dll!WebCore::Style::Builder::applyProperties(int firstProperty, int lastProperty) Line 143	C++
> WebKit.dll!WebCore::Style::Builder::applyHighPriorityProperties() Line 110	C++
> WebKit.dll!WebCore::Style::Resolver::applyMatchedProperties(WebCore::Style::Resolver::State & state, const WebCore::Style::MatchResult & matchResult, WebCore::Style::Resolver::UseMatchedDeclarationsCache useMatchedDeclarationsCache) Line 548	C++
> WebKit.dll!WebCore::Style::Resolver::applyMatchedProperties(WebCore::Style::Resolver::State & state, const WebCore::Style::MatchResult & matchResult, WebCore::Style::Resolver::UseMatchedDeclarationsCache useMatchedDeclarationsCache) Line 551	C++
> WebKit.dll!WebCore::Style::Resolver::styleForElement(const WebCore::Element & element, const WebCore::RenderStyle * parentStyle, const WebCore::RenderStyle * parentBoxStyle, WebCore::RuleMatchingBehavior matchingBehavior, const WebCore::SelectorFilter * selectorFilter) Line 243	C++
> WebKit.dll!WebCore::Style::TreeResolver::styleForStyleable(const WebCore::Styleable & styleable, const WebCore::RenderStyle & inheritedStyle) Line 149	C++
> WebKit.dll!WebCore::Style::TreeResolver::resolveElement(WebCore::Element & element) Line 214	C++
> WebKit.dll!WebCore::Style::TreeResolver::resolveComposedTree() Line 552	C++
> WebKit.dll!WebCore::Style::TreeResolver::resolve() Line 610	C++
> WebKit.dll!WebCore::Document::resolveStyle(WebCore::Document::ResolveStyleType type) Line 2035	C++
> WebKit.dll!WebFrame::invalidate() Line 1112	C++
> WebKit.dll!WebView::notifyPreferencesChanged(IWebNotification * notification) Line 5568	C++
> WebKit.dll!WebView::onNotify(IWebNotification * notification) Line 5108	C++
> WebKit.dll!WebNotificationCenter::postNotificationInternal(IWebNotification * notification, wchar_t * notificationName, IUnknown * anObject) Line 132	C++
> WebKit.dll!WebNotificationCenter::postNotificationName(wchar_t * notificationName, IUnknown * anObject, IPropertyBag * userInfo) Line 182	C++
> WebKit.dll!WebPreferences::postPreferencesChangesNotification() Line 155	C++
> WebKit.dll!WebPreferences::setBoolPreferenceForTesting(wchar_t * key, int value) Line 2346	C++
> DumpRenderTreeLib.dll!setWebPreferencesForTestOptions(IWebPreferences * preferences, const WTR::TestOptions & options) Line 944	C++
> DumpRenderTreeLib.dll!resetWebViewToConsistentStateBeforeTesting(const WTR::TestOptions & options) Line 1051	C++
> DumpRenderTreeLib.dll!runTest(const std::string & inputLine) Line 1333	C++
> DumpRenderTreeLib.dll!main(int argc, const char * * argv) Line 1668	C++
> DumpRenderTreeLib.dll!dllLauncherEntryPoint(int argc, const char * * argv) Line 1704	C++
> DumpRenderTree.exe!main(int argc, const char * * argv) Line 222	C++
> [Inline Frame] DumpRenderTree.exe!invoke_main() Line 78	C++
> DumpRenderTree.exe!__scrt_common_main_seh() Line 288	C++
> kernel32.dll!00007fffd5997c24()	Unknown
> ntdll.dll!00007fffd6d4d4d1()	Unknown

It is running Document::resolveStyle under resetWebViewToConsistentStateBeforeTesting !?

[Fujii Hironori]

r269157 seems the culprit.
Bug 218291 – [Testing] Remove requirement of adding new SPI for each preference that needs testing (WebKitLegacy Windows)

[Fujii Hironori]

Hi Sam and Brent,

Calling postPreferencesChangesNotification for every preference is costy.
Do you have a idea?

[Fujii Hironori]

There are two ways to solve it.

1. Don't call postPreferencesChangesNotification for every preference
2. Call resetWebViewToConsistentStateBeforeTesting after loading about:blank

Any other else? I'm going to submit my proposed patch for #2.

[Sam Weinig]

(In reply to Fujii Hironori from comment #5)
> There are two ways to solve it.
> 
> 1. Don't call postPreferencesChangesNotification for every preference
> 2. Call resetWebViewToConsistentStateBeforeTesting after loading about:blank
> 
> Any other else? I'm going to submit my proposed patch for #2.

Is this a regression? What changed to make this happen and why does this only effect some JS tests?

[Fujii Hironori]

(In reply to Sam Weinig from comment #6)
> (In reply to Fujii Hironori from comment #5)
> > There are two ways to solve it.
> > 
> > 1. Don't call postPreferencesChangesNotification for every preference
> > 2. Call resetWebViewToConsistentStateBeforeTesting after loading about:blank
> > 
> > Any other else? I'm going to submit my proposed patch for #2.
> 
> Is this a regression? What changed to make this happen and why does this
> only effect some JS tests?

Yes. Those JS test cases are generating large pages. It take long time to do resolveStyle.

[Fujii Hironori]

Created attachment 416760 [details]
Patch

[Sam Weinig]

Ok, I think I see what the regression is, and I don't think this is the right fix.

The issue is that the old, function based preference setting goes through WebPreferences::setBoolValue() (or whatever specific type is being used) and WebPreferences::setBoolValue() does an early return if the preference is not going to change:

void WebPreferences::setBoolValue(const char* key, BOOL value)
{
    if (boolValueForKey(key) == value)
        return;


and therefore does not call postPreferencesChangesNotification() if the preference doesn't change.

We should have mimic'd that for WebPreferences::setBoolPreferenceForTesting() but instead, we unconditionally call postPreferencesChangesNotification(), which is wrong.

We should update the new functions to early return. Something like this:

HRESULT WebPreferences::setBoolPreferenceForTesting(_In_ BSTR key, _In_ BOOL value)
{
    if (!SysStringLen(key))
        return E_FAIL;

#if USE(CF)
    auto keyString = String(key).createCFString();
    if (booleanValueForPreferencesValue(valueForKey(keyString.get()).get()) == value)
        return S_OK;
    setValueForKey(keyString.get(), value ? kCFBooleanTrue : kCFBooleanFalse);
#endif

    postPreferencesChangesNotification();

    return S_OK;
}

Your change seems ok as well, but it would be better to fix the actual issue here.

[Radar WebKit Bug Importer]

<rdar://problem/72756207>

[Fujii Hironori]

Created attachment 416891 [details]
Patch

[EWS]

Committed r271122: <https://trac.webkit.org/changeset/271122>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 416891 [details].