Как найти самые медленные запросы в Laravel приложении

Сайт тупит? Не грузится? Проверьте свои запросы к базе данных! А я покажу вам как в Laravel сделать это легко и изящно.

Конечно, сайт может работать медленно по многим причинами, но наиболее распространенная — тормозные запросы данных.

В Laravel обычно не используют напрямую SQL для получения данных — всё оборачивается в Eloquent ORM и конструктор запросов, которые затрудняют точное определение, какой именно из запросов вешает сайт.

DB::listen()

К счастью, мы можем задать колбэк, который будет вызываться каждый раз при выполнение запроса к базе данных (подробнее здесь). Для этого добавим следующий код в сервис провайдер (например в AppServiceProvider):

public function boot()
{
    DB::listen(function ($query) {
        // TODO: принести пользу
    });
}

Как вы видите, мы получаем переменную $query, которая является экземпляром класса QueryExecuted.  Она позволит нам получить дополнительную информацию о выполненном запросе:

DB::listen(function ($query) {
    $query->sql; // выполненная sql-строка
    $query->bindings; // параметры, переданные в запрос (то, что подменяет '?' в sql-строке)
    $query->time; // время выполнения запроса
});

С помощью $query->time мы можем отследить медленные запросы. Но у нас всё ещё нет информации, откуда был сделан этот запрос.

Как узнать, где был выполнен запрос?

Не смотря на то, что переменная $query не даёт информации о месте выполнения запроса, но мы можем её получить с помощью встроенной PHP-функции debug_backtrace().

DB::listen(function ($query) {
    dd(debug_backtrace());
});

Если вы запустите её в своём проекте, то получите в браузере что-то вроде этого:

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 [▶]
  ]
  ....

Это массив, содержащий все произошедшие вызовы функций. Но нам будут нужны только ключи file и line.

Ищем местонахождение запроса

Если вы внимательно посмотрите, то увидите, что в моём примере вызваны 63 функции. И это очень много, не смотря на то, что моё приложение достаточно простое. В сложном их будет гораздо больше. Но, обратите внимание, что большинство из них это внутренние функции фреймворка. Нам даже нет смысла их рассматривать.

Все они находятся в каталоге vendor. Значит нам нужно проверить в массиве каждый file и отфильтровать все вызовы из vendor/:

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

Здесь я преобразовываю массив в Коллекцию и использую метод filter. Если текущий file содержит vendor/, то мы удаляем его из коллекции.

Если я запущу код, то увижу в браузере:

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
}

Мы заметно уменьшили стек трассировки. Теперь у нас всего 5 вызовов. И самое приятное, что первый элемент коллекции это именно искомый SQL-запрос. Теперь мы можем извлечь всю нужную нам информацию для поиска самых медленных запросов.

Собираем всё вместе

Давайте всю найденную информацию записывать в журнал, который мы потом можем просматривать и выбирать запросы, которые нужно оптимизировать.

public function boot()
{
    DB::listen(function ($query) {
        $location = collect(debug_backtrace())->filter(function ($trace) {
            return !str_contains($trace['file'], 'vendor/');
        })->first(); // берем первый элемент не из каталога вендора

        $bindings = implode(", ", $query->bindings); // форматируем привязку как строку

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

В файле журнала будут появляться такие записи:

[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
                    ----------

Теперь вы сможете видеть, какие запросы медленные и попытаться их сделать быстрее или хотя бы кэшировать.

Как использовать?

Вы можете генерировать еженедельный отчтёт о самых медленных запросах.

Вы можете настроить отправку уведомлений в Slack, если какой-либо запрос превысит заданное время выполнения.

Вы можете создать интерфейс, где будут отображаться все выполненные запросы.

Автор: Cosme Escobedo
Перевод: Алексей Широков