Excimer: Difference between revisions
m switch default examples from _CPU to _REAL because it's what most people seem to prefer to consume/find more insightful, and because its supported on macOS. CPU is more stable and has benefits sa well, |
No edit summary |
||
Line 60: | Line 60: | ||
== Examples == |
== Examples == |
||
⚫ | |||
=== Per-request flame graph from MediaWiki === |
|||
⚫ | |||
Add once to your LocalSettings.php. After making a request with <code>?forceprofile=1</code> set, use [https://performance.wikimedia.org/excimer/speedscope/ Speedscope] to open the latest Speedscope JSON file from the MediaWiki logs directory.<syntaxhighlight lang="php"> |
|||
// Use ?forceprofile=1 to generate a trace log, written to /w/logs/speedscope.json |
|||
if ( extension_loaded( 'excimer' ) && isset( $_GET['forceprofile'] ) ) { |
|||
$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( MW_INSTALL_PATH . '/logs/speedscope-' . gmdate( 'Y-m-d_His' ) . '.json', |
|||
json_encode( $data, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE ) ); |
|||
} ); |
|||
} |
|||
</syntaxhighlight> |
|||
=== One-shot timer to limit the execution time of a function === |
=== One-shot timer to limit the execution time of a function === |
Revision as of 13:55, 25 April 2024
Excimer Release status: stable |
|
---|---|
Implementation | PHP |
MediaWiki | |
License | Apache License 2.0 |
Download | GitHub: |
Issues | Open tasks · Report a bug |
Excimer is a PHP 7.1+ extension that provides an interrupting timer and a low-overhead sampling profiler.
Installation
Linux package manager
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
pecl install excimer
See our PECL entry.
Source
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
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
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
For now, please see the function stubs in the extension source.
Examples
Per-request flame graph from MediaWiki
Add once to your LocalSettings.php. After making a request with ?forceprofile=1
set, use Speedscope to open the latest Speedscope JSON file from the MediaWiki logs directory.
// Use ?forceprofile=1 to generate a trace log, written to /w/logs/speedscope.json
if ( extension_loaded( 'excimer' ) && isset( $_GET['forceprofile'] ) ) {
$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( MW_INSTALL_PATH . '/logs/speedscope-' . gmdate( 'Y-m-d_His' ) . '.json',
json_encode( $data, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE ) );
} );
}
One-shot timer to limit the execution time of a function
$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
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)
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
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
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
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?
- Wikimedia Foundation: Profiling PHP in production (2021), Flame graphs arrive in WikimediaDebug (2023).
- Sentry for PHP: Add PHP profiling (2023).
See also
- Profiling PHP in production at scale, Timo Tijhof, 2021.
- Browse source code (GitHub mirror)
- Arc Lamp, generate flame graphs for PHP in production using Excimer as sampling profiler.
- Brendan Gregg's Flame Graphs
Code stewardship
- Maintained by MediaWiki Platform Team.
- Live chat (IRC): #mediawiki-core connect
- Issue tracker: Phabricator Excimer (Report an issue)
Maintainer notes
For information about how to update the PECL release, see how to PECL.
References
- ↑ Comment on "Excimer: new profiler for PHP", Tim Starling (2018), phabricator.wikimedia.org.
- ↑ "Web-facing Apache servers" refers to the appserver, api_appserver, and parsoid clusters that run MediaWiki at WMF. This notably excludes MediaWiki jobrunners.
- ↑ Application Servers RED metrics, grafana.wikimedia.org.