[9.x] Allow handling cumulative query duration limit per DB connection

[timacdonald]

This PR aims to being a nice way to detect and handle when your application has spent a specified cumulative duration querying the database throughout a request / job.

We already have the ability to "handle" what happens when an n+1 is triggered via Eloquent. This PR is in a similar spirit.

The query count isn't always reflective of a "performant" operation, so instead I wanted to be able to track the cumulative duration spent querying the DB for a specific connection.

DB::handleExceedingCumulativeQueryDuration(Interval::seconds(5), function (Connection $connection) {
    Log::warning("Database queries exceeded 5 seconds on {$connection->getName()}");
});

This does differ from the n+1 query handling that already exists in Laravel. The n+1 handler is called on every query, where as these handlers are only ever called a maximum of once per request / job.

DB::handleExceedingCumulativeQueryDuration(Interval::seconds(2), fn ($c) => echo 'handled');

DB::table('users')->get(); // 1 second query; total query time: 1 second;
DB::table('users')->get(); // 1 second query; total query time: 2 seconds;
DB::table('users')->get(); // 1 second query; total query time: 3 seconds;
// echo "handled"
DB::table('users')->get(); // 1 second query; total query time: 4 seconds;
DB::table('users')->get(); // 1 second query; total query time: 5 seconds;
DB::table('users')->get(); // 1 second query; total query time: 6 seconds;
DB::table('users')->get(); // 1 second query; total query time: 7 seconds;

It is important to note that this is all done on a per connection basis.

// default connection...
DB::handleExceedingCumulativeQueryDuration(/* */);

// specific connection...
DB::connection('postgres')->handleExceedingCumulativeQueryDuration(/* */);

Performance

Of course when introducing something around performance, I wanted to be extremely careful about impacting existing performance.

So if you do not utilise this feature, this is the only extra code that is executed for a standard request...

$this->totalQueryDuration += $time ?? 0.0;

this does however mean that even if you don't use this feature directly, you now have a nice way to get the total duration off of a connection...

DB::connection()->totalQueryDuration();

When it comes to the queue worker / octane, they do need to also reset the duration between jobs / requests.

To use the event system or not?!

There is one consideration here. I'm currently hooking into the event dispatcher. If another event that is listening to QueryExecuted returns false, it will mean that our handler will no longer trigger.

So with that in mind, we might want to consider not using the event listener. If this is preferred, I'll refactor this so it doesn't lean on the event dispatcher at all.

Architecture

So this might look a bit strange, but the reason we are holding onto the handlers on the connection instance and doing the whole "not_yet_run" song and dance is that we only want them to run once, but we also need to be able to "restore" the handlers in Octane and on a Queue worker.

Octane PR: laravel/octane#541

Notes

This is an easy starting point for handling slow endpoints / jobs with problematic (slow / many) queries and not a full blown replacement for the slow query log or other metric system, but gives developers some quick insight into their system with little to no extra knowledge / setup.

This is targeting a cumulative total duration, as I feel this where the most value initially lay, what's more is you can already easily handle individual query duration..

DB::enableQueryLog();

DB::listen(function ($event) {
    if ($event->time > 1000) {
        Log::warning("Individual database query exceeded 1 second.");
    }
});

That being said, I can see value in introducing nicely named helper for that as well, but I will introduce a different PR for that, if we are keen on it.

[ankurk91]

How does it work in queue worker?

[timacdonald]

@ankurk91 you should see in the src/Illuminate/Queue/QueueServiceProvider.php that the reset scope closure also resets the duration. This closure is called before attempting to fetch a new job, thus for each job the duration will include the time taken to query the DB for the job payload plus any subsequent queries made during the job execution.

[timacdonald]

as always: naming suggestions welcomed!

[KristianI]

Really cool - I would welcome it :)

[nikolaynizruhin]

Hey Tim 👋
Cool PR! Just naming feels a bit verbose 😬 Maybe something like DB::handleQueryDuration(/* */);?

[ziadoz]

This feature looks neat. Nice work.

The best method name I can come up with instead is: DB::handleQueriesExceedingTotalDuration().

[imrancoder]

    Log::warning("Database queries exceeded 5 seconds on {$connection->getName()}");
});

@timacdonald can you please also share how we can get which query took that much time ?

[timacdonald]

@imrancoder the duration does not mean a single query took that long, but ALL queries combined.

If you just want to track a single query, you can ignore this feature and use

DB::listen()