MEASUREMENT

bench/cancellation/06_debug_slow_callback.py

The script that produced the numbers in the article, and the record of the run. The file is read from the repository at build time — this is the code that was run, not a copy of it.

Cited in

/en/python/concurrency/event-loop

How to run it

CPython 3.11.15
CPython 3.12.3
CPython 3.13.7      <- основной прогон, весь дословный вывод ниже с него
CPython 3.14.7

The run below is recorded in Russian. It is a lab record, kept in the language it was written in; the numbers, the tables and the code read the same either way.

Record of the run

Отмена в asyncio: воспроизводимые примеры

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

Числа в выводе — только те, что печатает скрипт. Всё, что меняется от запуска к запуску (адреса объектов, loop.time(), номера строк, доли секунды в логе debug-режима), скрипты нормализуют сами и помечают как <...>.

Чем проверено

CPython 3.11.15
CPython 3.12.3
CPython 3.13.7      <- основной прогон, весь дословный вывод ниже с него
CPython 3.14.7

Исходники, на которые ссылаются скрипты, — установленный 3.13.7:

python3.13 -c "import sysconfig;print(sysconfig.get_paths()['stdlib'])"
# /root/.local/share/uv/python/cpython-3.13.7-linux-x86_64-gnu/lib/python3.13

Что где

Файл	Что показывает
`01_cancellederror_is_baseexception.py`	`CancelledError` — не `Exception`; `except Exception` её пропускает, `except BaseException` без `raise` её убивает
`02_finally_budget.py`	`finally` при отмене выполняется, но бюджета у него нет; повторный `cancel()`; проглоченная отмена; счётчик `cancelling()`
`03_timeout_vs_wait_for.py`	`asyncio.timeout` против `wait_for`: внутри `CancelledError`, снаружи `TimeoutError`; чем таймаут отличает свою отмену от внешней
`04_shield.py`	что `shield` защищает (работу) и чего не защищает (ожидающего)
`05_taskgroup_cancellation.py`	отмена соседей в `TaskGroup`, `ExceptionGroup`, `except*`, контраст с `gather`
`06_debug_slow_callback.py`	debug-режим asyncio и `loop.slow_callback_duration`: что именно печатается на медленный коллбэк
`version_matrix.py`	один файл на четырёх интерпретаторах: где границы двигались

Запуск:

python3.13 bench/cancellation/01_cancellederror_is_baseexception.py
python3.13 bench/cancellation/02_finally_budget.py
python3.13 bench/cancellation/03_timeout_vs_wait_for.py
python3.13 bench/cancellation/04_shield.py
python3.13 bench/cancellation/05_taskgroup_cancellation.py
python3.13 bench/cancellation/06_debug_slow_callback.py

python3.11 bench/cancellation/version_matrix.py
python3.12 bench/cancellation/version_matrix.py
python3.13 bench/cancellation/version_matrix.py
python3.14 bench/cancellation/version_matrix.py

Все семь файлов запускаются на всех четырёх интерпретаторах и на всех четырёх завершаются с кодом 0.

Дословный вывод: решающие места

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

01 — где CancelledError в иерархии и что из этого следует.

  __mro__                                        ('CancelledError', 'BaseException', 'object')
  issubclass(CancelledError, Exception)          False
  asyncio.CancelledError is concurrent.futures.CancelledError False
  concurrent.futures.CancelledError.__mro__      ('CancelledError', 'Error', 'Exception', 'BaseException', 'object')

  except Exception                               пропустил
  except BaseException                           ПОЙМАЛ

И то, ради чего это меряется, — на живой задаче:

  б) try/except BaseException/finally, БЕЗ raise
      task.cancelled()                           False
      итог                                       await task вернул: 'вернул значение, как будто ничего не было'

  д) contextlib.suppress(CancelledError)
      task.cancelled()                           False
      итог                                       await task вернул: None

Ловушка не в том, что отмену трудно поймать, а в том, что её легко поймать НЕ ТАМ: except Exception пропускает, except BaseException без raise — убивает.

02 — у finally нет бюджета.

  уборка просила                                 0.30 с
  от cancel() до конца задачи прошло             0.30 с

== 3. Повторный cancel() обрывает уборку; счётчик cancelling() растёт
  после 1-го cancel(): task.cancelling()         1
  после 2-го cancel(): task.cancelling()         2
    | finally: уборку оборвали на await

== 6. cancelling()/uncancel() — счётчик, а не флаг
  cancel()                                       1
  uncancel() вернул                              0
  итог                                           бросил CancelledError

Сколько уборка попросила — столько цикл и ждал. Предел появляется только тогда, когда отменяющая сторона отменяет ещё раз.

03 — одно событие, две ветки except.

    | изнутри блока прилетел CancelledError
    | снаружи блока: TimeoutError
    | цепочка: TimeoutError <-cause- CancelledError

== 3. Проглотили отмену внутри блока — таймаут молча не сработал
    | тело досчиталось до конца, хотя таймаут истёк
    | TimeoutError НЕ прилетел
    | блок с лимитом 0.05 с занял 0.15 с

04 — что shield защищает.

== 1. Отменяем ОЖИДАЮЩЕГО: внутренняя задача не замечает
  outer.cancelled()                              True
  inner.cancelled()                              False
  inner.result()                                 'внутренняя-результат'

== 4. shield под asyncio.timeout
    | снаружи: TimeoutError через 0.05 с
    | защищённая всё же доработала за 0.25 с

Таймаут отменил ожидание, но не работу. Не зная этого, получают «таймаут сработал, а запрос всё равно ушёл».

05 — отмена соседей и что выходит наружу.

== 2. Две задачи упали — обе в одном ExceptionGroup
    ExceptionGroup: 'unhandled errors in a TaskGroup' (2 шт.)
      ValueError: V
      KeyError: 'K'

== 3. CancelledError от ребёнка группу НЕ роняет
  итог                                           группа вышла штатно

== 4. Внешняя отмена родителя: наружу CancelledError, не ExceptionGroup
  await parent ->                                CancelledError

06 — debug-режим и порог.

  новый цикл: get_debug()                        False
  новый цикл: slow_callback_duration             0.1

  б) debug включён, порог по умолчанию 0.1 с
    | WARNING:asyncio:Executing <Handle blocking_callback() ...> took <N> seconds

  в) debug включён, порог поднят до 1.0 с — блокировка не заметна
    (предупреждения нет)

== 3. Тот же блок, но внутри задачи — жалуются на Task, а не на Handle
    | WARNING:asyncio:Executing <Task finished name='Task-<n>' coro=<blocking_step() ...>> took <N> seconds

Режим и порог — две независимые ручки: без debug порог не смотрится вовсе, а с порогом 1,0 с блокировка на 0,25 с не видна. Формат строки один, меняется только объект: Handle для call_soon, TimerHandle для call_later, Task для шага задачи — последний и означает «корутина заблокировала цикл».

Таблица версий

Строки, где выводы четырёх интерпретаторов разошлись:

	3.11.15	3.12.3	3.13.7	3.14.7
`hasattr(asyncio, 'eager_task_factory')`	False	True	True	True
`hasattr(asyncio.Queue, 'shutdown')`	False	False	True	True
`import asyncio.graph`	`ModuleNotFoundError`	`ModuleNotFoundError`	`ModuleNotFoundError`	ok
`get_event_loop()` без работающего цикла	вернул цикл, без предупреждений	вернул цикл + `DeprecationWarning`	вернул цикл + `DeprecationWarning`	`RuntimeError`
`wait_for`: корутина выполняется в той же задаче	False	True	True	True
`uncancel()` снимает ещё не доставленную отмену	нет	нет	да	да
`create_task` у не-входившей `TaskGroup`: `RuntimeWarning 'never awaited'`	есть	есть	нет	нет

Строки, одинаковые на всех четырёх (граница здесь — 3.11, и она не двигалась):

hasattr(asyncio, 'timeout')                          True
hasattr(asyncio, 'timeout_at')                       True
hasattr(asyncio, 'TaskGroup')                        True
hasattr(asyncio, 'shield')                           True
hasattr(asyncio.Task, 'cancelling')                  True
hasattr(asyncio.Task, 'uncancel')                    True
builtins.ExceptionGroup                              True
builtins.BaseExceptionGroup                          True
синтаксис except*                                    ok
CancelledError.__mro__                               ('CancelledError', 'BaseException', 'object')
issubclass(CancelledError, Exception)                False
asyncio.TimeoutError is builtins.TimeoutError        True
TimeoutError.__mro__                                 ('TimeoutError', 'OSError', 'Exception', 'BaseException', 'object')
Task реализован на C                                 True
wait_for отдаёт значение, если отмену съели          'проглотил и вернул'
ошибка ребёнка под внешним asyncio.timeout           ExceptionGroup['ValueError']
две вложенные TaskGroup падают разом                 ExceptionGroup -> ['ValueError(внешняя)', 'ValueError(внутренняя)']

Три различия из семи — не про наличие имён, а про поведение, и каждое ловится только запуском.

wait_for и «та же задача». На 3.11 wait_for заворачивал переданное в отдельную задачу и ждал её через коллбэк; на 3.12 и дальше он реализован как async with timeouts.timeout(timeout): return await fut (Lib/asyncio/tasks.py:506 на 3.13.7), то есть тело выполняется прямо в вызывающей задаче. Наблюдается это через asyncio.current_task().get_name(): Task-4 против Task-1.

uncancel() и ещё не доставленная отмена. До 3.13 uncancel() уменьшал только счётчик; с 3.13 он ещё и снимает флаг _must_cancel (Lib/asyncio/tasks.py:256-259). Скрипт ловит это так: отменить задачу до её первого шага (тогда _fut_waiter ещё None и отмена только «назначена»), сразу вызвать uncancel() — на 3.11/3.12 задача всё равно отменяется, на 3.13/3.14 доживает до конца и возвращает результат.

create_task у неактивной группы. С 3.13 переданная корутина закрывается, и RuntimeWarning: coroutine ... was never awaited больше не появляется. На 3.11/3.12 предупреждение есть — скрипт ловит его через warnings.catch_warnings(record=True), а не по тексту в stderr.

Про «зависание вложенных TaskGroup». Проба «две вложенные TaskGroup падают разом» обёрнута сторожевым asyncio.timeout(2) — если бы группа повисла, в таблице стояло бы ПОВИСЛО. На всех четырёх версиях она не виснет. Это не опровергает исправление 3.13: сценарий из gh-116720 воспроизводится не любым вложением, и доказать здесь можно только то, что эта проба ведёт себя одинаково. Такой пробы для той ошибки у нас нет.

Первоисточники

Дословные цитаты с переводами стоят во frontmatter статей, которые на эти файлы ссылаются, — там же, где они нужны читателю. Здесь только адреса: документация asyncio (asyncio-task, asyncio-exceptions, asyncio-dev, asyncio-eventloop), PEP 654 и «Что нового в 3.13». Текст снят с .rst-исходников CPython на теге v3.13.7 — это тот же текст, что рендерится на docs.python.org/3.13, и он привязан к точной версии.

Ключевые места в исходниках 3.13.7

Пути от корня установки: .../lib/python3.13/asyncio/.

Файл:строка	Что там
`exceptions.py:10`	`class CancelledError(BaseException):` — одна строка, из которой растёт весь сюжет
`exceptions.py:14`	`TimeoutError = TimeoutError # make local alias for the standard exception`
`tasks.py:115-116`	`self._num_cancels_requested = 0` и `self._must_cancel = False` — два поля состояния отмены
`tasks.py:198`	`def cancel(self, msg=None)`
`tasks.py:223`	`self._num_cancels_requested += 1`
`tasks.py:224-228`	закомментированный `if self._num_cancels_requested > 1: return False` с пометкой «These two lines are controversial» и ссылкой на обсуждение
`tasks.py:236-237`	`self._must_cancel = True` — путь, когда задача ещё не ждёт ни на чём
`tasks.py:240`	`def cancelling(self)`
`tasks.py:248`	`def uncancel(self)`
`tasks.py:256-259`	уменьшение счётчика и, с 3.13, сброс `_must_cancel` при нуле
`tasks.py:459`	`async def wait_for(fut, timeout)`
`tasks.py:506-507`	`async with timeouts.timeout(timeout): return await fut` — вся реализация `wait_for` с 3.12
`tasks.py:918`	`def shield(arg)`
`tasks.py:930-935`	«…the task running in something() is not cancelled… If something() is cancelled by other means this will still cancel shield()»
`tasks.py:946-949`	«Save a reference to tasks passed to this function…»
`timeouts.py:88-94`	`__aenter__`: запоминает `self._cancelling = self._task.cancelling()`
`timeouts.py:112`	`if self._task.uncancel() <= self._cancelling and exc_type is not None:` — вот чем своя отмена отличается от чужой
`timeouts.py:115-116`	`if issubclass(exc_type, exceptions.CancelledError): raise TimeoutError from exc_val`
`timeouts.py:127-132`	`_on_timeout`: `self._task.cancel()` и переход в состояние `EXPIRING`
`taskgroups.py:35`	`self._tasks = set()` — отсюда невоспроизводимый порядок отмены соседей
`taskgroups.py:144-149`	`if self._parent_cancel_requested: if self._parent_task.uncancel() == 0: propagate_cancellation_error = None`
`taskgroups.py:169-176`	uncancel + повторный cancel родителя, затем `raise BaseExceptionGroup('unhandled errors in a TaskGroup', self._errors)`
`taskgroups.py:186-194`	три проверки в `create_task`, каждая с `coro.close()` перед `RuntimeError`
`taskgroups.py:221-226`	`_abort`: `for t in self._tasks: if not t.done(): t.cancel()`
`taskgroups.py:235-236`	`if task.cancelled(): return` — отменённый ребёнок группу не роняет
`taskgroups.py:257-278`	отмена родительской задачи при первой ошибке ребёнка
`runners.py:198-206`	`_cancel_all_tasks`: `cancel()` всем и `run_until_complete(gather(...))` без ограничения по времени
`base_events.py:432`	`self.set_debug(coroutines._is_debug_mode())`
`base_events.py:437`	`self.slow_callback_duration = 0.1`
`base_events.py:2038-2047`	ветка `if self._debug:` в `_run_once` и `logger.warning('Executing %s took %.3f seconds', ...)`
`log.py:7`	`logger = logging.getLogger(__package__)` — логгер называется `asyncio`, к нему и цепляется обработчик в `06`

Оговорки

3.14 здесь — 3.14.7. Финальной сборки на машине нет. В таблицу с 3.14 попали только поведенческие факты (есть ли модуль, что вернёт вызов, какое исключение), и от rc до финала они меняться не должны — но «не должны» это не «проверено».

Числа в выводе — это asyncio.sleep, а не замер. 0,05 / 0,15 / 0,20 / 0,25 / 0,30 с воспроизводятся на любой машине с точностью до второго знака, потому что это заказанная длительность сна, а не измеренная стоимость работы. Единственное место, где стоит настоящее измерение, — секунды в логе debug-режима, и они нормализованы до <N>.

Порядок отмены соседей в TaskGroup не воспроизводим (set в taskgroups.py:35). Сам факт отмены — воспроизводим, порядок — нет.

Про исправление вложенных TaskGroup в 3.13 доказана только рамка. Проба в version_matrix.py показывает, что на всех четырёх версиях этот конкретный сценарий не виснет; воспроизведения самой ошибки gh-116720 у нас нет, и в статье это должно называться цитатой из whatsnew, а не «проверено запуском».

Вывод 06 нормализован. Секунды, адреса, номера строк и имена задач заменены на <...> самим скриптом — иначе дословное сравнение между запусками невозможно. Всё, что не в угловых скобках, — ровно то, что печатает asyncio.

Script

204 lines

"""Debug-режим asyncio и loop.slow_callback_duration.

Показывает запуском, что именно печатает asyncio, когда коллбэк или шаг задачи
занял больше порога, и чем режим отладки отличается от обычного:

  * порог по умолчанию 0.1 с (Lib/asyncio/base_events.py:437);
  * без debug не печатается ничего, сколько бы блокировка ни длилась;
  * с debug — WARNING «Executing <...> took N seconds» на call_soon-коллбэк
    и отдельно на шаг Task;
  * там же появляются «coroutine ... was never awaited» с местом создания
    и «Executing <TimerHandle ...>».

Строки лога печатаются дословно; в них меняются только секунды, номера строк
этого файла и адреса объектов — их скрипт нормализует, чтобы вывод сходился
между запусками. Нормализованное помечено <...>.

    python3.13 bench/cancellation/06_debug_slow_callback.py
"""

import asyncio
import io
import logging
import re
import sys
import time


def row(name, value):
    print(f"  {name:<46} {value}")


def head(title):
    print()
    print(f"== {title}")


def norm(text):
    """Убрать из строк лога всё, что меняется от запуска к запуску."""
    text = re.sub(r"took \d+\.\d+ seconds", "took <N> seconds", text)
    text = re.sub(r"when=\d+\.\d+", "when=<дедлайн>", text)
    text = re.sub(r"0x[0-9a-f]+", "0x<адрес>", text)
    text = re.sub(r"name='Task-\d+'", "name='Task-<n>'", text)
    text = re.sub(r"created at [^>]+", "created at <файл:строка>", text)
    text = re.sub(r"/[^\s>\"]*/06_debug_slow_callback\.py", "<этот файл>", text)
    text = re.sub(r"<этот файл>:\d+", "<этот файл>:<строка>", text)
    text = re.sub(r"line \d+", "line <строка>", text)
    return text


class Capture(logging.Handler):
    """Ловим ровно то, что asyncio пишет в свой логгер."""

    def __init__(self):
        super().__init__(level=logging.DEBUG)
        self.records = []

    def emit(self, record):
        self.records.append(
            f"{record.levelname}:{record.name}:{record.getMessage()}")


def with_capture(debug, threshold, body, warn_capture=False):
    """Запустить body(loop) в своём цикле и вернуть пойманные строки."""
    logger = logging.getLogger("asyncio")
    cap = Capture()
    logger.addHandler(cap)
    old_level = logger.level
    logger.setLevel(logging.DEBUG)
    warnings_out = io.StringIO()
    try:
        loop = asyncio.new_event_loop()
        loop.set_debug(debug)
        if threshold is not None:
            loop.slow_callback_duration = threshold
        try:
            if warn_capture:
                import warnings
                with warnings.catch_warnings(record=True) as caught:
                    warnings.simplefilter("always")
                    loop.run_until_complete(body(loop))
                for w in caught:
                    text = f"{w.category.__name__}: {w.message}"
                    lines = text.splitlines()
                    # трассировку места создания режем: она длинная и вся из
                    # путей и номеров строк, важен сам факт её наличия
                    if len(lines) > 2:
                        lines = lines[:2] + [
                            f"  ...и ещё {len(lines) - 2} строк(и) трассировки "
                            f"места создания"]
                    warnings_out.write("\n".join(lines) + "\n")
            else:
                loop.run_until_complete(body(loop))
        finally:
            loop.close()
    finally:
        logger.removeHandler(cap)
        logger.setLevel(old_level)
    return cap.records, warnings_out.getvalue()


# ---------------------------------------------------------------------------

def blocking_callback():
    time.sleep(0.25)


async def blocking_step():
    await asyncio.sleep(0)
    time.sleep(0.25)          # блокировка внутри шага задачи


async def scenario_callback(loop):
    loop.call_soon(blocking_callback)
    await asyncio.sleep(0.05)


async def scenario_timer(loop):
    loop.call_later(0.01, blocking_callback)
    await asyncio.sleep(0.10)


async def scenario_task(loop):
    await asyncio.ensure_future(blocking_step())


async def scenario_never_awaited(loop):
    async def forgotten():
        return 1
    forgotten()               # корутину никто не дождался
    await asyncio.sleep(0)
    import gc
    gc.collect()


# ---------------------------------------------------------------------------

def show(title, debug, threshold, body, warn_capture=False):
    print()
    print(f"  {title}")
    row("    loop.get_debug()", debug)
    row("    loop.slow_callback_duration", threshold if threshold is not None
        else "по умолчанию")
    records, warns = with_capture(debug, threshold, body, warn_capture)
    if not records and not warns:
        print("    | (в лог asyncio не попало ничего)")
    for line in records:
        print(f"    | {norm(line)}")
    for line in warns.splitlines():
        print(f"    W {norm(line)}")


def main():
    print(f"Python {sys.version.split()[0]}")

    head("1. Значения по умолчанию")
    loop = asyncio.new_event_loop()
    try:
        row("новый цикл: get_debug()", loop.get_debug())
        row("новый цикл: slow_callback_duration", loop.slow_callback_duration)
    finally:
        loop.close()
    row("PYTHONASYNCIODEBUG в окружении", "да" if "PYTHONASYNCIODEBUG"
        in __import__("os").environ else "нет")
    row("sys.flags.dev_mode", sys.flags.dev_mode)
    print("  Lib/asyncio/base_events.py:437 — self.slow_callback_duration = 0.1")
    print("  Lib/asyncio/base_events.py:432 — set_debug(coroutines._is_debug_mode())")

    head("2. Блокирующий коллбэк на 0.25 с")
    show("а) debug выключен (как в проде по умолчанию)",
         False, None, scenario_callback)
    show("б) debug включён, порог по умолчанию 0.1 с",
         True, None, scenario_callback)
    show("в) debug включён, порог поднят до 1.0 с — блокировка не заметна",
         True, 1.0, scenario_callback)
    show("г) debug включён, порог опущен до 0.01 с",
         True, 0.01, scenario_callback)
    print("  Lib/asyncio/base_events.py:2044 — if dt >= self.slow_callback_duration:")
    print("      logger.warning('Executing %s took %.3f seconds', ...)")

    head("3. Тот же блок, но внутри задачи — жалуются на Task, а не на Handle")
    show("debug включён, порог 0.1 с", True, None, scenario_task)

    head("4. Отложенный коллбэк (call_later) — TimerHandle")
    show("debug включён, порог 0.1 с", True, None, scenario_timer)

    head("5. Что ещё даёт debug: забытая корутина с местом создания")
    show("а) debug выключен", False, None, scenario_never_awaited,
         warn_capture=True)
    show("б) debug включён", True, None, scenario_never_awaited,
         warn_capture=True)
    print("  В debug-режиме включается coroutine origin tracking, и в тексте")
    print("  предупреждения появляется «created at <файл:строка>».")

    head("6. Как включают снаружи, не трогая код")
    print("    PYTHONASYNCIODEBUG=1 python3.13 своя_программа.py")
    print("    python3.13 -X dev своя_программа.py")
    print("    asyncio.run(main(), debug=True)")
    print("    loop.set_debug(True); loop.slow_callback_duration = 0.05")
    print("  Порог отдельно от режима: без debug он не смотрится вообще.")


if __name__ == "__main__":
    main()