Skip to content

feat: add kernel boot time as tracing attribute#13

Open
cyve wants to merge 1 commit intoworldia:masterfrom
cyve:feat/attribute-kernel-boot-time
Open

feat: add kernel boot time as tracing attribute#13
cyve wants to merge 1 commit intoworldia:masterfrom
cyve:feat/attribute-kernel-boot-time

Conversation

@cyve
Copy link
Collaborator

@cyve cyve commented Oct 22, 2022

Add sf.kernel_boot_duration attribute to the trace containing the elapsed time between the very beginning of the request and the dispatch of the kernel.request event (in HTTP) or the kernel.console event (in CLI), representing the booting duration of the Symfony Kernel.
This is useful when we try to improve the Symfony configuration to speed up the kernel boot.

Comment on lines +49 to +50
$startTime = $_SERVER['REQUEST_TIME_FLOAT'] ?? microtime(true); // Float with microsecond precision
$kernelBootTime = round(microtime(true) - $startTime, 3);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think REQUEST_TIME_FLOAT is always present, no matter what.
I would also suggest to move that has first instruction, if microseconds matters lets be as precise as possible.

Suggested change
$startTime = $_SERVER['REQUEST_TIME_FLOAT'] ?? microtime(true); // Float with microsecond precision
$kernelBootTime = round(microtime(true) - $startTime, 3);
$startTimeInMs = $_SERVER['REQUEST_TIME_FLOAT'];
$kernelBootTime = round(microtime(true) - $startTimeInMs, 3);

I don't find how to add a comment on a line that you did not modify so I put it here:
You must change the priority of the event, a lot of listeners (sentry, monolog, debug, dump, etc) have a higher priority. Otherwise it's not really the "kernel boot time".

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@camilledejoye Are you saying that REQUEST_TIME_FLOAT is set in CLI sapi context?

public function onRequestEvent(Event\RequestEvent $event): void
{
$request = $event->getRequest();
$startTime = $request->server->get('REQUEST_TIME_FLOAT'); // Float with microsecond precision
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As before I suggest to retrieve the current time as soon as possible.
And remove the comment since a name has the advantage of providing the information everywhere it's used and not becoming stale.

Suggested change
$startTime = $request->server->get('REQUEST_TIME_FLOAT'); // Float with microsecond precision
$startTimeInMs = $request->server->get('REQUEST_TIME_FLOAT');
$currentTimeInMs = microtime(true);

As for the commands, there is other subscribers/listeners being executing before this one.
As a reminder bin/console debug:event-dispatcher kernel.request list those registered in a SF application with their priority.

@cdaguerre
Copy link
Member

Why would this be an attribute? Shouldn't it be considered as a subspan?

@cdaguerre cdaguerre force-pushed the master branch 3 times, most recently from 80cb469 to a8ef73a Compare January 31, 2023 12:33
@cdaguerre cdaguerre force-pushed the master branch 2 times, most recently from 633595f to cee36ca Compare March 12, 2024 10:36
@cdaguerre cdaguerre force-pushed the master branch 19 times, most recently from 8b71925 to a8fc0aa Compare January 12, 2025 08:40
@cdaguerre
Copy link
Member

It's not really the kernel boot duration, more the time between fpm level request start and dispatching of the KERNEL_REQUEST event.

@cdaguerre cdaguerre force-pushed the master branch 6 times, most recently from 9aec428 to 890bfba Compare January 14, 2025 13:09
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

Comments