1533328 - js::InitDateTimeState loads tzres.dll on the main thread during early startup

Status: RESOLVED FIXED

(Core :: JavaScript Engine, enhancement, P1)

Description

[Florian Quèze [:florian]]

See the main thread I/O markers in this profile: https://perfht.ml/2ERxoDN

Could this be done off main thread?

Comment 1

[André Bargull [:anba]]

It may be possible to delay the call to internalUpdateTimeZoneAdjustment in js::DateTimeInfo::DateTimeInfo, but that'll only make a difference if there are no other callers during startup which call localtime, tzset, or any other date/time function which ends up loading "tzres.dll" on Windows.
Is it possible to investigate if there are other callers during startup which end up in _tzset, common_localtime_s (both from "ucrtbase.dll"), ConvertTimeZoneMuiString or GetTimeZoneInformation (both from "KERNELBASE.dll")?

Comment 2

[Jason Orendorff [:jorendorff]]

Florian, this has fallen into the crack between components and is now stalled.

Any thoughts on comment 1? Does anyone have time to push this through? We should start iff we can finish...

Comment 3

[Florian Quèze [:florian]]

(In reply to André Bargull [:anba] from comment #1)

It may be possible to delay the call to internalUpdateTimeZoneAdjustment in js::DateTimeInfo::DateTimeInfo

Delaying would be a win if we can ensure this isn't called before first paint. If you delay it, I can cover this with a test to prevent regressions.

Ideally, we would delay it enough that another thread has time to do it before we first need it on the main thread.

Is it possible to investigate if there are other callers during startup which end up in _tzset, common_localtime_s (both from "ucrtbase.dll"), ConvertTimeZoneMuiString or GetTimeZoneInformation (both from "KERNELBASE.dll")?

Any idea about how to check this? Is it enough to just comment out the current call to common_localtime_s in internalUpdateTimeZoneAdjustment?

Comment 4

[Jason Orendorff [:jorendorff]]

(In reply to Florian Quèze [:florian] from comment #3)

Any idea about how to check this? Is it enough to just comment out the current call to common_localtime_s in internalUpdateTimeZoneAdjustment?

...and set breakpoints on all those functions. Yes; except that we also want to know, if we did defer this, would we be forced to do it during startup anyway? So also set breakpoints on each of DateTimeInfo's 4 public methods.

I could be wrong, so leaving the ni?anba flag set.

Comment 5

[Florian Quèze [:florian]]

(In reply to Jason Orendorff [:jorendorff] from comment #4)

(In reply to Florian Quèze [:florian] from comment #3)

Any idea about how to check this? Is it enough to just comment out the current call to common_localtime_s in internalUpdateTimeZoneAdjustment?

...and set breakpoints on all those functions.

I assumed I would capture another startup profile, so we would see if the tzres.dll file gets loaded or not.

Comment 6

[Jason Orendorff [:jorendorff]]

Yep, go for it.

Comment 7

[Florian Quèze [:florian]]

https://perfht.ml/2WFQ2pv nicely shows that all child processes do main thread I/O to access this file, and the Privileged Content process is blocked in this profile for 7.9s trying to open tzres.dll.mui, despite this file having already been accessed by the parent process and other child processes.

Comment 8

[Florian Quèze [:florian]]

If I return early in internalUpdateTimeZoneAdjustment, the next stack loading tzset.dll is:

XREMain::XRE_main(int, char** const, mozilla::BootstrapConfig const&) [xul.dll]
NS_InitXPCOM [xul.dll]
nsComponentManagerImpl::Init(void) [xul.dll]
nsLayoutModuleInitialize(void) [xul.dll]
nsLayoutStatics::Initialize(void) [xul.dll]
nsContentUtils::Init(void) [xul.dll]
mozilla::nsRFPService::GetOrCreate(void) [xul.dll]
mozilla::nsRFPService::Init(void) [xul.dll]
mozilla::nsRFPService::UpdateRFPPref(void) [xul.dll]
tzset [ucrtbase.dll]
tzset_nolock [ucrtbase.dll]
tzset_from_system_nolock [ucrtbase.dll]
GetTimeZoneInformation [KERNELBASE.dll]
ConvertTimeZoneMuiStrings [KERNELBASE.dll]
ConvertTimeZoneMuiString [KERNELBASE.dll]
LoadLibraryExW [KERNELBASE.dll]
BasepLoadLibraryAsDataFileInternal [KERNELBASE.dll]
CreateFileW [KERNELBASE.dll]

Comment 9

[Florian Quèze [:florian]]

And then:

XPCWrappedJS method call []
js::RunScript []
TelemetryStartup.prototype.observe [resource://gre/modules/TelemetryStartup.jsm:21:0]
annotateEnvironment [resource://gre/modules/TelemetryStartup.jsm:33:0]
js::RunScript []
get currentEnvironment [resource://gre/modules/TelemetryEnvironment.jsm:80:0]
getGlobal [resource://gre/modules/TelemetryEnvironment.jsm:72:0]
EnvironmentCache [resource://gre/modules/TelemetryEnvironment.jsm:912:0]
_getBuild [resource://gre/modules/TelemetryEnvironment.jsm:1387:0]
js::RunScript []
get [resource://gre/modules/XPCOMUtils.jsm:124:0]
js::RunScript []
XPCU_serviceLambda [resource://gre/modules/XPCOMUtils.jsm:213:0]
0x6fe639983d []
xpc::CIGSHelper [xul.dll]
nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) [xul.dll]
nsComponentManagerImpl::GetServiceLocked [xul.dll]
mozilla::xpcom::CreateInstanceImpl [xul.dll]
nsSystemInfo::Init(void) [xul.dll]
common_localtime_s<__int64> [ucrtbase.dll]
_tzset [ucrtbase.dll]
tzset_nolock [ucrtbase.dll]
tzset_from_system_nolock [ucrtbase.dll]
GetTimeZoneInformation [KERNELBASE.dll]
ConvertTimeZoneMuiStrings [KERNELBASE.dll]
ConvertTimeZoneMuiString [KERNELBASE.dll]
LoadLibraryExW [KERNELBASE.dll]
BasepLoadLibraryAsDataFileInternal [KERNELBASE.dll]
CreateFileW [KERNELBASE.dll]

Comment 10

[Florian Quèze [:florian]]

And then

XREMain::XRE_main []
XREMain::XRE_main(int, char** const, mozilla::BootstrapConfig const&) [xul.dll]
XREMain::XRE_mainRun(void) [xul.dll]
nsAppStartup::Run(void) [xul.dll]
nsAppShell::Run(void) [xul.dll]
nsBaseAppShell::Run(void) [xul.dll]
MessageLoop::Run(void) [xul.dll]
MessageLoop::RunHandler(void) [xul.dll]
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [xul.dll]
NS_ProcessNextEvent(nsIThread*, bool) [xul.dll]
nsThread::ProcessNextEvent(bool, bool*) [xul.dll]
nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal*, bool) [xul.dll]
nsAppShell::ProcessNextNativeEvent(bool) [xul.dll]
DispatchMessageWorker [user32.dll]
UserCallWinProcCheckWow(_ACTIVATION_CONTEXT *,__int64 (*)(tagWND *,unsigned int,unsigned __int64,__int64),HWND__ *,_WM_VALUE,unsigned __int64,__int64,void *,int) [user32.dll]
nsWindow::WindowProc(HWND__*, unsigned int, uint64_t, int64_t) [xul.dll]
CallWindowProcCrashProtected [xul.dll]
nsWindow::WindowProcInternal(HWND__*, unsigned int, uint64_t, int64_t) [xul.dll]
nsWindow::ProcessMessage(unsigned int, uint64_t&, int64_t&, int64_t*) [xul.dll]
nsWindow::DispatchPendingEvents(void) [xul.dll]
NS_ProcessPendingEvents(nsIThread*, unsigned int) [xul.dll]
nsThread::ProcessNextEvent(bool, bool*) [xul.dll]
nsOutputStreamReadyEvent::Run(void) [xul.dll]
nsInputStreamPump::OnInputStreamReady []
nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) [xul.dll]
nsInputStreamPump::OnStateStart []
nsInputStreamPump::OnStateStart(void) [xul.dll]
nsBaseChannel::OnStartRequest(nsIRequest*) [xul.dll]
XMLHttpRequestMainThread::OnStartRequest []
mozilla::dom::XMLHttpRequestMainThread::OnStartRequest(nsIRequest*) [xul.dll]
mozilla::dom::XMLDocument::StartDocumentLoad(char const*, nsIChannel*, nsILoadGroup*, nsISupports*, nsIStreamListener**, bool, nsIContentSink*) [xul.dll]
mozilla::dom::Document::StartDocumentLoad(char const*, nsIChannel*, nsILoadGroup*, nsISupports*, nsIStreamListener**, bool, nsIContentSink*) [xul.dll]
mozilla::dom::Document::RetrieveRelevantHeaders(nsIChannel*) [xul.dll]
mozilla::dom::GetFormattedTimeString [xul.dll]
PR_ExplodeTime [nss3.dll]
PR_LocalTimeParameters [nss3.dll]
common_localtime_s<__int64> [ucrtbase.dll]
_tzset [ucrtbase.dll]
tzset_nolock [ucrtbase.dll]
tzset_from_system_nolock [ucrtbase.dll]
GetTimeZoneInformation [KERNELBASE.dll]
ConvertTimeZoneMuiStrings [KERNELBASE.dll]
ConvertTimeZoneMuiString [KERNELBASE.dll]
LoadLibraryExW [KERNELBASE.dll]
BasepLoadLibraryAsDataFileInternal [KERNELBASE.dll]
CreateFileW [KERNELBASE.dll]

Comment 11

[Florian Quèze [:florian]]

And then a stack that's after we have painted the browser UI:

XREMain::XRE_main []
PCompositorBridge::Msg_DidComposite []
EventDispatcher::Dispatch []
EventDispatcher::Dispatch MozAfterPaint []
EventListener.handleEvent []
js::RunScript []
bound [self-hosted:974:0]
0x25f976299f []
js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) [xul.dll]
InternalCall [xul.dll]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [xul.dll]
js::RunScript []
_delayedStartup [chrome://browser/content/browser.js:1581:0]
js::RunScript(JSContext*, js::RunState&) [xul.dll]
Interpret [xul.dll]
InternalCall [xul.dll]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [xul.dll]
XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [xul.dll]
XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [xul.dll]
XPTC__InvokebyIndex [xul.dll]
nsObserverService::NotifyObservers browser-delayed-startup-finished []
nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [xul.dll]
nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [xul.dll]
SharedStub [xul.dll]
PrepareAndDispatch [xul.dll]
XPCWrappedJS method call []
nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) [xul.dll]
JS_CallFunctionValue(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [xul.dll]
js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) [xul.dll]
InternalCall [xul.dll]
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [xul.dll]
js::RunScript []
BG_observe [resource:///modules/BrowserGlue.jsm:734:0]
BG__onFirstWindowLoaded [resource:///modules/BrowserGlue.jsm:1291:0]
_checkForOldBuildUpdates [resource:///modules/BrowserGlue.jsm:1073:0]
js::RunScript(JSContext*, js::RunState&) [xul.dll]
Interpret [xul.dll]
InternalConstruct [xul.dll]
DateConstructor [xul.dll]
js::DateTimeInfo::getOrComputeValue(js::DateTimeInfo::RangeCache&, int64_t, int (js::DateTimeInfo::*)(int64_t)) [xul.dll]
js::DateTimeInfo::computeUTCOffsetMilliseconds(int64_t) [xul.dll]
js::ResyncICUDefaultTimeZone(void) [xul.dll]
icu_64::TimeZone::recreateDefault(void) [xul.dll]
icu_64::TimeZone::detectHostTimeZone(void) [xul.dll]
tzset [ucrtbase.dll]
tzset_nolock [ucrtbase.dll]
tzset_from_system_nolock [ucrtbase.dll]
GetTimeZoneInformation [KERNELBASE.dll]
ConvertTimeZoneMuiStrings [KERNELBASE.dll]
ConvertTimeZoneMuiString [KERNELBASE.dll]
LoadLibraryExW [KERNELBASE.dll]
BasepLoadLibraryAsDataFileInternal [KERNELBASE.dll]
CreateFileW [KERNELBASE.dll]

If we reach that point, I think we have won. Especially as delaying until the browser UI has been painted gives enough time for another thread to load tzres without blocking the main thread.

We already have bug 1363586 that covers the stack in comment 9. The stack in comment 10 is just silly (it makes no sense to generate HTTP headers to load a local file), and nsRFPService could probably be initialized lazily.

Comment 12

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 1: Avoid calling system time functions during start-up to avoid main-thread I/O. r=jorendorff!

• Changes DateTimeInfo::internalUpdateTimeZoneAdjustment to set a flag to
  request an update instead of directly calling the system time functions.
• DateTimeInfo functions which require a valid time zone have been modified to
  call the new acquireLockWithValidTimeZone helper.

Comment 13

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 2: Move ICU time zone state into js::DateTimeInfo. r=jorendorff!

This ensures the ICU time zone state is only resync'ed when an actual time zone
change was detected. Without this change the following script will resync the
ICU time zone state in each call to Intl.DateTimeFormat:

// js::DateTimeInfo is here in its initial state where no time zone info has
// been retrieved yet.

for (var i = 0; i < 10; ++i) {
  // Creating a new Realm triggers a time zone check. Because no time zone
  // info is yet available, a forced reset of the ICU time zone state is
  // requested.
  newGlobal();

  // The ICU time zone state was just resetted above, so this call will again
  // fetch the current system time zone.
  new Intl.DateTimeFormat();
}

Depends on D37247

Comment 14

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 3: Switch 'reset' and 'update' method names in js::DateTimeInfo. r=jorendorff!

That way js::ResetTimeZoneInternal is calling js::DateTimeInfo::resetTimeZoneAdjustment,
which aligns the use of 'reset' in the function names. And the method which actually checks
for updates is then called js::DateTimeInfo::updateTimeZoneAdjustment.

Depends on D37248

Comment 15

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 4: Only call ResetTimeZone resp. tzset when the time zone was actually changed. r=jorendorff!

Depends on D37250

Comment 16

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 5: Remove delay of ICU time zone updates. r=jorendorff!

Part 1 ensures DateTimeInfo::updateTimeZoneAdjustment() is no longer called during
start-up, which enables us to resync ICU's time zone status right away. Furthermore
this change won't lead to a performance regression, because all callers to
DateTimeInfo::updateTimeZoneAdjustment() either also require an up-to-date ICU time
zone state (DTI::{getDSTOffsetMilliseconds,getOffsetMilliseconds,timeZoneDisplayName})
or trigger an ICU time zone update anyway (DTI::localTZA() when called in
DateObject::fillLocalTimeSlots()).

Depends on D37251

Comment 17

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 6: Remove 'Adjustment' from DateTimeInfo methods and fields. r=jorendorff!

Give these functions and fields a more general name to make clear they aren't tied
to the localTZA_ field.

Depends on D41372

Comment 18

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 7: Remove separate 'localTZA_' field from DateTimeInfo. r=jorendorff!

This field used to match "LocalTZA" from the ECMAScript specification when "LocalTZA"
was still a constant value. But in the current specification "LocalTZA" was changed to
a function to compute the local time zone adjustment at a given time. To avoid
confusion between localTZA_ and "LocalTZA" from the specification, remove localTZA_
and instead only expose the DateTimeInfo::localTZA() function in contexts where the
old "LocalTZA" definition is still used (non-Intl or system ICU builds).

localTZA_ was also used as a cache key for DateObject slots, replace the usage there
with DateTimeInfo::utcToLocalStandardOffsetSeconds() to make clear that the cache key
isn't tied to any spec calls to "LocalTZA".

Depends on D41373

Comment 19

[André Bargull [:anba]]

Attachment: Bug 1533328 - Part 8: Add comments explaining when <ctime> and ICU can return a different default time zone. r=jorendorff!

Depends on D41375

Comment 20

[André Bargull [:anba]]

Try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ea54f3f5bf5241f0bad33dbf59820168ed8d8676
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ee6bd6994f8b61e9d7ed4511185f42685b181951

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d61d6575dc21
Part 1: Avoid calling system time functions during start-up to avoid main-thread I/O. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/275636ab59df
Part 2: Move ICU time zone state into js::DateTimeInfo. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/1ed14c6e13bf
Part 3: Switch 'reset' and 'update' method names in js::DateTimeInfo. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/cb85ccc7f07a
Part 4: Only call ResetTimeZone resp. tzset when the time zone was actually changed. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/892d6484ee49
Part 5: Remove delay of ICU time zone updates. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/a83290b48536
Part 6: Remove 'Adjustment' from DateTimeInfo methods and fields. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/3d58871ccc93
Part 7: Remove separate 'localTZA_' field from DateTimeInfo. r=jorendorff
https://hg.mozilla.org/integration/autoland/rev/9bf1bcfbd155
Part 8: Add comments explaining when <ctime> and ICU can return a different default time zone. r=jorendorff

Comment 22

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/d61d6575dc21
https://hg.mozilla.org/mozilla-central/rev/275636ab59df
https://hg.mozilla.org/mozilla-central/rev/1ed14c6e13bf
https://hg.mozilla.org/mozilla-central/rev/cb85ccc7f07a
https://hg.mozilla.org/mozilla-central/rev/892d6484ee49
https://hg.mozilla.org/mozilla-central/rev/a83290b48536
https://hg.mozilla.org/mozilla-central/rev/3d58871ccc93
https://hg.mozilla.org/mozilla-central/rev/9bf1bcfbd155