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.

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;
}

In T205059#4609353, @ori wrote:

[..] 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?

In T205059#4609367, @tstarling wrote:

[..] 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.

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

@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

We're going to rebuild the extension package today from the latest code version and install it across the fleet.

Mentioned in SAL (#wikimedia-operations) [2018-12-17T13:40:59Z] <fsero> installing new version of php-excimer on mwdebug2001 - T205059

Mentioned in SAL (#wikimedia-operations) [2018-12-17T13:46:16Z] <fsero> installing new version of php-excimer on mwdebug* - T205059