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

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

0 голосов
/ 09 ноября 2018

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

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.

image1+1 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 запусков:

image1+1, print(1), and var += 1 as a function of loop index">

Дополнительные замечания:

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

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

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

1 Ответ

0 голосов
/ 09 ноября 2018

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

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

Я получаю ~ 5-кратный счетчик 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

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

...