Почему time.time() не монотонно увеличивается в асинхронном цикле?

#python #python-3.x #time #python-asyncio

#python #python-3.x #время #python-asyncio

Вопрос:

У меня есть приведенный ниже код внутри тестового файла в моем приложении.

 @pytest.mark.asyncio
async def test_async_time(iters=50000):
    last_now = time.time()

    for i in range(iters):
        current_now = time.time()
        if current_now < last_now:
            print(f"Failed at iteration {i}")
            print(f"{current_now} < {last_now}")
            assert False

        last_now = current_now

        await asyncio.sleep(random.random() * 0.0001)

    assert True
  

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

Редактировать: теперь я считаю, что это может быть проблемой с Docker, и особенно с Docker Desktop на Mac. Я забыл рассмотреть или упомянуть, что я запускал этот код в контейнере Docker на моем локальном Mac, поскольку я не думал, что это имеет значение. Однако ошибка, похоже, возникает только в контейнере, а не в моей хост-ОС. Действительно, событие происходит без какого-либо асинхронного кода, поэтому я ошибался в своем суждении, что источником проблемы был асинхронный код. У меня есть код в репозитории здесь: https://github.com/tclarke13/container_tests

Не стесняйтесь посмотреть, возникает ли ошибка на вашем компьютере, выполнив make run внутри основной папки репозитория.

Комментарии:

1. Вы уверены, что ваши часы не синхронизируются повторно через NTP и не искажают сообщенное время? Вот почему time.monotonic() (или time.monotonic_ns() ) существует, чтобы избежать подобных проблем, гарантируя монотонно увеличивающиеся часы. Это не время эпохи (точка отсчета не определена), поэтому вы не можете преобразовать его в истинную календарную дату / время, но различия между измерениями будут последовательно монотонными.

2. @ShadowRanger Я считал, что мой time.time() может быть «неправильным», сам по себе, поскольку время цикла событий, похоже, не имело этой ошибки. Также я не знал об этой time.monotonic() функции, спасибо за это. Но я все еще не знаю, почему мое время будет повторно синхронизировано через NTP, поскольку время, необходимое для запуска этой функции, составляет всего 10-20 секунд, что намного меньше среднего времени опроса NTP.

3. Да, это кажется маловероятным. Похоже, что цикл событий также предоставляет монотонный .time() метод , который может иметь больше смысла использовать в этом случае, но я согласен, что при отсутствии настроек системных часов не похоже, что вы должны видеть несоответствие.

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

5. Придирка из отдела «Я должен веселиться на вечеринках»: ожидается, что значения не будут монотонно увеличиваться, а монотонно не уменьшаться , что и проверяет ваш код. Получение одного и того же значения просто означает, что ваш код выполняется быстрее, чем детализация таймера.

Ответ №1:

Вы пробовали отделить свою программу от фреймворка pytest? Я запустил следующую программу на Win10 с Python3.8:

 import time
import random
import asyncio

async def test_async_time(iters=50000):
    last_now = time.time()
    t0 = last_now

    for i in range(iters):
        current_now = time.time()
        if current_now < last_now:
            print(f"Failed at iteration {i}")
            print(f"{current_now} < {last_now}")

        last_now = current_now

        await asyncio.sleep(random.random() * 0.0001)
        if i % 1000 == 0:
            print(f"Pass {i}")
    print(t0 - last_now)

asyncio.run(test_async_time())
  

Он выполнялся без печати чего-либо, кроме сообщения периода «Pass xxx», которое я добавил, чтобы я мог отслеживать прогресс. Это заняло 795 секунд, а не 10-20, которые вы наблюдаете. Это соответствует примерно 60 итерациям цикла в секунду. Это говорит о том, что детализация функции asycnio.wait() в Win10 составляет около 16,7 мс.

Мне трудно поверить, что вы можете выполнить код внутри цикла for за 400 микросекунд, что потребовалось бы для выполнения 50000 итераций за 20 секунд. Здесь что-то выглядит подозрительно, но я не могу догадаться, что это, поскольку ваши результаты сильно отличаются от моих.

Комментарии:

1. Я удивлен, что ваш запуск занял так много времени. Если вы просто возьмете ожидаемое количество времени asyncio.sleep , которое потребуется (0,00005 с), и умножите на количество итераций (50000), вы получите всего 2,5 с, поэтому я не чувствую, что мое общее время выполнения далеко.

2. Я согласен с @TaylorClarke относительно времени — хотя Python не самый быстрый язык, 0,4 мс — это много времени, и его вполне достаточно для итерации цикла событий. Если степень детализации цикла событий asyncio действительно составляет 16 мс в Windows, об этом следует сообщать как об ошибке.