Page MenuHomePhabricator

Profiling for X-Wikimedia-Debug seems to start fairly late
Closed, ResolvedPublic

Description

Not sure if we can easily improve this but I notice that when comparing HHVM-level flame graphs (from hourly/daily aggregation of Xenon, sampling profiler) to flame graphs from a one-off run with X-Wikimedia-Debug (XHProf to XHGui), it starts relatively late.

E.g. The outer level is basically the mediawiki core entry point file. We're missing the loading of multiversion, wmf-config and vendor.

X-Wikimedia-Debug (StartProfiler > XHProf > XHGui)Xenon (HHVM)
Screen Shot 2017-11-09 at 16.08.12.png (660×1 px, 229 KB)
Screen Shot 2017-11-09 at 16.08.36.png (608×2 px, 316 KB)
top-level files: core/vendor, core/LocalSettings (wmf-config)top-level files: core/load.php, core/WebStart, core/Setup, core/AutoLoader, core/vendor, core/LocalSetting (wmf-config)

As far as I can tell, this is entirely dictated by when MediaWiki core "includes" the local StartProfiler file, which happens from Setup.php after including AutoLoader.

I'm curious if we could move this earlier because as far as I can tell, there is already nothing useful available to StartProfiler's execution context (no settings, no vendor, no global functions).

The only thing StartProfiler does (from MediaWiki's perspective) is assign a standalone scalar value to a global variable $wgProfiler. No classes or constants are used here. And yet it is the fourth thing included by Setup.php, which in turn is the first thing included by WebStart.php, which in turn is the first thing included by entry points.

Setup.php
require_once "$IP/includes/profiler/ProfilerFunctions.php";
require_once "$IP/includes/AutoLoader.php";
require_once "$IP/includes/Defines.php";

$wgProfiler = [];
if ( file_exists( "$IP/StartProfiler.php" ) ) {
	require "$IP/StartProfiler.php";
}

Steps:

  1. Moving the inclusion of StartProfiler.php in MediaWiki core from being the fourth include, to being the first include. – 25d3185dde7631a24ec5833f045658aa6aa2ad4c
  2. Factor out the profiling code in wmf-config from StartProfile.php into a separate profiler.php file. – 96de34769d97
  3. Call xhprof_enable directly from profiler.php, instead of currently where we wait for MediaWiki to initialise the Profiler class, which then enables Xhprof. This cannot feasibly be done from within MediaWiki and must be done within wmf-config. – 6f3214eafda6
  4. Update Wikimedia's HHVM/PHP configuration to include profiler.php via a auto_prepend_file.

This last step will make it so that our profiles include mediawiki-core's Setup.php, WebStart.php, w/index.php (entry point), as well as the steps before that, from the multiversion entrypoint.

Details

SubjectRepoBranchLines +/-
operations/puppetproduction+3 -2
operations/puppetproduction+2 -2
operations/puppetproduction+4 -1
operations/mediawiki-configmaster+19 -0
operations/mediawiki-configmaster+13 -1
operations/mediawiki-configmaster+112 -113
operations/mediawiki-configmaster+21 -16
operations/mediawiki-configmaster+0 -44
operations/mediawiki-configmaster+14 -3
operations/mediawiki-configmaster+15 -13
operations/mediawiki-configmaster+12 -12
operations/mediawiki-configmaster+71 -72
operations/mediawiki-configmaster+79 -79
operations/mediawiki-configmaster+29 -14
operations/mediawiki-configmaster+6 -0
operations/puppetproduction+3 -0
operations/mediawiki-configmaster+79 -0
operations/mediawiki-configmaster+2 -19
operations/mediawiki-configmaster+279 -245
operations/mediawiki-configmaster+76 -22
mediawiki/coremaster+9 -10
Show related patches Customize query in gerrit

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes

It helps a little bit, but you still don't get multiversion. Maybe we should use auto_prepend_file.

It helps a little bit, but you still don't get multiversion. Maybe we should use auto_prepend_file.

Yeah, for WMF we might want to remove it from the php dir (so that it isn't discovered by MediaWiki) and ensure it gets loaded by other means (auto_prepend_file, or manually from our multiversion entry points (e.g. from operations/mediawik-config.git:/w/*.php).

Either way, it'd still good to improve core as much as we can.

Also, if we allow loading by other means, we'll need to make sure wgProfiler isn't cleared by Setup.php the way it is now. Which probably means a dirty isset() or some such.

Alternatively, we could split wmf-config's file into two separate files. One we load early (that takes care of everything, except setting $wgProfiler), and a short StartProfiler.php file that just sets the config variable if needed.... based on global state left behind from the first script? (e.g. $wmfProfiler, or a boolean constant)

Change 390351 merged by jenkins-bot:
[mediawiki/core@master] Setup: Include StartProfiler before others

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

For the record, WMF's HHVM configuration already makes use of a setting request_init_document, which is similar to auto_prepend_file. However, we mustn't use that for this purpose because its semantics are incompatible with our purposes.

HHVM 3.1.0 introduced support for auto_prepend_file. Since before that, HHVM has had a request_init_document setting. Details are at HHVM Server Flow, but I've summarised its behaviour at https://gerrit.wikimedia.org/r/#/c/390526/1/wmf-config/HHVMRequestInit.php

Change 390548 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] Improve StartProfiler.php file documentation

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

Change 390548 merged by jenkins-bot:
[operations/mediawiki-config@master] StartProfiler.php: Add lots of documentation

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

Change 391162 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] [WIP] Split profile.php from StartProfiler and add PhpAutoPrepend

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

Change 391162 merged by jenkins-bot:
[operations/mediawiki-config@master] Split profile.php from StartProfiler, and create PhpAutoPrepend.php

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

Change 403973 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] Remove unused PhpAutoPrepend.php file for now.

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

Change 403974 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] Initial profiler for Beta Cluster

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

Krinkle changed the task status from Open to Stalled.Jan 12 2018, 8:22 PM

Change 403973 merged by jenkins-bot:
[operations/mediawiki-config@master] Remove unused PhpAutoPrepend.php file for now.

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

Change 403974 merged by jenkins-bot:
[operations/mediawiki-config@master] Initial profiler for Beta Cluster

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

Krinkle changed the task status from Stalled to Open.Feb 14 2018, 6:50 AM

Change 412827 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/puppet@production] mediawiki: Enable auto_prepend_file setting for HHVM on Beta Cluster

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

Change 412827 merged by Giuseppe Lavagetto:
[operations/puppet@production] mediawiki: Enable auto_prepend_file setting for HHVM on Beta Cluster

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

Change 413315 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler-labs: Call xhprof_enable earlier to match prod

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

Change 413315 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler-labs: Call xhprof_enable earlier to match prod

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

Change 414863 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler-labs: Factor out 'Enable profiler' code, add 'forceprofile' to XWD

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

Change 414863 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler-labs: Factor out 'Enable profiler' code, add 'forceprofile' to XWD

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

Change 414868 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Swap order of Xenon and XHGui setup (no-op)

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

Change 414869 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Merge XHGui-setup into the overall hot_profiler block

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

Change 414881 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Move $XWD assignment to inside hot_profiler block (no-op)

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

Change 414884 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Rename $XWD to $xwd, and unset

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

Change 414863 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler-labs: Factor out 'Enable profiler' code, add 'forceprofile' to XWD

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

Change 414868 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Swap order of Xenon and XHGui setup (no-op)

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

Change 414869 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Merge XHGui-setup into the overall hot_profiler block

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

Change 414881 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Move $XWD assignment to inside hot_profiler block (no-op)

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

Change 414884 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Rename $XWD to $xwd, and unset

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

Mentioned in SAL (#wikimedia-operations) [2018-02-27T03:28:39Z] <krinkle@tin> Synchronized wmf-config/profiler.php: various refactor and clean up for T180183 (no-op) (duration: 00m 54s)

Change 414932 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Use preg_match_all instead of parse_str for XWD parsing

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

Change 414932 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Use preg_match_all instead of parse_str for XWD parsing

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

Change 414933 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Remove code for dumping xhprof to /tmp (no longer works)

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

Change 414933 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Remove code for dumping xhprof to /tmp (no longer works)

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

Change 415201 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Implement 'forceprofile' as part of X-Wikimedia-Debug

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

Change 415211 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Enable xhprof earlier from StartProfile

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

Change 415201 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Implement 'forceprofile' as part of X-Wikimedia-Debug

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

Change 415211 merged by Krinkle:
[operations/mediawiki-config@master] profiler: Enable xhprof earlier from StartProfile

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

Mentioned in SAL (#wikimedia-operations) [2018-03-06T04:01:42Z] <krinkle@tin> Synchronized wmf-config/profiler.php: T180183 (duration: 01m 33s)

Change 416636 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Sync remaining differences with profiler-labs

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

Change 416637 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/puppet@production] [WIP] mediawiki: Enable auto_prepend_file on canary_appserver

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

Change 416636 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Sync remaining differences with profiler-labs

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

Change 416638 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] Add PhpAutoPrepend.php

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

Change 416638 merged by jenkins-bot:
[operations/mediawiki-config@master] Add PhpAutoPrepend.php

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

Mentioned in SAL (#wikimedia-operations) [2018-03-06T04:59:30Z] <krinkle@tin> Synchronized wmf-config/profiler.php: T180183 - Ie5a164a9e2b (duration: 00m 57s)

Mentioned in SAL (#wikimedia-operations) [2018-03-06T05:00:52Z] <krinkle@tin> Synchronized wmf-config/PhpAutoPrepend.php: T180183: I6d72873b9d3 (duration: 00m 56s)

Change 416637 merged by Giuseppe Lavagetto:
[operations/puppet@production] mediawiki: Enable auto_prepend_file on canary_appserver

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

Change 417312 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/puppet@production] mediawiki: Actually enable auto_prepend_file on canary_appserver

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

Change 417312 merged by Giuseppe Lavagetto:
[operations/puppet@production] mediawiki: Actually enable auto_prepend_file on canary_appserver

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

This change is now live on canary app servers (including mwdebug* servers, as targeted via X-Wikimedia-Debug).

Before (sample)

children of main()
…
run_init::/srv/mediawiki/php-1.31.0-wmf.23/includes/DefaultSettin…
run_init::/srv/mediawiki/php-1.31.0-wmf.23/LocalSettings.php
run_init::/srv/mediawiki/php-1.31.0-wmf.23/vendor/autoload.php
…
MediaWiki::__construct
…

After (sample)

children of main()
{internal}
- run_init::/srv/mediawiki/multiversion/MWMultiVersion.php
  - run_init::/srv/mediawiki/multiversion/MWRealm.php
  - run_init::/srv/mediawiki/multiversion/vendor/autoload.php
  - …
- MWMultiVersion::getMediaWiki
  - …
- run_init::/srv/mediawiki/php-1.31.0-wmf.24/load.php
  - run_init::/srv/mediawiki/php-1.31.0-wmf.24/includes/WebStart.php
    - run_init::/srv/mediawiki/php-1.31.0-wmf.24/includes/Setup.php
    - run_init::/srv/mediawiki/php-1.31.0-wmf.24/StartProfiler.php
    - …
    - run_init::/srv/mediawiki/php-1.31.0-wmf.24/includes/DefaultSettin…
    - run_init::/srv/mediawiki/php-1.31.0-wmf.24/LocalSettings.php
    - run_init::/srv/mediawiki/php-1.31.0-wmf.24/vendor/autoload.php
  - MediaWiki::__construct
    - …

Previously broken:

  • Missing: /srv/mediawiki/ multiversion/…
  • Missing: /srv/mediawiki/ php-…/load.php
  • Missing: /srv/mediawiki/ php-…/includes/WebStart.php
  • Missing: /srv/mediawiki/ …/StartProfiler.php (previously the starting entry point for profiling, now a no-op)
  • Incorrectly nested: MediaWiki::__construct

Announced at https://lists.wikimedia.org/pipermail/wikitech-l/2018-March/089639.html ("[Wikitech-l] PHP profiling - Now covering covering multiversion and wmf-config")

Change 440822 had a related patch set uploaded (by Giuseppe Lavagetto; owner: Giuseppe Lavagetto):
[operations/puppet@production] profile::mediawiki::hhvm: add auto_prepend_file everywhere

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

@Krinkle I prepared a patch to use the auto prepend file on all appservers, not just the canaries. Should we deploy it once the deployment freeze is over?

Change 440822 merged by Giuseppe Lavagetto:
[operations/puppet@production] profile::mediawiki::hhvm: add auto_prepend_file everywhere

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