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 and query builder 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). To do this add the following code to any service provider (for example the AppServiceProvider):

    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 class. That means that we have access to some information about the query that was executed:

        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().

        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:

        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?:

    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 so you can find out about my other Laravel experiments as I try them.