Profile not matched with transaction about sentry-php HOT 5 CLOSED

microtime(true) returns microseconds, so the initProifler is called ~0,03ms after SENTRY_AUTOLOAD was set.

from sentry-php.

We already confirmed that it's an issue on the Sentry FE. I will link to the PR later.

from sentry-php.

@stayallive So we did debug this, and I think there is some issue with calculating the span durations in the Laravel SDK.

Given the following profile (internal link)

I got the following timestamps:

REQUEST_TIME_FLOAT
1690235634.2881
LARAVEL_START
1690235634.2891
SENTRY_AUTOLOAD
1690235634.296
Time startTransaction
1690235634.2881
Time initProfiler
1690235634.3329
Profile Start Time Stamp
1690235634.3329

And the following samples:

      "samples":[
         {
            "elapsed_since_start_ns":7133916,
            "stack_id":0,
            "thread_id":"0"
         },
         {
            "elapsed_since_start_ns":17597166,
            "stack_id":1,
            "thread_id":"0"
         },
         {
            "elapsed_since_start_ns":29798958,
            "stack_id":2,
            "thread_id":"0"
         }

Doing the math, the profile starts ~7ms after the transaction starts. So I would assume that the `app.bootstrap span is too long.

from sentry-php.

This one is interesting, it's a 75ms request in total (according to our transaction), But there are only 3 samples, which I would expect to be a little more, but that could be due to the way Excimer works.

Reading the code, the profile should start after app.bootstrap, I say this because:

1. We start the transaction, which starts the profile: https://github.com/getsentry/sentry-laravel/blob/a97d5eb2ecc86523dbcca729a75bb70b3f0570fe/src/Sentry/Laravel/Tracing/Middleware.php#L164
2. After that we jump into the code creating the app.bootstrap spans: https://github.com/getsentry/sentry-laravel/blob/a97d5eb2ecc86523dbcca729a75bb70b3f0570fe/src/Sentry/Laravel/Tracing/Middleware.php#L176
3. BUT we already have an end time for it by the time we end up there: https://github.com/getsentry/sentry-laravel/blob/a97d5eb2ecc86523dbcca729a75bb70b3f0570fe/src/Sentry/Laravel/Tracing/Middleware.php#L202
4. This is because: https://github.com/getsentry/sentry-laravel/blob/a97d5eb2ecc86523dbcca729a75bb70b3f0570fe/src/Sentry/Laravel/Tracing/ServiceProvider.php#L37-L39

So the booted event has already taken place and we are merely backdating the app.bootstrap since there was no transaction (or profile) active while the application was bootstrapping (which is a problem to solve another time).

The profile frames are also all descendants of Kernel::handle which runs after the app bootstraps and is the main entrypoint for handling the HTTP request.

But having said all that, I don't see where or why there is only 4ms between the autoload and initProfiler call since I would expect (based on the transasction data) that te quite some later with more like 30ms in between.

SENTRY_AUTOLOAD
1690235634.296
Time initProfiler
1690235634.3329

Anyway, maybe this ramble helps you point out a flaw in my thinking or the code!

from sentry-php.

Fixed in getsentry/sentry#53655

from sentry-php.