Debugowanie Wolnych Zapytań w Laravel: Programistyczne Logowanie Ponad Telescope

Każda aplikacja Laravel w końcu napotyka wolny endpoint. Gdzieś tam czai się zapytanie - pobiera za dużo danych, brakuje mu indeksu albo odpala się pięćdziesiąt razy w pętli. Telescope i Debugbar świetnie sprawdzają się podczas lokalnego developmentu, ale nic nie pomogą, gdy musisz przechwycić zachowanie zapytań programatycznie, zapisać je do pliku albo zbudować middleware aktywowany na żądanie w środowisku stagingowym. Ten artykuł pokazuje dokładnie, jak to zrobić.

📋 Spis treści

• 🔍 DB::listen() - Obserwowanie zapytań na żywo
• 📋 DB::enableQueryLog() - Przechwytywanie i analiza
• 🛠️ Budowanie middleware QueryLogger
• 🔬 Czytanie EXPLAIN - Co MySQL naprawdę robi
• ⚠️ Wzorce, które zabijają wydajność
• 🚀 Dev vs Produkcja - Co włączać i kiedy
• 🧱 MySQL Slow Query Log - Pełny obraz
• ✅ Podsumowanie

🔍 DB::listen() - Obserwowanie zapytań na żywo

DB::listen() rejestruje callback, który odpala się po każdym wykonanym zapytaniu SQL w bieżącym cyklu życia requestu. Otrzymuje zdarzenie QueryExecuted z SQL-em, bindingami i czasem wykonania.

Najprostszy przypadek użycia to wyrzucanie zapytań podczas lokalnego debugowania:

// app/Providers/AppServiceProvider.php

declare(strict_types=1);

namespace App\Providers;

use Illuminate\Database\Events\QueryExecuted;
use Illuminate\Support\Facades\DB;
use Illuminate\Support\ServiceProvider;

class AppServiceProvider extends ServiceProvider
{
    public function boot(): void
    {
        if (config('app.debug')) {
            DB::listen(function (QueryExecuted $query) {
                logger()->debug('Wykonano zapytanie', [
                    'sql'      => $query->sql,
                    'bindings' => $query->bindings,
                    'time_ms'  => $query->time,
                ]);
            });
        }
    }
}

Możesz też filtrować po progu - logować tylko wolne zapytania:

// app/Providers/AppServiceProvider.php

DB::listen(function (QueryExecuted $query) {
    if ($query->time > 100) { // ms
        logger()->warning('Wykryto wolne zapytanie', [
            'sql'     => $query->sql,
            'time_ms' => $query->time,
            'caller'  => collect(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 8))
                ->map(fn($t) => ($t['class'] ?? '') . '@' . ($t['function'] ?? ''))
                ->filter(fn($s) => str_contains($s, 'App\\'))
                ->values()
                ->first(),
        ]);
    }
});

Trick z debug_backtrace pozwala zawęzić, która klasa rzeczywiście wywołała zapytanie - przydatne przy warstwowych serwisach, gdy nie wiadomo od razu, skąd pochodzi wywołanie.

Kiedy używać DB::listen():

• Alerty progowe podczas developmentu (> 100ms → log warning)
• Zbieranie metryk w custom serwisie (liczba zapytań per request)
• Debugowanie w czasie rzeczywistym bez uruchamiania Telescope

Kiedy nie używać: Odpala się synchronicznie. Ciężkie callbacki spowalniają każdy request.

📋 DB::enableQueryLog() - Przechwytywanie i analiza

DB::enableQueryLog() buforuje każde zapytanie wykonane po jego wywołaniu. DB::getQueryLog() zwraca pełną listę w dowolnym momencie. W odróżnieniu od DB::listen(), zbiera wszystko do pamięci i udostępnia je do późniejszej inspekcji.

// routes/web.php (szybki lokalny debug - nie commitować!)

Route::get('/debug-orders', function () {
    DB::enableQueryLog();

    $orders = \App\Models\Order::with('items.product')
        ->where('status', 'pending')
        ->get();

    $log = DB::getQueryLog();

    return response()->json([
        'query_count' => count($log),
        'total_ms'    => collect($log)->sum('time'),
        'queries'     => $log,
    ]);
});

Tablica zwracana dla każdego wpisu ma następującą strukturę:

[
    'query'    => 'select * from `orders` where `status` = ?',
    'bindings' => ['pending'],
    'time'     => 4.21, // milisekundy
]

Praktyczny wzorzec - liczenie zapytań w teście:

// tests/Feature/OrderIndexTest.php

declare(strict_types=1);

use App\Models\Order;
use Illuminate\Support\Facades\DB;

it('ładuje zamówienia bez zapytań N+1', function () {
    Order::factory()->count(20)->hasItems(3)->create();

    DB::enableQueryLog();

    $this->getJson('/api/v1/orders')->assertOk();

    expect(DB::getQueryLog())->toHaveCount(2); // orders + eager-loaded items
});

To jeden z najczystszych sposobów wymuszania zapobiegania N+1 na poziomie testów - bez żadnej zewnętrznej paczki.

🛠️ Budowanie middleware QueryLogger

Prawdziwa siła tkwi w połączeniu obu narzędzi w middleware aktywowanym na żądanie - bez deployu, bez dotykania kodu i bez globalnego włączania trybu debug.

// app/Http/Middleware/QueryLogger.php

declare(strict_types=1);

namespace App\Http\Middleware;

use Closure;
use Illuminate\Http\Request;
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Log;
use Symfony\Component\HttpFoundation\Response;

class QueryLogger
{
    public function handle(Request $request, Closure $next): Response
    {
        if ($this->shouldLog($request)) {
            DB::enableQueryLog();
        }

        return $next($request);
    }

    public function terminate(Request $request, Response $response): void
    {
        if (! $this->shouldLog($request)) {
            return;
        }

        try {
            $queries   = DB::getQueryLog();
            $total     = count($queries);
            $timeMs    = array_sum(array_column($queries, 'time'));
            $timestamp = now()->format('Ymd_His_u');
            $path      = storage_path("logs/query_debug_{$timestamp}.json");

            file_put_contents($path, json_encode([
                'request'  => $request->method() . ' ' . $request->fullUrl(),
                'summary'  => [
                    'total_queries' => $total,
                    'total_time_ms' => round($timeMs, 2),
                ],
                'queries'  => $queries,
            ], JSON_PRETTY_PRINT));

            Log::info('QueryLogger zapisany', ['path' => $path, 'total' => $total]);
        } catch (\Throwable $e) {
            Log::error('QueryLogger nie powiódł się: ' . $e->getMessage());
        }
    }

    private function shouldLog(Request $request): bool
    {
        return config('app.debug')
            && ($request->hasHeader('X-Debug-Queries') || $request->has('debug_queries'));
    }
}

Zarejestruj middleware w stosie:

// bootstrap/app.php

declare(strict_types=1);

use App\Http\Middleware\QueryLogger;

return Application::configure(basePath: dirname(__DIR__))
    ->withMiddleware(function ($middleware) {
        $middleware->append(QueryLogger::class);
    })
    ->create();

Aktywuj go nagłówkiem:

curl -H "X-Debug-Queries: 1" https://staging.example.com/api/v1/orders

Wynikowy plik wygląda tak:

{
  "request": "GET https://staging.example.com/api/v1/orders",
  "summary": {
    "total_queries": 47,
    "total_time_ms": 312.45
  },
  "queries": [
    {
      "query": "select * from `orders` where `user_id` = ?",
      "bindings": [42],
      "time": 6.21
    }
  ]
}

47 zapytań dla jednego endpointu to bardzo czytelny sygnał N+1 do naprawy. Plik daje pełny obraz bez żadnego narzutu toolingowego.

Uwaga dotycząca bezpieczeństwa: Guard shouldLog() sprawdza app.debug. Nigdy nie zostawiaj tego middleware włączonego na produkcji z APP_DEBUG=true. Na stagingu ustaw flagę i używaj nagłówka tylko wtedy, gdy rzeczywiście tego potrzebujesz.

🔬 Czytanie EXPLAIN - Co MySQL naprawdę robi

Gdy masz już wolne zapytanie z logu, kolejnym krokiem jest uruchomienie EXPLAIN, żeby zrozumieć, co MySQL z nim robi.

EXPLAIN SELECT * FROM orders WHERE user_id = 42 AND status = 'pending';

Najważniejsze kolumny:

Przykład - przed dodaniem indeksu:

EXPLAIN SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC;

-- type: ALL | key: NULL | rows: 94823 | Extra: Using filesort

Skanowanie 94 tys. wierszy z filesort - na skali to boli. Naprawa:

// database/migrations/2026_03_01_add_index_to_orders_table.php

declare(strict_types=1);

use Illuminate\Database\Migrations\Migration;
use Illuminate\Database\Schema\Blueprint;
use Illuminate\Support\Facades\Schema;

return new class extends Migration
{
    public function up(): void
    {
        Schema::table('orders', function (Blueprint $table) {
            $table->index(['status', 'created_at']);
        });
    }

    public function down(): void
    {
        Schema::table('orders', function (Blueprint $table) {
            $table->dropIndex(['status', 'created_at']);
        });
    }
};

Po migracji:

EXPLAIN SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC;

-- type: ref | key: orders_status_created_at_index | rows: 312 | Extra: Using index condition

Z 94 tys. wierszy do 312. Indeks złożony na (status, created_at) pokrywa zarówno filtr WHERE, jak i ORDER BY w jednym skanie.

EXPLAIN ANALYZE (MySQL 8.0+) idzie dalej - naprawdę wykonuje zapytanie i pokazuje rzeczywiste czasy:

EXPLAIN ANALYZE SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 20;

-- -> Limit: 20 row(s)  (actual time=0.312..0.318 rows=20 loops=1)
--    -> Index lookup on orders using orders_status_created_at_index (status='pending')
--       (actual time=0.298..0.312 rows=20 loops=1)

Rzeczywisty czas: 0.318ms. Przed indeksem było 340ms. Najpierw dodaj indeks, potem myśl o cache.

⚠️ Wzorce, które zabijają wydajność

To wzorce, które najczęściej pojawiają się w query logu:

1. Brak select() - ładowanie wszystkiego

// Źle - ładuje wszystkie 40 kolumn, serializuje wszystko
$users = User::all();

// Dobrze - tylko to, czego endpoint potrzebuje
$users = User::select('id', 'name', 'email')->get();

2. Wildcard LIKE z wiodącym %

// Źle - nie może użyć indeksu, zawsze pełny skan
User::where('email', 'LIKE', '%@example.com')->get();

// Lepiej - końcowy wildcard może użyć indeksu
User::where('email', 'LIKE', 'jan%')->get();

// Najlepiej do pełnotekstowego wyszukiwania - użyj Laravel Scout

3. Podzapytanie w pętli

// Źle - jedno zapytanie per zamówienie (N+1 w przebraniu)
foreach ($orders as $order) {
    $order->total = $order->items()->sum('price');
}

// Dobrze - agregat w jednym zapytaniu
$orders = Order::withSum('items', 'price')->get();
// Dostęp: $order->items_sum_price

4. orderBy() na kolumnie bez indeksu

// Źle - filesort na created_at bez indeksu
Product::where('category_id', 5)->orderBy('created_at')->get();

// Naprawa: dodaj index(['category_id', 'created_at'])

5. Wielokrotny count() na tej samej relacji

// Źle - jedno zapytanie COUNT per post w pętli
foreach ($posts as $post) {
    echo $post->comments()->count();
}

// Dobrze - jedno zapytanie dla wszystkich liczników
$posts = Post::withCount('comments')->get();
// Dostęp: $post->comments_count

🚀 Dev vs Produkcja - Co włączać i kiedy

Złota zasada: nigdy nie zostawiaj DB::enableQueryLog() włączonego globalnie na produkcji. Buforuje wszystkie zapytania w pamięci dla każdego requestu. Pod obciążeniem to wyciek pamięci.

Na produkcji właściwym narzędziem jest MySQL slow query log (następna sekcja).

🧱 MySQL Slow Query Log - Pełny obraz

Gdy logowanie na poziomie Laravela jest wyłączone, MySQL nadal może wychwytywać wolne zapytania na poziomie bazy danych. Działa to niezależnie od kodu aplikacji.

Włącz go w my.cnf (lub my.ini na Windows):

# /etc/mysql/mysql.conf.d/mysqld.cnf

slow_query_log         = 1
slow_query_log_file    = /var/log/mysql/slow.log
long_query_time        = 1
log_queries_not_using_indexes = 1

• long_query_time = 1 - loguj zapytania trwające ponad 1 sekundę
• log_queries_not_using_indexes = 1 - wychwytuje pełne skany nawet gdy są teraz szybkie

Zrestartuj MySQL i obserwuj log:

sudo tail -f /var/log/mysql/slow.log

Wynik zawiera zapytanie, użytkownika, host i dokładne czasy:

# Time: 2026-03-13T08:42:11
# Query_time: 2.341  Lock_time: 0.000  Rows_sent: 1  Rows_examined: 94823
SELECT * FROM orders WHERE status = 'pending' ORDER BY created_at DESC LIMIT 1;

Skrzyżuj to z wynikiem QueryLogger - jeśli to samo zapytanie pojawia się w obu miejscach, masz potwierdzony wąskie gardło. Użyj mysqldumpslow do agregacji i rankingu:

mysqldumpslow -s t -t 10 /var/log/mysql/slow.log

Pokazuje 10 najwolniejszych zapytań według łącznego czasu. W Dockerze dodaj konfigurację slow logu do usługi MySQL:

# docker-compose.yml

services:
  mysql:
    image: mysql:8.0
    command: >
      --slow_query_log=1
      --slow_query_log_file=/var/log/mysql/slow.log
      --long_query_time=1
      --log_queries_not_using_indexes=1
    volumes:
      - mysql_logs:/var/log/mysql

✅ Podsumowanie

• Używaj DB::listen() do logowania progowego podczas developmentu - filtruj do > 100ms i zapisuj do laravel.log
• Używaj DB::enableQueryLog() w testach do wymuszania maksymalnych liczb zapytań i wychwytywania regresji N+1 przed produkcją
• Middleware QueryLogger to narzędzie na żądanie dla stagingu - aktywuj nagłówkiem, dostań plik JSON, wyłącz bez deployu
• EXPLAIN mówi, co MySQL planuje zrobić; EXPLAIN ANALYZE mówi, co naprawdę zrobił - uruchamiaj oba przed i po dodaniu indeksu
• Najpierw napraw zapytanie, dodaj indeks jako drugi krok, cache na końcu - w tej kolejności
• MySQL slow query log wychwytuje to, co umknie toolingowi na poziomie aplikacji, szczególnie podczas okien dużego ruchu

Obserwuj mnie na LinkedIn po więcej tipów z Laravel! Chcesz zobaczyć głębsze omówienie optymalizacji zapytań z indeksami złożonymi i covering indexes? Daj znać w komentarzach!