Make WP_Hook gather callback performance information

[Rarst]

The Hook API represents one of the most interesting parts of core from performance point of view. It is both widely used and implementation is in userland code, as opposed to language features (such as standalone function calls).

However as of current implementation (WP_Hook class) it is a huge challenge to gather profiling information from it in safe and compatible way. Class itself is final and instances cannot be effectively replaced. Injecting custom logic at all hook and reimplementing hook execution in extension code is possible, but risky.

I suggest we implement WP_Hook natively logging origin and duration times for executed callbacks. The information can be added to callback record which is in public access space and will not cause any backwards incompatible changes.

My draft suggestion would be something like this (notably to account for multiple executions of hook/callback):

[
	'function' => ...
	'accepted_args' => ...
	'runs' => [
		[ 'start' => ..., 'duration' => ... ],
		[ 'start' => ..., 'duration' => ... ],
		[ 'start' => ..., 'duration' => ... ],
	]
]

Main concern would be resource cost, with sites possibly calling tens of thousands of hooks. I think resource overhead should be reasonable with only adding two floats to array and no complex calls or calculations. This can be tested and profiled on a proof of concept implementation.

The possible mitigation to runtime costs can be making the feature opt–in with flag analogous to SAVEQUERIES, for example SAVE_HOOK_TIME.

The possible mitigation to memory costs can be implementing cut off limit to amount of timings stored, e.g. start discarding old records when a certain limit of X records is reached for a callback.

If there is agreement on feasibility I will work on a patch.

[johnbillion]

I like the idea but I don't think this is something that needs to run on every hook on every page load. The constant idea solves that somewhat, but I think it could be abstracted further into something that a developer plugin hooks into in order to perform its own profiling.

For example, in Query Monitor I'd like to record the database queries that were performed during each hook callback too.

Could we expose an interface that a developer plugin hooks into in order to trigger its own profiling of each hook callback?

[Rarst]

I got more feedback in line of "just let people plug into it" and I don't feel that is prudent. It invites too much complexity by becoming event system for the event system.

I get your point about nested events, but those can be worked backwards from timing data. As long as you have event boundaries you can reconstruct how they fit within each other. In my Laps plugin this is now done automatically with no need to know the nature of said events.

Trying to do that explicitly is a glob of recursive madness. A hook calling a core function performing an SQL query calling a hook calling a plugin filter performing an SQL query calling a hook... and so on.

So far I am just not convinced there is a specific need for arbitrary extensible system here.

[Rarst]

I've run a rough benchmark with 1 hook x 5 lightweight callbacks x 10,000 executions = 50,000 callback runs.

On my machine this goes from 19ms to 2.8s (memory goes up by several megabytes, but fluctuates a lot).

While if you are firing 50K real–world callbacks — you probably have bigger problems, nevertheless this is probably too heavy to just enable. Constant opt–in then.

Also while playing with this I realized that my initial suggestion is a little too granular. It works well if I already know the hook I am interested in. But it doesn't work well for easily answering questions like "which hooks were slower than N ms".

I think collection should also capture same metrics (start time and duration) for overall hook execution. This will give two levels of granularity to easily detect both hooks and callbacks worth attention.

Will start on a patch and see if anything else comes up.

[schlessera]

Would maybe make more sense to store a single added entry that sums everything:

<?php
[
        'function'      => ...,
        'accepted_args' => ...,
        'profiling'     => [
                'hits'           => ...,
                'total_duration' => ...,
                'fastest'        => ...,
                'slowest'        => ...,
        ],
]

Otherwise, hooks like 'gettext' on their own will already take down servers...

I know that the exact times would be more interesting to you for display purposes, but I think that type of granularity is just not feasible without a dedicated profiling run. It would maybe work on very barebones sites, but on the complex sites where you would actually need the profiling, it would just run out of memory or hit the timeout.

[Rarst]

Define complex and we'll just test it on (eventual) proof of concept?.. Why guess about something that can be measured?

As above on 50K callbacks overhead was noticeable for always-on purposes, but hardly critical or likely to crash.