Excimer: new profiler for PHP
Open, Needs TriagePublic

Description

XHProf is mired in maintainer issues, with multiple forks, and the small code base doesn't provide much value for what we want to do.

PHP 7.1+ provides EG(vm_interrupt), a global variable which, when set to 1, will cause the VM to call the hook zend_interrupt_function fairly promptly. This is now used for timeout handling and pcntl_signal, allowing userspace signal handlers to be called safely, soon after a signal is received.

My proposal is to use this to implement a new profiler for PHP 7.1+, modelled on the LuaSandbox profiler. Like LuaSandbox, it will only support timer_create() with SIGEV_THREAD.

$excimer = new ExcimerProfiler;
$excimer->setPeriod( 0.1 /*seconds*/ );
$excimer->setEventType( EXCIMER_CPU );

// The flush callback is automatically called on destruct, or if the specified number of samples were collected
$excimer->setFlushCallback( 'flushCallback', 1000 );

$excimer->start();
$excimer->stop();
$log = $excimer->getLog();

function flushCallback( $log ) {
    // Write file in FlameGraph format with semicolon-separated stacks
    file_put_contents( 'profile.folded', $log->formatCollapsed(),  FILE_APPEND );
}

// Using an iterable object for the log avoids the overhead of constructing a PHP array
// Because the profiler is request-local, we can use opline/oparray pointers to store logs compactly
foreach ( $log as $entry ) {
    // Storing a timestamp in the log entry allows a couple of interesting applications:
    //    - Percentage of busy versus halted CPU time
    //    - Browser-style time-series flame chart
    print $entry->getTimestamp() . "\n";
    // Trace array format will be similar to Exception::getTrace()
    foreach ( $entry->getTrace() ) {
        ...
    }
}

Currently in Xenon, the sampling interval is 600 seconds, which is much larger than the average request time. This could be supported in Excimer by having Excimer stagger the time at which the first event occurs randomly over the period. For example, if the period was 10 seconds, the first event would occur after mt_rand(0, 10000) milliseconds, then the next event would occur exactly 10 seconds after that. So the timer would most often be disarmed at the end of the request without having fired. The flush callback would not be called if the log is empty.

Using a non-static, non-global profiler means that it will be possible to run two profilers at once. We could have one profiler running which records CPU time, and another which records wall clock time, and generate flame graphs for both.

Once we have the relevant infrastructure for timer_create() handling, we could easily provide a generic timer facility to the userspace:

$timer = new ExcimerTimer;
$timer->setEventType( EXCIMER_CPU );
$timer->setInterval( 1 ); // one-shot mode
$timer->setPeriod( 1 ); // periodic mode
$timer->setCallback( $callback );
$timer->start();
$timer->stop();
$timer->getTime(); // timer_gettime() wrapper
$timer->getOverrun(); // timer_getoverrun() wrapper

Interestingly, such a facility would probably be able to throw exceptions safely from within the callback, providing a means to abort long-running functions (such as parsing) before the PHP request timeout is hit.

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 21 2018, 6:44 AM
Krinkle awarded a token.
ori added a subscriber: ori.Sep 24 2018, 2:46 AM

I wonder if a callback is the right choice, particularly for the periodic mode. Presumably you'd want the processing of samples to occur after response data has been flushed, in a context that is healthy (e.g., you can make use of storage and logging facilities, and you are not on the cusp of hitting the timeout). But if the callback can be called because the sample buffer is full, then the call could come at any time, no? Wouldn't it be better to leave it to PHP code to call $excimer->getLog(), and have that return null if the log is empty?

The main reason to use a flush callback is for real-time analysis of overload events. The problem we've had in the past is that if profiling data is only logged at the end of the request, the requests that are timing out are invisible. If we log once every 10 seconds, we can get a realistic snapshot of what the cluster is doing.

If setFlushCallback() is not called, then it would work as you describe, my proposal does not prevent doing that. If you're worried about the callback being called before MW is fully initialised, why not call $excimer->start() at the start of the request, and then $excimer->setFlushCallback() after initialisation is done? There would be no reason to reset the logs when setFlushCallback() is called.

I'm planning the timer backend component. An interesting wrinkle is ZTS support. As in LuaSandbox, we can have an integer ID (sival_int) with our timer struct stored in a hashtable, with a lock protecting it from concurrent updates. Instead of setting a hook in a lua_State, we need to store &EG(vm_interrupt) in the timer struct, since in PHP 7.0+ it is declared with __thread, so taking the address of it is the only way to transport it to the handler thread. Then when the zend_interrupt_function() hook is called, the hook function will need to find all the ExcimerTimer/ExcimerProfiler instances associated with the local thread that have pending events -- this was not a problem with LuaSandbox which only had one "timer set" per lua_State.

One thing that we might have missed in LuaSandbox is that a SIGEV_THREAD handler should be able to safely call malloc(). So we can add values to a HashTable from the handler thread if the HashTable is initialised with the persistent flag. So the handler thread could fetch the timer struct from a global hashtable, and then in that timer struct find a pointer to a thread-local hashtable. The thread-local hashtable could have a map [ timer ID => event count ], where the event count is incremented each time the timer fires, plus the overrun count. Then when the hook runs, it can iterate over this local hashtable, dispatching events.

The backend interface synopsis pseudocode:

timer = excimer_timer_create(callback, userdata);
excimer_timer_set(timer, interval, value); // simple timer_settime() wrapper, both periodic and one-shot
excimer_timer_stop(timer);
excimer_timer_destroy(timer);

// This is called from the zend_interrupt_function hook
void callback(void * userdata, int64_t event_count) {
   ...
}

ExcimerProfiler and ExcimerTimer can both use this backend. ExcimerTimer will have a simple callback which just gets a zval out of the userdata and calls it. ExcimerProfiler will collect a stack trace and optionally call a flush callback.

Joe added a subscriber: Joe.Sep 24 2018, 4:45 PM
Imarlier added a subscriber: Imarlier.

I think there should also be ExcimerProfiler::flush(), which detaches the log and returns it, similar to what happens on an implicit flush. The theory is that ExcimerProfiler::stop() will leave the log still attached to the profiler, so this:

$excimer->stop();
$log = $excimer->getLog();
$excimer->start();
foreach ( $log as $entry ) {
   ...
}

gives a log object in $log which may be appended to at any time, producing unexpected results. Instead we could have:

$log = $excimer->flush();
foreach ( $log as $entry ) {
   ...
}

Where $log would be subsequently immutable, a new log being created for the profiler to write to, as if the implementation were:

function flush() {
    $log = $this->log;
    $this->log = new ExcimerLog;
    return $log;
}
Krinkle added a comment.EditedSep 29 2018, 12:39 AM

[..] Presumably you'd want the processing of samples to occur [..] in a context that is healthy (e.g., you can make use of storage and logging facilities [..]

I think the flush logic to send data to Arc Lamp can be easily written in plain PHP code. We might need a class from a compiled PHP extension (e.g. Redis), but no interaction with code defined by mediawiki-core or mediawiki-vendor.

Would that address your concern?

[..] If you're worried about the callback being called before MW is fully initialised, why not call $excimer->start() at the start of the request, and then $excimer->setFlushCallback() after initialisation is done [..]

I agree this solution would work well if we require flushes to only happen after MediaWiki initialisation is done. But, per the above, I don't think we should. I'd much rather the profiling code simply work independent of MediaWiki, which has the happy side-effect of avoiding this additional requirement.

ori added a comment.Oct 3 2018, 12:00 AM

Tim's rationale for the callback interface makes sense to me. Thanks for the explanation.

Change 464742 had a related patch set uploaded (by Tim Starling; owner: Tim Starling):
[mediawiki/php/excimer@master] [WIP] Excimer: PHP 7 profiler

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

Change 464742 merged by jenkins-bot:
[mediawiki/php/excimer@master] Excimer: PHP 7 profiler

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

daniel added a subscriber: daniel.Oct 26 2018, 7:48 AM

@Krinkle asked whether we can do function counts in excimer, to provide feature parity with xhprof. I think the answer is no, not without a PHP patch. The relevant hook (zend_execute_ex) is a true global, so it needs to be installed unconditionally, on MINIT. When this hook is overridden, the VM switches into a slow mode which uses the C stack for internal function calls, instead of the internal stack. For example, in the DO_FCALL handler:

	if (EXPECTED(fbc->type == ZEND_USER_FUNCTION)) {
		...
		if (EXPECTED(zend_execute_ex == execute_ex)) {
			LOAD_OPLINE();
			ZEND_VM_ENTER_EX();
		} else {
			execute_data = EX(prev_execute_data);
			LOAD_OPLINE();
			ZEND_ADD_CALL_FLAG(call, ZEND_CALL_TOP);
			zend_execute_ex(call);
		}

So I think just enabling an extension that has a function call counting feature will be enough to incur a significant performance overhead, even before it does anything. So it makes sense to use a separate extension for that, installed on a separate debugging host.

We could do a PHP patch which provides a non-recursive function entry hook. It would be called everywhere i_init_func_execute_data() is currently called.

Mentioned in SAL (#wikimedia-operations) [2018-11-26T12:04:43Z] <_joe_> uploaded php-excimer for component thirdparty/php72 to stretch-wikimedia T205059

Change 475769 had a related patch set uploaded (by Giuseppe Lavagetto; owner: Giuseppe Lavagetto):
[operations/puppet@production] profile::mediawiki::php: install excimer on newer versions of php

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

FYI I've been following along here, and I checked out the excimer build - super cool, worked well for me! I just had a question around the scope. When I tried it I noticed inbuilt PHP functions were not part of the sample, so if I have a function that calls sleep or curl_exec, I don't see this as part of the sample. I assumed this is because inbuilt functions use a different API. Is there plan to include inbuilt php functions in the samples?

@Joehoyle: internal functions were just skipped for simplicity. We configure xhprof to skip them, so we presumably don't need that feature for production. Finding the function name for an internal function requires a few more lines of code. So I guess it depends on how much you want them.

For methods of internal classes there's a get_class_name handler that may need to be called, it's not guaranteed that the name in the zend_class_entry is valid.

I'm wondering now whether we should just call zend_fetch_debug_backtrace() instead of reimplementing it bit by bit. There's a few other special cases there that we haven't implemented, such as generators and trait aliases. I was just concerned about it being slower, but maybe it doesn't matter, since the sampling period will be much larger than the overhead.

Also, the zend_interrupt_function hook is only called after the internal function returns to the VM, at which point it is not in the stack anymore. At best you would only see functions that re-enter the VM, like array_map(). So it would be misleading.

Change 475769 merged by Giuseppe Lavagetto:
[operations/puppet@production] profile::mediawiki::php: install excimer on newer versions of php

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