MediaWiki

Excimer

Excimer is a PHP 7.1+ extension that provides an interrupting timer and a low-overhead sampling profiler.

MediaWiki extensions manual
Excimer
Release status: stable
Implementation PHP
MediaWiki
License Apache License 2.0
Download

GitHub:

Issues Open tasks · Report a bug

Installation edit

Linux package manager edit

apt-get install php-excimer

See packages.debian.org and packages.ubuntu.com.

For alternate PHP versions, Excimer is also packaged at https://deb.sury.org/.

For Fedora and other RPM-based distributions (e.g. using yum), Excimer is packaged at https://rpms.remirepo.net (example).

On FreeBSD, Excimer is available in the Ports Collection as devel/pecl-excimer.

PECL edit

pecl install excimer

See our PECL entry.

Source edit

Download the source code into an appropriate directory from git:

git clone https://gerrit.wikimedia.org/r/mediawiki/php/excimer.git

Or download a snapshot and unpack.

Build edit

Excimer requires Linux or BSD.

Below excimer/ is the directory that excimer Git repository was cloned to. 

cd excimer/
phpize && ./configure && make && sudo make install

Then add extension=excimer.so to the PHP configuration in an appropriate place. For example, in modern Debian-derived distributions you'd add a file to /etc/php/$version/mods-available (where $version is the version of PHP for which you compiled Excimer) and use the phpenmod command to enable it.

Background edit

For more detail, refer to our Profiling PHP in production at scale blog post.

We found that just enabling Tideways XHProf on a server with PHP 7.2 caused a performance degradation of about 4%. We believe this is due to it installing a zend_execute_ex hook, which intercepts all function calls in PHP.[1] Even though this hook does nothing by default, just having it causes PHP's VM to omit certain optimisations. The hook can only be installed globally, and it is not possible to enable it just for a particular request.

Excimer does not install any zend_execute_ex hook. This means it cannot perfectly count function calls, but does mean it it suitable for production-wide installation.

PHP provides a vm_interrupt global flag in the PHP engine that its virtual machine checks during code execution. It’s not a very precise feature, but it is checked at least once before the end of any userland function, and on every loop iteration. This check exists in the upstream PHP engine and happens regardless of whether Excimer is installed or used. This is is optimal for measuring or interrupting PHP code and more generally for CPU-intensive tasks.

If an Eximer timer, or profile sample period, elapses while the engine is busy running a C function (such as mysqli_connect), then your callback or profile sample will take place immediately after that function completes, but before your PHP code continues running. Thus the time spent will still be accurately attributed to caller. However, it also means you cannot use Excimer timers to stop (i.e. your callback throws an exception) an expensive operation that takes place as a single C function call (i.e. a single slow request, or a single slow query).

Reference documentation edit

For now, please see the function stubs in the extension source.

Examples edit

For locally profiling a MediaWiki request, see: MediaWiki-Docker/Configuration recipes/Profiling.

One-shot timer to limit the execution time of a function edit 

$timer = new ExcimerTimer;
$timer->setInterval( 10 /* seconds */ );
$timer->setCallback( function () {
    throw new Exception( "The allowed time has been exceeded" );
} );
$timer->start();
do_expensive_thing();

The "interval" timer fires only once. When the exception is thrown, the backtrace will report the callback as called from within your interrupted code.

Note that the $timer variable must be kept alive, for example by keeping it in scope. If the timer object is destroyed, the timer is automatically cleaned up and the callback never called.

Periodic timer to gather time-series memory usage statistics edit

A long-running process (e.g. command-line job) can be interrupted periodically, and the current memory usage appended to a file.

$timer = new ExcimerTimer;
$timer->setPeriod( 0.1 ); // every 100ms
$startTime = microtime( true );
$timer->setCallback( function () use ( $startTime ) {
	$usage = sprintf( "%.2f", memory_get_usage() / 1048576 );
	$interval = microtime( true ) - $startTime;
	$date = sprintf( "%.2f", $interval );
	file_put_contents(
		'/tmp/php-memory-usage',
		"$date\t$usage\n",
		FILE_APPEND );
} );
$timer->start();
...

Per-process flame graph (Speedscope) edit

In this example, a web request is traced at a high resolution (1ms samples), with a Speedscope-compatible data file written afterward.

You can drag-n-drop the JSON file directly into www.speedscope.app.

At Wikimedia Foundation, we abstract and automate the below through excimer-ui-client and excimer-ui-server (T291015).

function startExcimer() {
	static $excimer;
	$excimer = new ExcimerProfiler();
	$excimer->setPeriod( 0.001 ); // 1ms
	$excimer->setEventType( EXCIMER_REAL );
	$excimer->start();
	register_shutdown_function( function () use ( $excimer ) {
		$excimer->stop();
		$data = $excimer->getLog()->getSpeedscopeData();
		$data['profiles'][0]['name'] = $_SERVER['REQUEST_URI'];
		file_put_contents('/tmp/speedscope.json', json_encode($data, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE ));
	} );
}
startExcimer();

Per-process trace log edit

In this example, a web request is traced at a high resolution (1ms samples). This can then be viewed in Speedscope (drag and drop), or turned into an interactive flame graph SVG. FlameGraph is presumed to be installed at /usr/local/bin/flamegraph.pl. A demo of the typical output can be seen at https://tstarling.com/stuff/excimer-flamegraph.svg .

$profiler = new ExcimerProfiler;
$profiler->setPeriod( 0.001 ); // every 1ms
$profiler->setEventType( EXCIMER_REAL );
$profiler->start();
register_shutdown_function( function () use ( $profiler ) {
	$profiler->stop();
	file_put_contents( '/tmp/trace.log', $profiler->getLog()->formatCollapsed() );
} );

/usr/local/bin/flamegraph.pl /tmp/trace.log > /tmp/profile.svg

Per-process function table edit

In this example, event counts are aggregated by function name, formatted in a fixed-width table, and written to a file. An example of typical output can be seen at https://tstarling.com/stuff/excimer-aggregated.txt .

$profiler = new ExcimerProfiler;
$profiler->setPeriod( 0.01 ); // every 10ms
$profiler->setEventType( EXCIMER_REAL );
$profiler->start();
register_shutdown_function( function () use ( $profiler ) {
	$profiler->stop();
	$report = sprintf( "%-79s %14s %14s\n", 'Function', 'Self', 'Inclusive' );
	foreach ( $profiler->getLog()->aggregateByFunction() as $id => $info ) {
		$report .= sprintf( "%-79s %14d %14d\n", $id, $info['self'], $info['inclusive'] );
	}
	file_put_contents( '/tmp/aggregated.txt', $report );
} );

Site-wide sample profiling edit

You can generate flame graphs that represent production requests with very low overhead. Starting the Excimer profiler with a very high period (e.g. 60 seconds), means most requests will never be observed, and a fraction of your requests will have 1 sample taken that we then flush to a tracelog buffer. This could be Redis, rsyslog, ZeroMQ, Multicast UDP-to-file, Kafka, etc. The below example will write it to a local file for testing purposes. This file could then be turned into a flame graph by running cat /tmp/excimer-traces.log | /usr/local/bin/flamegraph.pl > flamegraph.svg. Or load the trace log directly into Speedscope.

function start_my_sampling_profiler() {
    static $prof; // Keep object until the end of the request
    $prof = new ExcimerProfiler;
    $prof->setEventType( EXCIMER_REAL );
    $prof->setPeriod( 60 ); // every 60s
    $prof->setMaxDepth( 250 ); // https://phabricator.wikimedia.org/T176916#5105095

    // In production, assuming requests generally take far less than 60s,
    // most web requests will never call this, and some will call it once.
    $prof->setFlushCallback( function ( $log ) {
        // e.g. send to Redis, UDP, or local file
		file_put_contents( '/tmp/excimer-traces.log', $log->formatCollapsed(), FILE_APPEND );
	}, 1 );
    $prof->start();
}
start_my_sampling_profiler();

Eximer ensures that samples are representative by automatically staggering the first (and likely, only) interval by a random fraction of the sampling period.

As of December 2022, Wikipedia's web-facing Apache servers receive about 1.6 billion requests per day (~20,000 req/s) from 300 physical servers across its 2 main data centers.[2] The median latency is ~100ms, with p95 of ~600ms.[3] With the sampling period of 60 seconds, we end up collecting 3 million stack traces per day. This translates to roughly 1 sample from 0.2% of requests, and 0 samples from the other 99.8%. Refer to Arc Lamp for how we do this in production. More details on Profiling PHP in production at scale at our Techblog. Our hourly and daily flame graph can be browsed at https://performance.wikimedia.org/php-profiling/.

Who uses Excimer? edit

See also edit

Code stewardship edit

Maintainer notes edit

For information about how to update the PECL release, see how to PECL.

References edit

  1. ↑ Comment on "Excimer: new profiler for PHP", Tim Starling (2018), phabricator.wikimedia.org.
  2. ↑ "Web-facing Apache servers" refers to the appserver, api_appserver, and parsoid clusters that run MediaWiki at WMF. This notably excludes MediaWiki jobrunners.
  3. ↑ Application Servers RED metrics, grafana.wikimedia.org.
Retrieved from "https://www.mediawiki.org/w/index.php?title=Excimer&oldid=6387521"