Как посмотреть время запроса в PostgreSQL?

Мониторинг времени запросов в PostgreSQL: Практический гайд

Мониторинг производительности запросов — это критический навык для оптимизации. Я использую несколько подходов в зависимости от задачи.

Способ 1: EXPLAIN для анализа плана выполнения

Базовый EXPLAIN

-- Посмотреть план выполнения запроса
EXPLAIN
SELECT * FROM users WHERE email = 'john@example.com';

-- Output:
-- Seq Scan on users (cost=0.00..35.50 rows=1 width=512)
--   Filter: (email = 'john@example.com')

EXPLAIN ANALYZE — с фактическими временами

-- Это ВЫПОЛНЯЕТ запрос и показывает реальное время
EXPLAIN ANALYZE
SELECT * FROM users WHERE email = 'john@example.com';

-- Output:
-- Seq Scan on users (cost=0.00..35.50 rows=1 width=512) (actual time=0.123..0.456 rows=1 loops=1)
--   Filter: (email = 'john@example.com')
-- Planning Time: 0.234 ms
-- Execution Time: 0.678 ms

Интерпретация:

• cost=0.00..35.50 — оценённая стоимость (в условных единицах)
• actual time=0.123..0.456 — реальное время (мин..макс в миллисекундах)
• rows=1 — количество строк
• Planning Time — время на планирование запроса
• Execution Time — время на выполнение

EXPLAIN с BUFFERS

-- Показывает использование буфера (памяти)
EXPLAIN (ANALYZE, BUFFERS)
SELECT u.id, u.email, COUNT(p.id) as post_count
FROM users u
LEFT JOIN posts p ON u.id = p.user_id
WHERE u.created_at > '2025-01-01'
GROUP BY u.id, u.email;

-- Output:
-- Aggregate (cost=1500.00..1502.00 rows=100 width=40) (actual time=45.123..45.456 rows=85 loops=1)
--   Buffers: shared hit=1234 read=56 written=0
--   -> Hash Join (cost=500.00..1400.00 rows=500 width=40) (actual time=10.234..40.123 rows=500 loops=1)

Что означают Buffers:

• shared hit=1234 — прочитано из памяти (кэша)
• shared read=56 — прочитано с диска
• written=0 — записано на диск

Способ 2: TIMING через psql

psql -U postgres -d mydatabase

-- Включить таймер
\timing
Timing is on.

-- Запрос выполнится с показом времени
SELECT * FROM users WHERE id = 1;
-- Time: 0.123 ms

-- Включить более подробную информацию
\timing detailed

-- Отключить
\timing

Способ 3: log_statement и log_duration в конфиге

Конфигурация PostgreSQL

# /etc/postgresql/14/main/postgresql.conf

# Логировать все запросы дольше 1 секунды
log_min_duration_statement = 1000  # в миллисекундах

# Логировать время выполнения для каждого запроса
log_duration = on

# Логировать сам запрос
log_statement = 'all'  # 'all', 'ddl', 'mod', or 'none'

# Уровень логирования
log_level = 'info'

# Формат логов
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h '

Просмотр логов

# На Linux
tail -f /var/log/postgresql/postgresql.log

# Поиск медленных запросов
grep "duration:" /var/log/postgresql/postgresql.log | sort -t: -k3 -rn | head

# На Docker
docker logs -f postgres_container

Способ 4: pg_stat_statements расширение

Это мощный инструмент для отслеживания всех запросов.

Установка

-- Создать расширение (нужны права superuser)
CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

-- Проверить
SELECT * FROM pg_stat_statements LIMIT 1;

Использование

-- Топ самых медленных запросов
SELECT
    query,
    calls,
    total_exec_time,
    mean_exec_time,
    max_exec_time,
    stddev_exec_time
FROM pg_stat_statements
ORDER BY mean_exec_time DESC
LIMIT 10;

-- Output:
-- query                          | calls | total_exec_time | mean_exec_time | max_exec_time
-- SELECT * FROM users WHERE...  |  1000 |      45678.123  |      45.678    |      234.567

-- Запросы с наибольшим общим временем
SELECT
    query,
    calls,
    total_exec_time,
    mean_exec_time
FROM pg_stat_statements
WHERE query NOT LIKE 'pg_stat_statements%'
ORDER BY total_exec_time DESC
LIMIT 5;

-- Самые частые запросы
SELECT
    query,
    calls,
    mean_exec_time
FROM pg_stat_statements
ORDER BY calls DESC
LIMIT 10;

-- Сбросить статистику
SELECT pg_stat_statements_reset();

Способ 5: Django ORM и логирование SQL

# settings.py
DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.postgresql',
        'NAME': 'mydatabase',
    }
}

# Логирование SQL запросов
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        'django.db.backends': {
            'handlers': ['console'],
            'level': 'DEBUG',  # Показывает все SQL запросы
        },
    },
}

# В коде
from django.test.utils import CaptureQueriesContext
from django.db import connection

with CaptureQueriesContext(connection) as ctx:
    users = User.objects.filter(email='john@example.com')
    for user in users:
        print(user.name)

for query in ctx.captured_queries:
    print(f"Time: {query['time']}")
    print(f"SQL: {query['sql']}")

# Или просто смотреть время
from django.utils.decorators import decorator_from_middleware
from django.middleware.gzip import GZipMiddleware

# Включить debug mode для development
# Settings: DEBUG = True
# Тогда доступен: django.db.connection.queries

from django.db import connection, reset_queries
from django.conf import settings

if settings.DEBUG:
    reset_queries()
    users = User.objects.filter(email='john@example.com')
    for query in connection.queries:
        print(f"Execution time: {query['time']} seconds")
        print(f"Query: {query['sql']}")

Способ 6: asyncpg с таймингом (для асинхронного кода)

import asyncpg
import time

async def timed_query():
    # Подключение к PostgreSQL
    conn = await asyncpg.connect('postgresql://user:password@localhost/mydb')
    
    start = time.perf_counter()
    
    result = await conn.fetch('SELECT * FROM users WHERE email = $1', 'john@example.com')
    
    elapsed = time.perf_counter() - start
    
    print(f"Query time: {elapsed:.4f} seconds")
    print(f"Rows returned: {len(result)}")
    
    await conn.close()
    return result

Способ 7: psycopg2 с timeit

import psycopg2
import timeit

# Подключение
conn = psycopg2.connect(
    dbname='mydb',
    user='postgres',
    password='password',
    host='localhost'
)
cur = conn.cursor()

# Способ 1: Простой timer
import time

start = time.perf_counter()
cur.execute('SELECT * FROM users WHERE email = %s', ('john@example.com',))
rows = cur.fetchall()
elapsed = time.perf_counter() - start

print(f"Execution time: {elapsed:.4f} seconds")
print(f"Rows: {len(rows)}")

# Способ 2: timeit для точного измерения
def query():
    cur.execute('SELECT COUNT(*) FROM users')
    return cur.fetchone()[0]

time_taken = timeit.timeit(query, number=1000)
print(f"Average time per query: {time_taken/1000:.6f} seconds")

cur.close()
conn.close()

Практический пример: Профилирование медленного запроса

-- 1. Сначала просто запустить EXPLAIN ANALYZE
EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON)
SELECT u.id, u.email, p.title, COUNT(c.id) as comment_count
FROM users u
JOIN posts p ON u.id = p.user_id
LEFT JOIN comments c ON p.id = c.post_id
WHERE u.status = 'active'
GROUP BY u.id, u.email, p.title
ORDER BY comment_count DESC
LIMIT 10;

-- 2. Результат в JSON (удобнее для анализа)
-- {
--   "Plan": {
--     "Node Type": "Limit",
--     "Actual Total Time": 234.567,
--     "Execution Time": 234.567
--   }
-- }

-- 3. Проверить наличие индексов
SELECT * FROM pg_stat_user_indexes;

-- 4. Если нужен индекс
CREATE INDEX idx_users_status ON users(status);
CREATE INDEX idx_posts_user_id ON posts(user_id);
CREATE INDEX idx_comments_post_id ON comments(post_id);

-- 5. Запустить EXPLAIN ANALYZE заново
EXPLAIN ANALYZE ...
-- Время должно улучшиться

Итоговая шпаргалка

Лучшие практики

-- 1. Используй EXPLAIN ANALYZE для оптимизации
EXPLAIN (ANALYZE, BUFFERS)
SELECT ...

-- 2. Смотри на Execution Time, а не на Planning Time
-- (обычно Execution Time > Planning Time)

-- 3. Ищи Seq Scan вместо Index Scan
-- Seq Scan = полный просмотр таблицы (медленно)
-- Index Scan = использование индекса (быстро)

-- 4. Мониторь с pg_stat_statements в production
-- это даст тебе реальную картину нагрузки

Главный совет: Всегда используй EXPLAIN ANALYZE, чтобы увидеть реальное время выполнения и план выполнения. Это даст тебе информацию для оптимизации запросов.