Краткий ответ

Нужно добавить профилирование по реальному времени — wall-clock profiling, которое учитывает не только выполнение на CPU, но и ожидание ввода-вывода, блокировок и таймеров. CPU-профиль показывает главным образом участки, когда поток действительно выполняется, поэтому длительное ожидание базы данных или сети в нём может почти не отражаться.

Исторический контекст

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

Поэтому для анализа пользовательской задержки стали применять измерения реального времени и sampling-профилирование стеков. Они отвечают на другой вопрос: не «где процессор занят», а «где находится выполнение или ожидание в течение времени запроса».

Постановка проблемы

Если анализировать только CPU-время, запрос продолжительностью 2 секунды может выглядеть дешёвым: приложение, например, потратит 10 миллисекунд на подготовку SQL-запроса, а остальные 1,99 секунды будет ждать ответа базы данных.

Оптимизация Python-кода в такой ситуации почти не изменит задержку. Более того, можно ошибочно увеличить вычислительную нагрузку, не устранив настоящую причину — медленный внешний сервис, блокировку, исчерпание пула соединений или задержку планировщика.

Подробное решение

Wall-clock profiling измеряет время по часам и может включать состояния ожидания. Если профилировщик периодически снимает стек, пока поток заблокирован, в снимках будет виден участок кода, который инициировал ожидание: вызов клиента базы данных, сетевой операции, блокировки или синхронного ожидания в асинхронном коде.

Разница между CPU-временем и реальным временем видна даже на простом измерении:

import time

start_wall = time.perf_counter()
start_cpu = time.process_time()

time.sleep(0.2)

print(time.perf_counter() - start_wall)
print(time.process_time() - start_cpu)

perf_counter() приблизительно покажет прошедшие 0,2 секунды, а process_time() почти не увеличится, потому что процесс в это время не выполнял вычисления на CPU. Это измерение не заменяет профилировщик стеков, но наглядно показывает, почему два вида времени дают разные выводы.

Для поиска CPU-нагрузки подходит CPU sampling или детерминированный профилировщик. Для поиска причин задержки следует использовать wall-clock sampling, трассировку запросов или инструмент, который умеет связывать ожидание с конкретным стеком и внешней операцией.

У wall-clock profiling есть ограничения. Частота sampling определяет детализацию: очень короткое ожидание может не попасть в снимок, а редкие события требуют длительного наблюдения. Поэтому результаты нужно сопоставлять с метриками длительности запросов, тайм-аутами, временем SQL-запросов, состоянием пулов и распределением задержек, а не трактовать один профиль как полное доказательство причины.

Ситуация из практики

API-сервис имел высокий p95 задержки, но CPU-профиль показывал небольшую загрузку Python-потоков. Рассматривались три варианта: оптимизировать сериализацию, увеличить число рабочих потоков или включить wall-clock sampling.

Оптимизация сериализации была бы полезна только при подтверждённой CPU-нагрузке. Увеличение числа потоков могло временно скрыть проблему, но одновременно усилить давление на пул соединений и базу данных. Поэтому сначала добавили профилирование реального времени и метрики ожидания.

Профиль показал, что значительная часть запросов зависала внутри вызова базы данных, ожидая свободное соединение. Увеличение пула в пределах допустимой нагрузки и исправление долгих транзакций уменьшили p95 задержки; оптимизация Python-кода не потребовалась.

Что кандидаты часто упускают

Вопрос: Достаточно ли измерить wall-clock время всего обработчика, чтобы найти конкретную причину задержки?

Ответ: Нет. Такое измерение покажет полную длительность, но не распределит её между вычислениями, сетью, блокировками и дочерними вызовами. Нужны стеки wall-clock sampling, трассировка или отдельные таймеры вокруг внешних операций.
Вопрос: Может ли CPU-профиль показать ожидание ввода-вывода?

Ответ: Косвенно — иногда да, но не как затраченное CPU-время на ожидание. В профиле могут быть видны вызвавшая функция, переключения контекста или малые фрагменты работы до и после блокировки, однако сама пауза обычно не увеличивает CPU-время. Для надёжного обнаружения ожидания нужен профиль по реальному времени или специализированная трассировка.
Вопрос: Почему wall-clock sampling не всегда точно показывает сумму задержек всех операций?

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