Таймаут — не дедлайн: как теряется бюджет времени в микросервисах¶

Во всех сервисах, которые я запускал, на каждом исходящем вызове стоял таймаут. И каждый из этих сервисов всё равно умудрялся отвечать дольше любого числа в конфигурации. Это не ошибка HTTP-клиента. Число в настройках — таймаут, число в SLO — дедлайн, и похожи они только на первый взгляд. В этой статье я трижды измеряю разницу: на одном HTTP-вызове, на вызове с повторами и на цепочке из трёх gRPC-сервисов, где деньги списываются через целую секунду после того, как клиент увидел ошибку. Затем — исправление, которое сводится к арифметике, и три места, где эта арифметика должна работать.

Все числа ниже измерены на одном ноутбуке с серверами на loopback-интерфейсе. Скрипты находятся в лаборатории статьи. Версии пакетов: httpx 0.28.1, grpcio 1.83.1, deadline-budget 0.1.3, clientwright 0.2.2, grpc-client-kit 0.1.0, Python 3.13.

Таймаут ограничивает операцию¶

Вот сервер, который отвечает немедленно, но заканчивает ответ только через четыре секунды. Он сразу отправляет строку статуса и заголовки, а затем восемь раз передаёт по одному байту тела с интервалом в полсекунды:

async def drip(reader, writer):
    await reader.readuntil(b"\r\n\r\n")
    writer.write(b"HTTP/1.1 200 OK\r\nContent-Length: 8\r\n\r\n")
    for _ in range(8):
        await asyncio.sleep(0.5)
        writer.write(b"x")
        await writer.drain()
    writer.close()

А вот клиент, которому разрешили ждать одну секунду:

async with httpx.AsyncClient(timeout=1.0) as client:
    response = await client.get(url)

В первой строке — вся статья в миниатюре. timeout=1.0 в httpx задаёт четыре ограничения: на подключение, чтение, запись и получение соединения из пула. Таймаут чтения определяет, сколько клиент готов ждать между двумя порциями данных. Здесь каждая порция приходит за полсекунды, поэтому отсчёт восемь раз начинается заново и ни разу не истекает. Вторая строка показывает, как то же число выполняет свою задачу: сервер, который молчит четыре секунды, останавливают через одну. Те же настройки, тот же клиент, четырёхкратная разница — и оба результата корректны. Таймаут работает именно так, как описано в документации. Он измеряет терпение, а не полное время выполнения.

Дедлайн — конкретный момент на часах. В стандартной библиотеке для этого достаточно одной строки:

async with asyncio.timeout(1.0):
    response = await client.get(url)

Тот же сервер, медленно передающий тело ответа, но вызов отменяется через секунду: часы находятся снаружи, и ничто внутри вызова не может запустить их заново. В этом и состоит разница между двумя понятиями. Дальше мы увидим, что происходит, если игнорировать её в более крупной системе.

Повторы умножают время¶

Почти в любой кодовой базе найдётся такой цикл. Обычно его пишут в тот день, когда зависимый сервис впервые начинает сбоить:

async with httpx.AsyncClient(timeout=1.0) as client:
    for attempt in range(3):
        try:
            return await client.get(url)
        except httpx.TimeoutException:
            continue

Если сервер принимает соединение, но не отвечает, получается следующее:

Автор цикла считал, что ограничил вызов одной секундой. Вызывающий код ждал три. Сервер, которому и так было тяжело, получил три запроса вместо одного. Умножьте это на каждый переход с таким же циклом — и получите шквал повторов, который превращает медленную зависимость в аварию. Но это тема отдельной статьи.

Исправление — не уменьшить число. Нужны одни часы на весь логический вызов: все попытки, паузы между ними и перенаправления расходуют общий бюджет. Именно так clientwright понимает ограничение времени. Поэтому у TimeoutConfig есть поле total:

from clientwright import ClientConfig, RetryConfig, TimeoutConfig, build

config = ClientConfig(
    service_name="orders",
    timeout=TimeoutConfig(total=1.0),
    retry=RetryConfig(max_attempts=3),
)
client = build("httpx", config)         # a real httpx.AsyncClient, not a wrapper
response = await client.get(url)

Вторая строка — то, что автор исходного цикла, по его мнению, и написал: секунда, затем результат, независимо от политики повторов. В третьей строке те же три попытки, но теперь три секунды — выбранное вами число в конфигурации, внутри которого должна уместиться политика повторов. Разница между первой и третьей строками не в поведении, а в том, кто определил суммарное время: вы или умножение.

total отсчитывает полное время вызова, включая тело ответа. Сервер из первого раздела, который обходил timeout=1.0, отправляя по байту каждые полсекунды, получает от total=1.0 тот же ответ, что и от asyncio.timeout:

Так выглядит разница между таймаутом, который принадлежит клиенту, и дедлайном, который принадлежит вызову.

При переходе между сервисами таймаут начинает врать¶

Теперь возьмём три сервиса. Шлюз вызывает Orders и даёт ему две секунды. Orders сначала вызывает Inventory, чтобы зарезервировать товар, затем Billing, чтобы списать деньги. Каждая операция занимает полторы секунды и фиксирует изменение: начавшись, она завершается. Так может вести себя запись в базу или платёжный API, даже если вызывающая сторона уже перестала ждать. gRPC-клиенты Orders настроены привычным образом: пять секунд на каждый вызов.

Вот что увидели сервисы, если считать время с момента вызова на шлюзе. Оставшееся время каждый сервер прочитал из контекста собственного запроса, поэтому здесь нет предположений о внутреннем устройстве клиента:

fresh 5 s timeout on every call

  0.00 s  gateway    calls orders, timeout 2.0 s
  0.00 s  orders     deadline seen 2.00 s
  0.00 s  inventory  deadline seen 5.00 s
  1.50 s  inventory  reserve completed
  1.51 s  billing    deadline seen 5.00 s
  2.02 s  gateway    DEADLINE_EXCEEDED
  2.02 s  orders     cancelled
  2.02 s  billing    caller gone, but the charge is already running
  3.01 s  billing    charge completed

Посмотрите на строки Billing. Его вызвали на отметке 1,51 с и сообщили, что у него есть пять секунд. У запроса, ради которого он работал, оставалось 0,49 с. Billing выполнил поручение и завершил списание на отметке 3,01 с — через секунду после того, как покупатель увидел ошибку. А покупатель сделал то, что покупатели обычно делают после ошибки на странице оплаты. Пятисекундный таймаут честно описывал конфигурацию Orders, но неверно описывал запрос. Billing никак не мог узнать об этой разнице.

Та же цепочка с одним изменением: Orders берёт полученный дедлайн и переносит его во все свои вызовы.

the gateway's 2 s carried down the chain

  0.00 s  gateway    calls orders, timeout 2.0 s
  0.00 s  orders     deadline seen 2.00 s
  0.00 s  inventory  deadline seen 2.00 s
  1.50 s  inventory  reserve completed
  1.51 s  billing    deadline seen 0.49 s
  1.51 s  billing    refuses: 1.5 s of work does not fit in 0.49 s
  1.51 s  orders     DEADLINE_EXCEEDED
  1.51 s  gateway    DEADLINE_EXCEEDED

Запрос по-прежнему завершается ошибкой, но на полсекунды раньше и без списания денег. Причина передана по сети: Billing узнал правду — осталось 0,49 с. Сервис, который знает, что списание занимает 1,5 с, может отказаться до начала операции. Новый таймаут на каждом шаге сообщает, насколько терпелива конфигурация вызывающего клиента. Дедлайн сообщает, сколько времени действительно осталось у запроса. Только второе позволяет вызываемому сервису принять осмысленное решение.

В этом логе нужно пояснить две вещи. grpc.aio действительно отменяет серверный обработчик, когда истекает дедлайн вызывающей стороны: в первом запуске это видно на отметке 2,02 с. Но он не может отменить уже отправленную платёжную операцию. Именно поэтому решение нужно принимать до вызова. И запас между 1,51 с и 2,00 с во втором запуске — не везение: Orders успел ответить, потому что отказ не потребовал длительной работы.

---
config:
  theme: default
  look: classic
  sequence:
    useMaxWidth: false
    wrap: true
    width: 140
    actorMargin: 36
    mirrorActors: false
---
sequenceDiagram
    accTitle: Передавайте остаток времени вместо нового таймаута
    accDescr: Каждый исходящий вызов ограничен остатком времени входящего запроса. Работа и повторные попытки расходуют один общий бюджет.
 participant G as Шлюз
 participant O as Orders
 participant I as Inventory
 participant B as Billing
 G->>O: Запрос + остаток бюджета
 O->>I: Вызов с остатком бюджета
 I-->>O: Ответ
 O->>B: Вызов с уменьшившимся бюджетом
 B-->>O: Ответ
 O-->>G: Ответ

Где живёт дедлайн¶

Правило, благодаря которому получился второй лог, формулируется просто. Дедлайн создаётся один раз — в точке входа запроса в систему. На каждом переходе сервис читает переданное значение и восстанавливает из него свой бюджет. Каждый исходящий вызов получает меньшее из двух ограничений: настроенного у клиента и оставшегося у запроса.

В gRPC переданный по сети дедлайн доступен через context.time_remaining(). Вот обработчик Orders из второго запуска:

from deadline_budget import BudgetContext
from grpc_client_kit import DeadlineBudgetConfig, TimeoutConfig, build_interceptors, use_budget

chain = build_interceptors(
    timeout=TimeoutConfig(default=5.0),       # the client's own ceiling per call
    deadline_budget=DeadlineBudgetConfig(),   # trimmed to what the request has left
)

class Orders:
    async def Submit(self, request, context):
        left = context.time_remaining()       # None when the caller sent no deadline
        budget = BudgetContext.create(total_seconds=left) if left else None
        with use_budget(budget):
            await self.inventory.Reserve(request)
            await self.billing.Charge(request)

Отсчёт бюджета начинается в строке его создания. Перед каждым вызовом внутри блока with клиент узнаёт, сколько осталось. Inventory получил 2,00 с вместо пяти, потому что два меньше пяти. Billing получил 0,49 с — столько осталось после Inventory. Бюджет может только ужесточить ограничение вызова, но не ослабить его: я также проверил бюджет в 50 секунд с той же пятисекундной конфигурацией, и сервер увидел 5,00 с.

В HTTP нет встроенного дедлайна, поэтому значение передаётся в заголовке. Перед каждой попыткой клиент записывает остаток бюджета в целых миллисекундах:

from clientwright import AdapterDeps, ClientConfig, RetryConfig, TimeoutConfig, build
from clientwright.contrib.deadline import AmbientDeadlineSource, use_budget

config = ClientConfig(
    service_name="orders",
    timeout=TimeoutConfig(total=10.0),        # the client's own opinion
    retry=RetryConfig(max_attempts=3, initial_backoff=0.3),
    deadline_header="X-Deadline-Ms",
)
client = build("httpx", config, AdapterDeps(deadline_source=AmbientDeadlineSource()))

with use_budget(BudgetContext.create(total_seconds=2.0)):
    await client.get(inventory_url)           # first attempt gets a 503, the retry succeeds
    await do_our_own_work()                   # half a second
    await client.get(inventory_url)

Сервис Inventory записал заголовок каждого из трёх полученных запросов:

attempt 1: X-Deadline-Ms: 1999
attempt 2: X-Deadline-Ms: 1687
attempt 3: X-Deadline-Ms: 1179

В конфигурации стоят десять секунд. Ни один следующий сервис этого числа не видит. Первая попытка несёт весь бюджет, повтор — бюджет за вычетом паузы, второй вызов — то, что осталось после нашей собственной работы. На принимающей стороне первая строка обработчика делает то же, что и в gRPC: читает заголовок и создаёт из него бюджет.

budget = DeadlineBudget(total_seconds=int(headers["X-Deadline-Ms"]) / 1000, safety_margin=0.2)

Обратите внимание: сам объект бюджета по сети не передаётся. В нём хранится показание монотонных часов, чья точка отсчёта ничего не значит в другом процессе. Передаётся только число; после доставки вызываемый сервис начинает собственный отсчёт. Точность такого подхода ограничена временем передачи, поэтому при выборе запаса нужно учитывать и сетевую задержку.

Запас на завершение¶

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

Весь расчёт бюджета выглядит так:

remaining = (total_seconds - safety_margin) - elapsed
available = max(remaining - reserve_for_next, min_timeout)
return min(available, cap)

safety_margin — время, которое сервис оставляет себе на завершение. reserve_for_next — запас, который один вызов оставляет следующему. min_timeout — нижний порог: таймаут в три миллисекунды может оказаться практически гарантированной ошибкой, на которую всё равно уйдёт сетевой обмен. Из-за нижнего порога последний вызов иногда получает чуть больше времени, чем осталось в бюджете; этот перерасход покрывает запас. Все эти числа выбираете вы. В конфигурации с единственным timeout=5.0 ни одного из них нет.

Что изменилось в коде¶

Раньше у Orders было пять таймаутов в пяти местах. Каждый правильно описывал своего клиента, но ни один — запрос целиком. Теперь есть одно число, созданное в точке входа запроса, которое каждый клиент читает перед вызовом. Это единственное структурное изменение. Именно оно позволило Billing отказаться.

Арифметика находится в deadline-budget. Библиотека занимается только ею: без таймеров, задач, контекстных переменных, транспорта и зависимостей. Она принимает общий бюджет и для каждого вызова сообщает, сколько секунд тот может занять. Этот бюджет читают два клиента: grpc-client-kit, чей перехватчик ограничивает каждый исходящий RPC, и clientwright, чей движок делает то же для httpx, aiohttp, requests и urllib3, сохраняя привычный нативный клиент. В обоих случаях интеграция подключается опционально. Если у вас уже есть собственный учёт дедлайнов, подойдёт любой объект с методами remaining() и expired().

Смысл никогда не был в библиотеках. Смысл — в строке лога, где Billing говорит: «0,49 с — нет».