Почему операции Python в 30 раз медленнее после вызова time.sleep или subprocess.Popen?

Рассмотрим следующий цикл:

for i in range(20):
    if i == 10:
        subprocess.Popen(["echo"]) # command 1
    t_start = time.time()
    1+1 # command 2
    t_stop = time.time()
    print(t_stop - t_start)

Команда "команда 2" выполняется систематически дольше, когда "команда 1" выполняется перед ней. На следующем графике показано время выполнения 1+1 в зависимости от индекса i цикла, усредненного по 100 циклам.

Выполнение 1+1 в 30 раз медленнее, когда ему предшествует subprocess.Popen. subprocess.Popen.

Execution time of <code>1+1</code> as a function of loop index

Это становится еще более странным. Можно подумать, что затрагивается только первая команда, выполняемая после subprocess.Popen(), но это не так. Следующий цикл показывает, что затрагиваются все команды в текущей итерации цикла. Но последующие итерации цикла кажутся в основном нормальными.

var = 0
for i in range(20):
    if i == 10:
      # command 1
      subprocess.Popen(['echo'])
    # command 2a
    t_start = time.time()
    1 + 1
    t_stop = time.time()
    print(t_stop - t_start)
    # command 2b
    t_start = time.time()
    print(1)
    t_stop = time.time()
    print(t_stop - t_start)
    # command 2c
    t_start = time.time()
    var += 1
    t_stop = time.time()
    print(t_stop - t_start)

Вот график времени выполнения для этого цикла, в среднем более 100 запусков:

Execution times of <code>1+1, print(1), and var += 1</code> as a function of loop index

Больше замечаний:

  • Мы получаем тот же эффект при замене subprocess.Popen() ("command 1") на time.sleep() или rawkits libraw C++ для инициализации привязок (libraw.bindings.LibRaw()). Однако использование других библиотек с привязками C++, таких как libraw.py или OpenCVs cv2.warpAffine(), не влияет на время выполнения. Открытие файлов тоже не происходит.
  • Эффект не вызван time.time(), потому что он виден с помощью timeit.timeit() и даже измерением вручную, когда появляется результат print().
  • Это также происходит без цикла for.
  • Это происходит даже тогда, когда между "командой 1" (subprocess.Popen) и "командой 2" выполняется много разных (возможно, CPU- и занимающих много памяти) операций.
  • С массивами Numpy замедление оказывается пропорциональным размеру массива. При относительно больших массивах (~ 60 M точек) простая операция arr += 1 может занять до 300 мс!

Вопрос: Что может вызвать этот эффект и почему он влияет только на текущую итерацию цикла?

Я подозреваю, что это может быть связано с переключением контекста, но это, похоже, не объясняет, почему повлияла бы итерация всего цикла. Если переключение контекста действительно является причиной, почему некоторые команды запускают его, а другие нет?

Ответы

Ответ 1

я предполагаю, что это связано с тем, что код Python вытесняется из различных кэшей в системе ЦП/памяти

пакет perflib можно использовать для получения более подробной статистики уровня ЦП о состоянии кэша, то есть о количестве попаданий/пропусков.

Я получаю в 5 раз LIBPERF_COUNT_HW_CACHE_MISSES счетчика LIBPERF_COUNT_HW_CACHE_MISSES после вызова LIBPERF_COUNT_HW_CACHE_MISSES Popen():

from subprocess import Popen, DEVNULL
from perflib import PerfCounter
import numpy as np

arr = []
p = PerfCounter('LIBPERF_COUNT_HW_CACHE_MISSES')                                                        

for i in range(100):
  ti = []
  p.reset()
  p.start()
  ti.extend(p.getval() for _ in range(7))
  Popen(['echo'], stdout=DEVNULL)
  ti.extend(p.getval() for _ in range(7))
  p.stop()
  arr.append(ti)


np.diff(np.array(arr), axis=1).mean(axis=0).astype(int).tolist()

дает мне:

 2605,  2185,  2127,  2099,  2407,  2120,
5481210,
16499, 10694, 10398, 10301, 10206, 10166

(строки разбиты в нестандартных местах для обозначения потока кода)