Page MenuHomePhabricator

Use php-hrtime monotonic clock instead of microtime for perf measure in MW
Open, MediumPublic

Description

Problem

We currently use microtime(true) quite a lot. This internally uses gettimeofday() in C, which isn't monotonic and subject to clock drift etc.

Impact

The metrics we collect for WANObjectCache, ResourceLoader, Backend Save Timing etc. are all affected by this and thus cannot be trusted. Their mean average might give a rough sense of how long something takes under "boring" circumstances, but it's not a useful way to set alerts because we can't trust the outliers.

For backend metrics it's important that we monitor the p99 and max, not the mean average (why). However, due to clock drift, the metrics that fire these alerts are difficult to trust (e.g. T242024 and T233059).

Examples:

Requirements

PHP 7.3+ introduces hrtime() for this purpose, which internally uses clock_gettime(CLOCK_MONOTONIC) in C. This is comparable to performance.now() in web browsers, and process.hrtime() in Node.js.

We'll need to provide a way to get access to the monotonic timer in within the MediaWiki run-time.

Proposal

It looks like it will probably take at least a year before we run MediaWiki on PHP 7.3 by default at WMF. Both for that reason and for third parties, I suggest we invest in supporting a way on PHP 7.2 to get monotonic timers.

Assuming this can't be done in pure PHP, it will require a PHP extension (either from Pecl or to developer our own).

We would then conditionally define hrtime() if absent to use that instead (for older PHP versions), with ultimate falllback to microtime(true) if the user is neither PHP 7.3 nor the extension in question.

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
Krinkle updated the task description. (Show Details)

Some ideas:

  • There is a PECL extension for PHP that registers an HRTime class. See https://www.php.net/manual/en/intro.hrtime.php (source code). If this is well-written and has no other runtime impact, that might be a good option. (It does not yet have a Debian package.)
  • Our php-excimer exension is already using clock_gettime(CLOCK_MONOTONIC). Exposing it would be trivial. Not sure if we want to expose it there long-term, though.
  • Create a super simple php extension just for this. Using Excimer as template, we'd create a "temporary" extension like "php-wikihrtime" that we'd keep around until we're on PHP 7.3.

Can we cherry-pick the hrtime implementation into our PHP packages?

Following up on our discussion at today's team meeting, I looked at the linked PHP commit. hrtime() is just a wrapper around clock_gettime(CLOCK_MONOTONIC). This could rather trivially be backported into a PHP C extension for use with earlier versions.

It should be a VDSO jump instead of a system call, but we should double-check when we roll it out, as there are interactions between glibc, the kernel, and the hardware that can cause it to fall back. See e.g. https://bert-hubert.blogspot.com/2017/03/on-linux-vdso-and-clockgettime.html and https://bugzilla.kernel.org/show_bug.cgi?id=198961.

Thinking about this a bit further, there might be cases where we want access to CLOCK_MONOTONIC_RAW instead of CLOCK_MONOTONIC, which would point us towards wanting to build our own extension.

CLOCK_MONOTONIC is disciplined by NTP as the CPU oscillator changes, so is desirable for measuring things that hit the network or I/O bus. For measuring CPU-bound tasks (i.e. how many instructions a given code path takes), we'd get more consistent timings with CLOCK_MONOTONIC_RAW (or rolling our own access to the CPU timers using intrinsics).

On CLOCK_MONOTONIC_RAW vs CLOCK_MONOTONIC - I don't know enough there to know, I trust your judgement there. Is one of them not actually monotonic and/or not increasing a constant rate in terms of cpu/wall time?.

We probably want to switch MW over for perf measures from microtime to hrtime, unless the CLOCK_MONOTONIC is not (much) better than microtime/gettimeofday.

If CLOCK_MONOTONIC_RAW is justifably better in general, we should get in touch with upstream as well. We have a few contacts there (incl former staff), so definitely worth a shot. Also worth comparing perhaps what other runtimes use here. You mentioned Golang in today's meeting. We also use Node.js' hrtime and browser vendor's performance.now() and Navigation Timing.

"Better" depends on what's being measured. CLOCK_MONOTONIC will always move forward, at a rate that's designed to mimic the passage of time in the real world. This means the NTP daemon will speed it up or slow it down as it notices the system clock drifting away from its reference time sources. (But unlike CLOCK_REALTIME, it will never be moved backwards, and will never "jump" due to a leap second or the user manually adjusting the system time.) If we're measuring something happening in the real world (e.g. waiting on the network or a hard drive), this is going to be the most accurate measure.

CLOCK_MONOTONIC_RAW, on the other hand, is the CPU's count of how many clock cycles have passed. This may skew versus real-world time, but will be consistent between runs, regardless of what's going on with the CPU clock rate (e.g. thermal throttling). If we're measuring local code execution, this will reduce the amount of noise from external influences.

The NTP daemon tracks adjustments to the clock, so it's possible to identify when/why/how much these two counters diverge. This is why I want to start tracking the statistics it keeps.

Before we move any further - I'd like to understand what problem we're trying to solve.

Did we notice cases where microtime() returned values we don't like, and that affected metrics? To be clear - we use NTP everywhere and so the clock drift of a single server shouldn't really be over 1 second ever.

A cursory look at the linked tasks doesn't show me anything that stands out as being caused by the use of microtime.

Before we go any further with this, I'd like to understand the above with actual examples.

Also let me note that monotonic clocks are useful when you need your computation to always result in a positive integer, not for purposes of accurate time measurement.

CLOCK_MONOTONIC_RAW, on the other hand, is the CPU's count of how many clock cycles have passed. This may skew versus real-world time, but will be consistent between runs, regardless of what's going on with the CPU clock rate (e.g. thermal throttling). If we're measuring local code execution, this will reduce the amount of noise from external influences.

doesn't take into account that not all servers have the same cpu so they will have slight time skews that are different from one another, thus making the results hard to trust in general - esp across different clock speeds. I also remember in the past some reports that cpu frequency scaling has some effect on the monotonic clock anyways.

Summarizing:

  • Please provide a more detailed rationale (with production examples) of why microtime() is inadequate and causing an impact
  • Please provide an example of how using a monotonic clock would fix that issue
  • If both of the above are verified, I think we should just backport the patch introducing hrtime. This is /not/ cost free in terms of maintenance, so you need a pretty strong case for doing so.

The main problem I'd like to solve is to remove some doubt from our various backend timing instrumentations in MediaWiki PHP code. Specifically to not have to worry about them going backwards and more generally be less affected by clockskew. We currently have the pattern of $start = microtime(true); /*… */ $duration = microtime(true) - $start; sprinkled all over MediaWiki as a way to profile key tasks that are part of higher-level things we monitor the backend performance of. Such as

This would be achieved by CLOCK_MONOTONIC instead, such as via hrtime() instead of microtime(true), or through one of the other ways mentioned above.

As part of the EventBus/UUID incident investigation (T94522) I found that clockskew was quite common in production. That was in 2018 with HHVM, so don't know if it's per se fully applicable, but at the time it was easy to find examples of several seconds skew building up over only a few minutes of execution time. This suggests that measures over function calls that typically last 10-100ms each could be quite significantly skewed by this.

Regarding CLOCK_MONOTONIC_RAW - I agree that we don't need this in MediaWiki. I only just learned about this existing in Linux and it kind of answers an unrelated question I've held for some time, about how to measure the number instructions put on the CPU itself. This may be of interest for benchmarks so that there's less influence from the surrounding environment (more stable metrics). But of course, that increased stability while interesting in isolation, also makes it unsuitable for any absolute monitoring of latency.

Change 579120 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] objectcache: make WANObjectCache::set() handle very slow regeneration

https://gerrit.wikimedia.org/r/579120

This is a slightly different question than the task addresses, but microtime can be surprisingly expensive on VMs, requiring a syscall and context switch to the kernel as dpifke has mentioned, when gettimeofday isn't available through the user-space vDSO.

Continuing on this side question of overhead, we should offer configurable sampling. (Update: SamplingStatsdClient answers half of that need, reducing network overhead at least, if not short-circuiting any of the upstream logic.)

Using ltrace -cf, I caught my development server making 22,440 gettimeofday calls for no particular reason, loading and saving a short wiki page. I would be grateful if someone with access could confirm that we aren't possibly making this number of syscalls in production and that we at least have vDSO. Apologies, this has probably been covered somewhere else or in the offline discussion.


Meanwhile, while we're improving timing it would ideally be done using a shared decorator rather than custom code in every place we need to time a duration. In PHP, I guess that's best done functionally. This of course has a nice side-effect of centralizing sampling and disablement.

$performanceMonitor->measureHighResolutionDuration( $metricName, $callable );

In the rare event that we do need a high-resolution timestamp in isolation (what would this even be for?), let's provide it through a distinct API to discourage accidentally reintroducing the procedural anti-pattern for performance timing, and to allow us to choose a relatively-correct timer for durations, and an absolute timer for timestamps.

$ts = $timestampGenerator->recordHighResolutionTimestamp();

Change 585966 had a related patch set uploaded (by Awight; owner: Awight):
[mediawiki/core@master] [WIP][POC] Higher-level performance logging

https://gerrit.wikimedia.org/r/585966

Some ideas:

  • There is a PECL extension for PHP that registers an HRTime class. See https://www.php.net/manual/en/intro.hrtime.php (source code). If this is well-written and has no other runtime impact, that might be a good option. (It does not yet have a Debian package.)
  • Our php-excimer exension is already using clock_gettime(CLOCK_MONOTONIC). Exposing it would be trivial. Not sure if we want to expose it there long-term, though.
  • Create a super simple php extension just for this. Using Excimer as template, we'd create a "temporary" extension like "php-wikihrtime" that we'd keep around until we're on PHP 7.3.

The options I'm aware of:

  1. Backport hrtime from PHP 7.3 to our PHP 7.2 package. MediaWiki to use it as progressive enhancement the same way we're planning to do for PHP 7.3 anyway (fallback to non-monotonic microtime).
  2. Ship hrtime with php-excimer (e.g. if we want to avoid adding this to our PHP 7.2 package temporarily). It would be conditional and obsolete once we use PHP 7.3.
  3. Ship hrtime in a new PHP extension just for this (e.g. if we prefer not to mix this with an unrelated package). To be created, tested, packaged, and deployed in the short term. And removed again once we go to PHP 7.3.
  4. Audit the legacy PECL HRTime extension, and package and deploy that as a new temporary Debian package. I don't know if this is equivalent and without downsides though. Seems risky.

I'm awaiting feedback from ServiceOps on what approach you prefer from an operational and package management perspective.

@Krinkle there have been some discussions regarding whether it is feasible to switch to PHP 7.3 sooner. Can we hold this off a bit longer? I reckon we may have a timeline for this upgrade by Oct. If not, we can consider which option makes sense.

@MoritzMuehlenhoff what is your opinion?

As we're building custom 7.2 packages anyway; adding a backport for 1.) would not be an issue.

Thanks. We'll start work on that basis then, coding MW only for the standard PHP function.

Is there already a backport of hrtime() for 7.2?

Changelog:

It looks like no nominal changes have been made to the code at all since its first commit, so I believe the following one commit would cleanly apply and suffice:

  1. 83497327e7: Implement high resolution monotonic timer function hrtime

The following seem optional for us, but might be good to include for consistency (if they are compatible with PHP 7.2):

  1. a795bd8265: hrtime: Optimize zend_hash_real_init
  2. 19d31433dc: hrtime: Enable on OpenBSD
  3. b9dfa12853: hrtime: Wrap in extern "c" {} macro for use in extensions
  4. 4a55794b98 FIXUP hrtime: Wrap in extern "c" {} macro for use in extensions

To avoid potential misunderstandings; I currently don't have time to handle/test such a backport myself, my earlier comment from above referred to carrying an existing, backported patch forward across our remaining 7.2.x package life cycle. But if anyone from Performance Team tests such a patch e.g. in Beta I'm happy to include it in the next round of PHP updates.

I'm happy to backport/test this. Can you point me to where our PHP is built from? I found https://gerrit.wikimedia.org/r/admin/repos/operations/debs/pkg-php/php,branches but it doesn't look current.

We do local rebuild of the packages of the sury.org repo. I think the easiest way to obtain the Debian source package if you run "apt-get source php7.2" on a random app server.

Are we going to try to get sury.org to "upstream" our patch? Or maintain the patch somewhere else? (Gerrit? Attachment to this task? Somewhere else?)

The sury.org repos stick very close to the upstream releases, that won't happen realistically, especially for a feature backport.

We don't use Gerrit for your backports, it's mostly just some local commands/scripts on our build host. If you have a patch for 7.2, simply attach to this task and I'll take it from there, ok?

jijiki added a project: User-jijiki.

@dpifke please ping me to roll out the package when you are ready

For the MW side, we have these two fairly popular polyfills for third-parties:

They both more or less do the same, in that they do "nothing" when the function is natively available, and otherwise fallback to calling microtime() once to obtain a start time, and then on hrtime calls subtract it from the then-current microtime.

Of the two, I like polyfill-hrtime slightly more as it also picks up the php-hrtime extension if present (from Debian or PECL), which MediaWiki developers could install locally whilst working with PHP 7.2, which seems to be a common choice in our dev environments, so as to match prod, but we might not have the patched package from prod in our dev environment.

The reason we'd need something like this is so as to allow code to consistently call hrtime rather than having inline checks all over our code base.

For the MW side, we have these two fairly popular polyfills for third-parties:
<snip>

I agree that we need a polyfill, but I don't think we need it for third-parties. Release branches already require PHP 7.3, which has hrtime built-in. So the polyfill would just be needed for devs still running 7.2 who aren't using our theoretical patched 7.2+hrtime packages.

Ah, I forgot about that. Agreed yeah, it's just for CI and dev then.

Looks like we already bundle and deploy symfony/polyfill-php73 in production for symfony/console, which in turn is bundled for psy/psysh, which powers the maintenance/shell.php script.

They're mutually exclusive so let's just stick with this one then. Note that mass adoption in the critical path should wait until this patch is applied to production.

Krinkle renamed this task from Use monotonic clock instead of microtime() for perf measures in MW PHP to Use php-hrtime monotonic clock instead of microtime for perf measure in MW.Jun 17 2022, 4:46 PM

Re-opening for original purpose. The php-hrtime blocked is effectively resolved but we still need to go through and switch MW code to use hrtime instead of time/microtime for callers that measure duration instead of timestamp.

Untagging serviceops since php-hrtime is part of PHP 7.4 by default and no longer requires server provision changes.

Tagging MediaWiki-libs-Stats since it includes recently added code that makes use of microtime() for time duration purposes, rather than timestamps, thus appropiate for adopting hrtime() instead.

Change 965568 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/core@master] Stats: convert TimingMetric usage of microtime() to hrtime()

https://gerrit.wikimedia.org/r/965568

colewhite changed the task status from Open to In Progress.Oct 12 2023, 8:11 PM
colewhite claimed this task.

Change 965568 merged by jenkins-bot:

[mediawiki/core@master] Stats: convert TimingMetric usage of microtime() to hrtime()

https://gerrit.wikimedia.org/r/965568

colewhite changed the task status from In Progress to Open.Jan 19 2024, 9:13 PM
colewhite removed colewhite as the assignee of this task.
colewhite subscribed.

StatsLib now uses hrtime() when using start() and stop().

Unassigning myself because I am not currently working on migrating other uses.