1843534 - clock_gettime() etc are very slow on some android devices

Status: RESOLVED FIXED

(Core :: Performance, defect)

Description

[Jamie Nicol [:jnicol]]

https://share.firefox.dev/3PPYuRI

This shows up a lot in a speedometer (around 4%), and skews comparisons with Chrome as both browsers take timestamps in different places, though appear to be similarly affected overall.

This occurs on several devices I have tested including the Samsung A51, Samsung S9, Pixel 5, OnePlus 8 Pro. On other devices (including Pixel 4, PIxel 6, Samsung S10) this barely shows up in profiles if at all. This isn't a exynos vs snapdragon type thing. Additionally, naively checking the kernel version doesn't show a pattern: if this was broken then fixed in specific versions then perhaps vendor specific backports muddy the water.

It appears that the VDSO fast path is failing for some reason and we end up doing a syscall. I'm trying to get kernel symbols included in the profile to see if that sheds any light on why.

We may need to audit our usage of timestamps on the critical path.

Comment 1

[Jamie Nicol [:jnicol]]

I think I've figured out why this is slow, on the A51 at least.

The code I'm linking to below is from the 4.14 branch of the android common kernel. The actual kernel used on the device will differ but hopefully the relevant bits are still the same.

See ARM64_ERRATUM_858921, which affects Cortex-A73 CPUs (which the Samsung A51 has). Presumably this workaround is therefore enabled.

We can see here this creates a arch_timer_erratum_workaround instance with the read_cntvct_el0 field set.

We can then see here that if that field is set, we set clocksource_counter.archdata.vdso_direct to false.

Then in update_vsyscall(), which is where the kernel writes its time data to the vdso data page, if archdata.vdso_direct is false then it sets vdso_data.use_syscall to true.

Then finally, see the actual clock_gettime() implementation in the vdso. This uses the syscall_check macro, which reads the value of vdso_data.use_syscall and branches to the syscall fallback if it's set.

Comment 2

[Jamie Nicol [:jnicol]]

CLOCK_MONOTONIC_COARSE is unaffected by this issue, it stays in the VDSO fast path. So at the very least we can add an implementation of TimeStamp::NowLowRes() using this.

Additionally we can then audit our existing usage of timestamps, and see if there's any we can either remove or switch to low resolution.

Comment 3

[Jamie Nicol [:jnicol]]

The Pixel 5 family is also affected via the same mechanism, but due to a different CPU erratum, which affects Cortex A76 and Kyro 4G (of which the pixel 5 has the latter core).

While the pixel 6 family has a Cortex A76, it is not affected due to this commit which restricts that workaround to AArch32 mode.

There are other affected devices too with different CPUs, and sometimes 2 devices may have the same CPU and kernel version but one is affected and one is not. But I'm confident enough that this is our cause, and will chaulk that up to vendors cherry-picking different patches on to their kernels.

Comment 4

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Implement TimeStamp::NowLoRes() when CLOCK_MONOTONIC_COARSE is supported. r?glandium

We have discovered that clock_gettime(CLOCK_MONOTONIC) can be slow on
certain arm64 devices due to kernel workarounds for CPU errata
avoiding the VDSO fast-path. Using CLOCK_MONOTONIC_COARSE is
unnaffected by these issues. This patch adds an implementation of
TimeStamp::NowLoRes() using the coarse clock, meaning that when lower
precision timestamps are adequate we do not pay the penalty of hitting
the slow path.

Comment 5

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Avoid measuring protect time when write-protection is disabled. r?jandem

On certain devices we have seen that taking frequent timestamps can be
expensive. Currently we measure the time taken to write protect JIT
code, and as this is a hot path we see these timestamps show up in
profiles. However, since bug 1835876 we no longer write protect code
in content processes. This patch therefore avoids measuring the time
when write protection is disabled.

Depends on D185004

Comment 6

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Use low resolution timestamp for GC timeouts. r?jonco

On certain devices we have seen that taking frequent high-resolution
timestamps can be expensive, therefore it makes sense to use
low-resolution timestamps instead where possible.

js::Nursery::isUnderused() and CCGCScheduler::MaybePokeCC() check for
timeouts of > 1 second, therefore the low resolution timer is more
than adequate.

Depends on D185005

Comment 7

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Remove unused telemetry probes. r?#layout-reviewers!,#xpcom-reviewers!

On certain devices we have seen that taking frequent timestamps can be
expensive, therefore it makes sense to reduce the number of timestamps
taken in hot paths. Measuring the time taken in refresh driver phases
and in NotifyObservers() shows up in profiles. However, these values
are only used to report to telemetry and we do not actually collect
this telemetry on Android. This patch therefore avoids measuring these
durations on Android.

Depends on D185006

Comment 8

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Avoid taking unnecessary timestamps when thread is not being profiled for markers. r?mstange

As taking timestamps can be expensive on certain devices we should try
to avoid taking them where possible. This patch fixes a few occasions
where we take a timestamp solely for a profiler marker even when the
current thread is not being profiled.

Depends on D185007

Comment 9

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Use single timestamp in HttpChannelChild::OnStopRequest(). r?#necko-reviewers

On certain devices we have seen that taking frequent timestamps can be
expensive, therefore it makes sense to reduce the number of timestamps
taken in hot paths. HttpChannelChild::OnStopRequest() currently takes
multiple timestamps (for profiler markers and telemetry measurements)
without performing meaningful work in between. This patch replaces
these with a single timestamp used multiple times.

Depends on D185008

Comment 10

[Jamie Nicol [:jnicol]]

Attachment: Bug 1843534 - Avoid unnecessary timestamp in nsTimerImpl::Fire if logging is disabled. r?#xpcom-reviewers

On certain devices we have seen that taking frequent timestamps can be
expensive, therefore it makes sense to reduce the number of timestamps
taken in hot paths. nsTimerImpl::Fire() currently takes a timestamp
which only gets used in logging. This patch therefore makes it so the
timestamp is only taken when logging is enabled.

Depends on D185009

Comment 11

[Emilio Cobos Álvarez (:emilio)]

Attachment: Bug 1843534 - Ensure profiler_add_marker arguments are not evaluated when not profiled. r=canaltinova,aabh

This is a more generic version of D185008.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/dfac5b1681a1
Implement TimeStamp::NowLoRes() when CLOCK_MONOTONIC_COARSE is supported. r=glandium
https://hg.mozilla.org/integration/autoland/rev/e1cf0b9086ba
Avoid measuring protect time when write-protection is disabled. r=jandem
https://hg.mozilla.org/integration/autoland/rev/cf8e2772f907
Use low resolution timestamp for GC timeouts. r=jonco,smaug
https://hg.mozilla.org/integration/autoland/rev/65677e6aa05d
Remove unused telemetry probes. r=emilio
https://hg.mozilla.org/integration/autoland/rev/01be17916dd3
Avoid taking unnecessary timestamps when thread is not being profiled for markers. r=julienw
https://hg.mozilla.org/integration/autoland/rev/e03410fcc17d
Use single timestamp in HttpChannelChild::OnStopRequest(). r=necko-reviewers,kershaw,jesup,acreskey
https://hg.mozilla.org/integration/autoland/rev/7b7e075d34e7
Avoid unnecessary timestamp in nsTimerImpl::Fire if logging is disabled. r=xpcom-reviewers,nika

Comment 13

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/dfac5b1681a1
https://hg.mozilla.org/mozilla-central/rev/e1cf0b9086ba
https://hg.mozilla.org/mozilla-central/rev/cf8e2772f907
https://hg.mozilla.org/mozilla-central/rev/65677e6aa05d
https://hg.mozilla.org/mozilla-central/rev/01be17916dd3
https://hg.mozilla.org/mozilla-central/rev/e03410fcc17d
https://hg.mozilla.org/mozilla-central/rev/7b7e075d34e7

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ccf1b5218169
Ensure profiler_add_marker arguments are not evaluated when not profiled. r=jnicol,canaltinova

Comment 15

[Narcis Beleuzu [:NarcisB]]

Backed out for bustages on ProfilerMarkers.h

Backout link: https://hg.mozilla.org/integration/autoland/rev/df7fb7f4fde75763265536c8098274ee9d22677d
Log link: https://treeherder.mozilla.org/logviewer?job_id=425518473&repo=autoland&lineNumber=27635

Comment 16

[Jamie Nicol [:jnicol]]

redirecting ni to emilio

Comment 17

[Phabricator Automation]

Comment on attachment 9348145 [details]
Bug 1843534 - Ensure profiler_add_marker arguments are not evaluated when not profiled. r=canaltinova,aabh

Revision D185800 was moved to bug 1848130. Setting attachment 9348145 [details] to obsolete.

Comment 18

[Emilio Cobos Álvarez (:emilio)]

Let me move that to a separate bug to ease tracking.

Comment 19

[Daniel Holbert [:dholbert]]

Note, I'm going to request ESR115 uplift one particular patch on this bug, https://phabricator.services.mozilla.com/D185007 in particular, since it's just a code-removal and it makes the ESR uplifts in bug 1861259 apply more cleanly.

(I'm using moz-phab to request uplift of just that one patch; I think that'll result in a new ESR-bound phabricator revision here. Apologies if anything goes haywire, as the new uplift-approval process is quite new.)

Comment 20

[Daniel Holbert [:dholbert]]

Attachment: Bug 1843534 - Remove unused telemetry probes.

These telemetry probes have long since expired, so remove them. This
avoids taking unnecessary timestamps in these functions, which we have
seen can be expensive on certain devices.

Original Revision: https://phabricator.services.mozilla.com/D185007

Comment 21

[Phabricator Automation]

Uplift Approval Request

• Steps to reproduce for manual QE testing: N/A
• Is Android affected?: yes
• String changes made/needed: None
• Code covered by automated testing: yes
• User impact if declined: None, but it makes uplift in bug 1861259 more awkward/human-error-prone
• Explanation of risk level: This is just removing code for an unused telemetry probe.
• Risk associated with taking this patch: Essentially zero.
• Fix verified in Nightly: yes
• Needs manual QE test: no

Comment 22

[Dianna Smith [:diannaS]]

Comment on attachment 9360719 [details]
Bug 1843534 - Remove unused telemetry probes.

Approved for 115.5esr

Comment 23

[Pulsebot]

https://hg.mozilla.org/releases/mozilla-esr115/rev/cb731d48619e

Comment 24

[Mathew Hodson]

I don't think it's correct to say that this bug is fixed in ESR 115. Only one patch was uplifted that doesn't affect behaviour.