How to find the slowest query in your application 
Tags: laravel, php, database, performance
Published: 2022-02-12 20:00:38

Is your website slow? does it take ages to load? Are the users complaining that it's almost _unusable_?. You should check your database queries. And I'm going to show you a neat way to profile all database queries easily.

Of course, your website might be slow for a lot of reasons, but one of the most common reasons is slow database queries. 

But in laravel we don't use SQL (most of the time) to fetch data from our database, we use laravel's [eloquent ORM](https://laravel.com/docs/8.x/eloquent) and [query builder](https://laravel.com/docs/8.x/queries) which sometimes makes it hard to pinpoint that query that is making our site so slow.

## DB::listen()

Fortunately, in laravel, we can define a callback that gets called every time a query gets executed (see [here](https://laravel.com/docs/8.x/database#listening-for-query-events)). To do this add the following code to any service provider (for example the AppServiceProvider):

```php
    public function boot()
    {
        DB::listen(function ($query) {
            // TODO: make this useful
        });
    }
```

As you can see we are receiving a variable $query, this variable is an instance of the [QueryExecuted](https://github.com/laravel/framework/blob/8.x/src/Illuminate/Database/Events/QueryExecuted.php) class. That means that we have access to some information about the query that was executed:

```php
        DB::listen(function ($query) {
            $query->sql; // the sql string that was executed
            $query->bindings; // the parameters passed to the sql query (this replace the '?'s in the sql string)
            $query->time; // the time it took for the query to execute;
        });
```

This is very useful information, now we have a way to identify slow queries by looking at the `$query->time` property. **But this doesn't tell us where the query was executed in our code.**

## How do I know where the query was executed?

Even though the `$query` variable doesn't give us any information about  _where_ that `$query` originated from, we can still get that information using the PHP built-in function [`debug_backtrace()`](https://www.php.net/manual/en/function.debug-backtrace.php).

```php
        DB::listen(function ($query) {
            dd(debug_backtrace());
        });
```
If you run this on your project you will see something like this on the browser:

```
array:63 [▼
  0 => array:7 [▼
    "file" => "/home/cosme/Documents/projects/cosme.dev/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php"
    "line" => 404
    "function" => "App\Providers\{closure}"
    "class" => "App\Providers\AppServiceProvider"
    "object" => App\Providers\AppServiceProvider {#140 ▶}
    "type" => "->"
    "args" => array:1 [▶]
  ]
  1 => array:7 [▼
    "file" => "/home/cosme/Documents/projects/cosme.dev/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php"
    "line" => 249
    "function" => "Illuminate\Events\{closure}"
    "class" => "Illuminate\Events\Dispatcher"
    "object" => Illuminate\Events\Dispatcher {#27 ▶}
    "type" => "->"
    "args" => array:2 [▶]
  ]
  2 => array:7 [▼
    "file" => "/home/cosme/Documents/projects/cosme.dev/vendor/laravel/framework/src/Illuminate/Database/Connection.php"
    "line" => 887
    "function" => "dispatch"
    "class" => "Illuminate\Events\Dispatcher"
    "object" => Illuminate\Events\Dispatcher {#27 ▶}
    "type" => "->"
    "args" => array:1 [▶]
  ]
  ....
```

This is an array containing every function call up to this point on the request. I'm going to focus only on the `file` and `line` keys in each array.

If you look closely you can see that in my example there were 63 function calls, which can be considered a lot, and this is a simple application, in a more complicated one, there might be a lot more. To make matters worse if you look at the ones at the top, **all are internal functions to the laravel framework**. Are we supposed to look at each one until we find something that might help us?

## Finding the query location

As I said before most of them are internal framework calls, which means that most of those files are inside our `vendor/` directory. That means that we can check each `file` and filter out any call that has `vendor/`, like this: 

```php
        DB::listen(function ($query) {
            $stackTrace = collect(debug_backtrace())->filter(function ($trace) {
                return !str_contains($trace['file'], 'vendor/');
            });
            
            dd($stackTrace);
        });
```

Here I'm converting the array into a collection to use the `filter` method, if the `file` of the current `$trace` has `vendor/` we remove it from the collection. 

If you run the code above, you will see something like this:

```
Illuminate\Support\Collection {#1237 ▼
  #items: array:5 [▼
    12 => array:7 [▼
      "file" => "/home/cosme/Documents/projects/cosme.dev/app/Models/Post.php"
      "line" => 61
      "function" => "get"
      "class" => "Illuminate\Database\Eloquent\Builder"
      "object" => Illuminate\Database\Eloquent\Builder {#310 ▶}
      "type" => "->"
      "args" => []
    ]
    16 => array:6 [▶]
    17 => array:6 [▶]
    61 => array:7 [▶]
    62 => array:4 [▶]
  ]
  #escapeWhenCastingToString: false
}
``` 

Those are a lot fewer items, *we went from 63 to only 5*. And the best part is that the first item in the collection is the exact place where we triggered the SQL query. That means that we can extract that information to find the slowest queries.


## Putting it all together 

Now that we have all the information that we need, why don't we log it so we can check and look for the slowest queries?:

```php

    public function boot()
    {
        DB::listen(function ($query) {
            $location = collect(debug_backtrace())->filter(function ($trace) {
                return !str_contains($trace['file'], 'vendor/');
            })->first(); // grab the first element of non vendor/ calls

            $bindings = implode(", ", $query->bindings); // format the bindings as string

            Log::info("
                   ------------
                   Sql: $query->sql
                   Bindings: $bindings
                   Time: $query->time
                   File: ${location['file']}
                   Line: ${location['line']}
                   ------------
            ");
        });
    }
```

If you use this in your application you can then check your log file and you should see the queries information like this:

```
[2022-02-03 02:20:14] local.INFO:
                    ------------
                    Sql: select "title", "slug", "body" from "posts" where "published" = ? order by "id" desc   
                    Bindings: 1
                    Time: 0.18
                    File: /home/cosme/Documents/projects/cosme.dev/app/Models/Post.php
                    Line: 61
                    ----------
```

Now you know what queries are the slowest and start tackling them one by one, try to make them faster, or at the very least cache them.

## Beyond debugging 

This is very useful for debugging but this technique can be used in a multitude of ways.


*You could create a weekly report showing the slowest queries of the week.*

*You could get a slack alert if a query exceeds a time threshold*

*You could create a dashboard where you and your team could see every query executed*

The sky is the limit.

If you liked this, [**follow me on twitter**](https://twitter.com/cosmeescobedo) so you can find out about my other Laravel experiments as I try them.