[SOLVED] Why are Python operations 30× slower after calling time.sleep or subprocess.Popen?

Issue

Consider the following loop:

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)

“command 2” command takes systematically longer to run when “command 1” is run before it. The following plot shows the execution time of 1+1 as a function of the loop index i, averaged over 100 runs.

Execution of 1+1 is 30 times slower when preceded by subprocess.Popen.

---

It gets even weirder. One may think that only the first command run after subprocess.Popen() is affected, but it is not the case. The following loop shows that all commands in the current loop iteration are affected. But the subsequent loops iterations seem to be mostly OK.

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)

Here’s a plot of the execution times for this loop, average over 100 runs:

---

More remarks:

• We get the same effect when replacing subprocess.Popen() (“command 1”) with time.sleep(), or rawkit’s libraw C++ bindings initialization (libraw.bindings.LibRaw()). However, using other libraries with C++ bindings such as libraw.py, or OpenCV’s cv2.warpAffine() do not affect execution times. Opening files don’t either.
• The effect is not caused by time.time(), because it is visible with timeit.timeit(), and even by measuring manually when print() result appear.
• It also happens without a for-loop.
• This happens even when a lot of different (possibly CPU- and memory-consuming) operations are performed between “command 1” (subprocess.Popen) and “command 2”.
• With Numpy arrays, the slowdown appears to be proportional to the size of the array. With relatively big arrays (~ 60 M points), a simple arr += 1 operation can take up to 300 ms!

---

Question: What may cause this effect, and why does it affect only the current loop iteration?

I suspect that it could be related to context switching, but this doesn’t seem to explain why a whole loop iteration would affected. If context switching is indeed the cause, why do some commands trigger it while others don’t?

Solution

my guess would be that this is due to the Python code being evicted from various caches in the CPU/memory system

the perflib package can be used to extract more detailed CPU level stats about the state of the cache — i.e. the number of hits/misses.

I get ~5 times the LIBPERF_COUNT_HW_CACHE_MISSES counter after the Popen() call:

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()                                                

gives me:

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

(lines broken in non-standard places to indicate code flow)

Answered By – Sam Mason

Answer Checked By – Candace Johnson (BugsFixing Volunteer)