Page MenuHomePhabricator

Gain telemetry on MW init
Closed, ResolvedPublic

Description

Gain visibility into how much time is spent on a typical request to get from "start of entry point file" to "end of WebStart/Setup.php".

This can be temporary and is to complete task T189966.

Some ideas:

  • Broken down by entry point (e.g. focus on "index", "api" and "load").
  • Broken down by: 1) entrypoint+Setup until LocalSetings, 2) LocalSettings (e.g. wmf-config), 3) Rest of Setup.

Given that we're fully on stacktrace-based profiling (both for debug and for sampling, Tideways/Excimer), we can't easily create fake spans of time measurements here.

Two approaches to consider:

  • Ad-hoc microtime sent to StatsD from shutdown callback (would be coded in wmf-config + mutliversion).
  • Or - leverage the stacktrace profiling by making sure the logical groups have a non-root stack frame, e.g. wrapped in a function call.

The latter would be easiest also long-term. The main hindering there is that LocalSettings must execute in the global scope (and emulating that is non-trivial, likely impossible in a way that would be performant and backward-compatible).

Perhaps a combination of the two.

Event Timeline

From task description:

Broken down by: 1) entrypoint+Setup until LocalSetings, 2) LocalSettings (e.g. wmf-config), 3) Rest of Setup.
[…]
[…] leverage the stacktrace profiling by making sure the logical groups have a non-root stack frame, e.g. wrapped in a function call.

The sampling profiler already tracks the file-scope by using the filename as "fake" stack frame. This means we already have an exact proportion of time spent in wmf-config/CommonSettings and sub files etc..

For the debug profiler this is not the case, but can be approximated by deducting the main call (e.g. MediaWiki::run or ResourceLoader::respond) from main() at which point the other stuff remains.

Sampling profiler

For load.php (2019-09-29 samples):

Screenshot 2019-09-30 at 02.44.57.png (1×2 px, 552 KB)

38.25% is spent within WebStart.php. Breakdown, roughly in order of execution:

  • 0.04% (self) in WebStart.
  • 0.20% in vendor/autoload.php.
  • 8.24% in LocalSettings.php, proxies wmf-config/CommonSettings.php
    • 2.09% (self) in wmf-config/CommonSettings.php.
    • 0.43% in wmfEtcdConfig
    • 0.46% in wmf-config/wgConf.php
    • 1.40% in MWConfigCacheGenerator::readFromStaticCache
    • 0.82% in wmf-config/logging.php
    • 1.72% in wfLoadExtension
  • 0.62% in ExtensionRegistry::getInstance
  • 17.28% in ExtensionRegistry::loadFromQueue. – T187154
  • 1.14% in MediaWikiServices::getInstance
  • 2.63% in MediaWikiServices::getDBLoadBalancer. – T228895
  • 1.81% in WebRequest::getIP (for DBLoadBalancer).
  • 0.37% in ObjectCache::getLocalClusterInstance (assign $wgMemc). – T160813
  • 1.07% in MediaWikiServices::getContentLanguage (to assign deprecated $wgContLang)
  • 0.39% in WebRequest::interpolateTitle (irrelevant to non-index.php, but runs regardless)
  • 0.37% in SessionManager::singleton (note, the entry point has MW_NO_SESSION)
  • 0.18% in PHPSessionHandler::install (note, the entry point has MW_NO_SESSION)
  • 0.53% in EchoHooks::initEchoExtension (as wgExtensionFunctions) mostly spent in Hooks::callHook, suggests it might have significant overhead.

For api.php (2019-09-29 samples):

Screenshot_2019-09-30_at_03.13.16.png (1×2 px, 700 KB)

24.67% is spent within WebStart.php. Breakdown, roughly in order of execution:

  • 0.02% (self) in WebStart.
  • 4.48% in LocalSettings.php, proxies wmf-config/CommonSettings.php
    • 1.14% (self) in wmf-config/CommonSettings.php.
    • 0.21% in wmfEtcdConfig
    • 0.24% in wmf-config/wgConf.php
    • 0.84% in MWConfigCacheGenerator::readFromStaticCache
    • 0.52% in wmf-config/logging.php
    • 0.99% in wfLoadExtension
  • 0.27% in ExtensionRegistry::getInstance
  • 9.58% in ExtensionRegistry::loadFromQueue. – T187154
  • 0.50% in MediaWikiServices::getInstance
  • 1.46% in MediaWikiServices::getDBLoadBalancer. – T228895
  • 1.07% in WebRequest::getIP (for DBLoadBalancer).
  • 0.19% in ObjectCache::getLocalClusterInstance (assign $wgMemc).
  • 0.47% in MediaWikiServices::getContentLanguage (assign $wgContLang)
  • 0.17% in SessionManager::singleton.
  • 3.99% in SessionManager::getGlobalSession.
  • 0.30% in EchoHooks::initEchoExtension (as wgExtensionFunctions).

For index.php (2019-09-29 samples):

Screenshot 2019-09-30 at 03.19.15.png (1×2 px, 744 KB)

13.19% is spent within WebStart.php. Breakdown, roughly in order of execution:

  • 0.01% (self) in WebStart.
  • 2.57% in LocalSettings.php, proxies wmf-config/CommonSettings.php
    • 0.46% in MWConfigCacheGenerator::readFromStaticCache
    • 0.31% in wmf-config/logging.php
    • 0.55% in wfLoadExtension
  • 5.07% in ExtensionRegistry::loadFromQueue. – T187154
  • 0.28% in MediaWikiServices::getInstance
  • 0.72% in MediaWikiServices::getDBLoadBalancer. – T228895
  • 0.61% in WebRequest::getIP (for DBLoadBalancer).
  • % in ObjectCache::getLocalClusterInstance (assign $wgMemc). – T160813
  • 0.26% in MediaWikiServices::getContentLanguage (assign $wgContLang)
  • 1.97% in SessionManager::getGlobalSession.

I'll take some runs from XHGui tomorrow as well, which would give us more absolute time measures. After that, we can consider the task closed and revisit towards the end of the parent task once the work that came out of this is resolved.

Debug profiler

XHGui profile on 2019-10-03 for load.php…startup

  • main() – 869 ms
    • MediaWikiServices::getResourceLoader – 18.3 ms
    • ResourceLoader::respond – 798.4 ms
    • MediaWiki::doPostOutputShutdown – 8.2 ms
    • Setup, WebStart and wmf-config – 44.1 ms
      • ExtensionRegistry::loadFromQueue – 14.4 ms
      • wfLoadExtension (119 calls) – 3.8 ms
      • WebRequest::getIP – 2.7 ms
      • MWConfigCacheGenerator::readFromStaticCache – 1.7 ms
      • MWWikiversions::readDbListFile (5 calls) – 1.1 ms