Как посмотреть реальное время выполнения запроса?

Как посмотреть реальное время выполнения запроса

Профилирование и мониторинг времени выполнения — критические навыки для оптимизации приложения. Покажу все способы от простейших до production решений.

1. Базовое измерение: модуль time

Простейший способ:

import time
import requests

start = time.time()
response = requests.get("https://api.example.com/data")
end = time.time()

duration = end - start
print(f"Запрос выполнен за {duration:.3f} секунд")  # 0.245 секунд

Более точный способ (perf_counter):

import time

# time.time() может быть неточным, используй time.perf_counter()
start = time.perf_counter()
response = requests.get("https://api.example.com/data")
end = time.perf_counter()

duration = end - start
print(f"Время выполнения: {duration:.3f}s")

Декоратор для функций:

import time
from functools import wraps

def measure_time(func):
    """Декоратор для измерения времени выполнения функции."""
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        result = func(*args, **kwargs)
        end = time.perf_counter()
        
        duration = end - start
        print(f"{func.__name__} выполнена за {duration:.3f}s")
        return result
    
    return wrapper

@measure_time
def slow_function():
    import time
    time.sleep(1)
    return "done"

slow_function()  # slow_function выполнена за 1.002s

2. Контекстный менеджер для блоков кода

import time
from contextlib import contextmanager

@contextmanager
def timer(name: str = "Operation"):
    """Контекстный менеджер для измерения времени."""
    start = time.perf_counter()
    try:
        yield
    finally:
        end = time.perf_counter()
        duration = end - start
        print(f"{name}: {duration:.3f}s")

# Использование
with timer("Загрузка данных"):
    data = load_large_file()

with timer("Обработка"):
    processed = process_data(data)

# Output:
# Загрузка данных: 0.245s
# Обработка: 1.234s

3. Встроенный timeit модуль

Для микро-бенчмарков:

import timeit

# Способ 1: простая функция
time_taken = timeit.timeit(
    lambda: [i for i in range(1000)],
    number=10000
)
print(f"10000 итераций заняло {time_taken:.3f}s")  # ~0.45s

# Способ 2: сравнение методов
setup = "x = list(range(1000))"

method1_time = timeit.timeit(
    "y = x.copy()",
    setup=setup,
    number=10000
)

method2_time = timeit.timeit(
    "y = x[:]",
    setup=setup,
    number=10000
)

print(f"copy(): {method1_time:.3f}s")
print(f"[:]:    {method2_time:.3f}s")

# Результат: [:] немного быстрее

4. Профилирование с cProfile

Узнать какие функции занимают больше всего времени:

import cProfile
import pstats
import io

def main():
    # Твой код
    result = [i ** 2 for i in range(100000)]
    sorted_result = sorted(result)
    return sorted_result

# Профилировать
profiler = cProfile.Profile()
profiler.enable()

main()

profiler.disable()

# Вывести статистику
stats = pstats.Stats(profiler)
stats.sort_stats('cumulative')
stats.print_stats(10)  # Топ 10 функций

Вывод:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.001    0.001    0.002    0.002 script.py:1(main)
    1    0.001    0.001    0.001    0.001 {built-in method sorted}

5. Запись профиля в файл

import cProfile

def slow_app():
    # Твоё приложение
    pass

cProfile.run('slow_app()', 'profile_stats')

# Анализ
import pstats
stats = pstats.Stats('profile_stats')
stats.sort_stats('cumulative')
stats.print_stats(20)

6. Flask-specific: встроенный профайлер

from flask import Flask
from werkzeug.contrib.profiler import ProfilerMiddleware

app = Flask(__name__)
app.wsgi_app = ProfilerMiddleware(app.wsgi_app)

@app.route('/data')
def get_data():
    return {'data': 'result'}

# При каждом запросе будет выведена статистика профайлера
if __name__ == '__main__':
    app.run(debug=True)

7. FastAPI middleware для логирования времени

from fastapi import FastAPI
from starlette.middleware.base import BaseHTTPMiddleware
import time
import logging

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

app = FastAPI()

class TimingMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        start = time.perf_counter()
        response = await call_next(request)
        end = time.perf_counter()
        
        duration = end - start
        logger.info(
            f"{request.method} {request.url.path} "
            f"completed in {duration:.3f}s"
        )
        
        response.headers["X-Process-Time"] = str(duration)
        return response

app.add_middleware(TimingMiddleware)

8. Логирование времени в запросах к БД

SQLAlchemy event listener:

from sqlalchemy import event
from sqlalchemy.engine import Engine
import time
import logging

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

@event.listens_for(Engine, "before_cursor_execute")
def before_cursor_execute(conn, cursor, statement, parameters, context, executemany):
    conn.info.setdefault('query_start_time', []).append(time.perf_counter())

@event.listens_for(Engine, "after_cursor_execute")
def after_cursor_execute(conn, cursor, statement, parameters, context, executemany):
    total = time.perf_counter() - conn.info['query_start_time'].pop(-1)
    logger.info(f"SQL Query executed in {total:.3f}s")
    logger.info(f"Query: {statement}")

# Теперь все SQL запросы будут залогированы с временем

9. Requests library с встроенным timing

import requests

response = requests.get('https://api.example.com/data')

# Получить информацию о времени
print(f"Время подключения: {response.elapsed.total_seconds():.3f}s")

# Детальная информация (с расширением requests-timing)
from requests import Session

session = Session()
response = session.get('https://api.example.com/data')

# Информация о запросе
print(f"URL: {response.url}")
print(f"Статус: {response.status_code}")
print(f"Время: {response.elapsed.total_seconds():.3f}s")

10. py-spy для production профилирования

Снять профиль боевого приложения:

# Установить py-spy
pip install py-spy

# Снять профиль приложения (PID 12345)
py-spy record -p 12345 -o profile.svg

# Или запустить приложение с профилированием
py-spy record -o profile.svg -- python app.py

# Будет создан SVG файл с flame graph
# Открой в браузере и кликай на блоки для деталей

11. Полный пример: профилирование API

from fastapi import FastAPI
from datetime import datetime
import logging
import time
from typing import Callable

app = FastAPI()
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

class PerformanceTracker:
    def __init__(self):
        self.metrics = []
    
    def log_request(self, method: str, path: str, duration: float, status_code: int):
        self.metrics.append({
            "timestamp": datetime.now(),
            "method": method,
            "path": path,
            "duration": duration,
            "status_code": status_code
        })
        
        logger.info(
            f"{method} {path} - {status_code} - {duration*1000:.1f}ms"
        )
    
    def get_stats(self):
        """Получить статистику по всем запросам."""
        if not self.metrics:
            return {}
        
        durations = [m["duration"] for m in self.metrics]
        return {
            "total_requests": len(durations),
            "avg_duration": sum(durations) / len(durations),
            "min_duration": min(durations),
            "max_duration": max(durations),
            "p95_duration": sorted(durations)[int(len(durations) * 0.95)]
        }

tracker = PerformanceTracker()

from starlette.middleware.base import BaseHTTPMiddleware

class PerformanceMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        start = time.perf_counter()
        response = await call_next(request)
        duration = time.perf_counter() - start
        
        tracker.log_request(
            request.method,
            request.url.path,
            duration,
            response.status_code
        )
        return response

app.add_middleware(PerformanceMiddleware)

@app.get("/stats")
async def get_stats():
    """Получить статистику производительности."""
    return tracker.get_stats()

Рекомендации

Вывод

• Используй time.perf_counter() для точного измерения
• Создавай декораторы для повторного использования
• Профилируй регулярно чтобы найти узкие места
• В production используй middleware для автоматического логирования
• Помни про сетевую задержку и кэширование при анализе результатов