[Performance] Add spans for plugin initialization and hook execution

[lizozom]

While benchmarking Kibana server's performance, I tried using our APM integration to find performance bottlenecks.
While it was easy to enable and worked well, it was evident that we're missing critical information about the execution of some key functions:

• The preboot, setup and start time of each plugin (should be reported as spans under the kibana-platform transactions).
• The execution time of each hook registered to the http service: PreAuth, Auth, PostAuth, PreRouting, PreResponse. (should be reported as spans under the request transactions).

[elasticmachine]

Pinging @elastic/kibana-core (Team:Core)

[pgayvallet]

The preboot, setup and start time of each plugin

There's no preboot stage for plugins, but apart from that, +1

The execution time of each hook registered to the http service: PreAuth, Auth, PostAuth, PreRouting, PreResponse. (should be reported as spans under the request transactions).

That totally makes sense, just some remarks:

• The execution time of each hook registered to the http service: PreAuth, Auth, PostAuth, PreRouting, PreResponse

ATM we're basically just converting our hook format to HAPI's, e.g:

kibana/src/core/server/http/http_server.ts

Lines 395 to 404 in d5416ed

	private registerOnPreResponse(fn: OnPreResponseHandler) {
	if (this.server === undefined) {
	throw new Error('Server is not created yet');
	}
	if (this.stopping || this.stopped) {
	this.log.warn(`registerOnPreResponse called after stop`);
	}
	this.server.ext('onPreResponse', adoptToHapiOnPreResponseFormat(fn, this.log));
	}

So we'll add to introduce spans in our conversion function, such as adoptToHapiOnPreResponseFormat

Note that we don't have a name/id nor the source (pluginId or core) for such hooks ATM, so we won't be able to display much details. Also, if multiple hooks are registered for the same HAPI lifecycle, it will create one span per handler, as they are executed/converted independently.

• should be reported as spans under the request transactions

Correct me if I'm wrong here, but the request transaction is manually created by APM's internal instrumentation of HAPI, isn't it (couldn't grep any 'request' in core's http code? If that's the case, we can only hope that the spans added explicitly in core will properly be considered as being inside the request transaction.

[afharo]

Huge +1 to this!

I have questions about how to best implement this?

We currently set up transactions during preboot, setup and start. Should we simply call apm.startSpan(pluginName) so we'll see transaction: setup and span: discover or do we want to follow any other specific naming convention to the spans like ${pluginName}-setup?

The execution time of each hook registered to the http service: PreAuth, Auth, PostAuth, PreRouting, PreResponse

Is it enough to set a span to measure each lifecycle step instead of each hook registered in each lifecycle step? I'm wondering how it would affect performance if we start a span for each hook. Also, we may hit the transactionMaxSpans limit.

What do you think?

[lizozom]

@afharo I would consult with the @elastic/apm-agent-node-js team.
I'm sure they would be able to help.

Maybe hit up the #apm-instrumentation-of-stack channel and ask there?