Важное замедление сельдерея на подпроцессе

Question

В контексте веб-приложения я недавно переключил некоторую трудоемкую обработку (латексную визуализацию) из моей «основной программы» на сельдерей.

И хотя он работал отлично на моем ноутбуке во время dev, на моем рабочем сервере время, необходимое для выполнения этой обработки, увеличилось более чем в три раза.

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

обработка Ядро

def process(content, passes=2): 
    tmp_dir = tempfile.mkdtemp() 

    with open(os.path.join(tmp_dir, 'content.tex'), 'wb') as f: 
     f.write(content.encode('utf-8')) 

    pr = cProfile.Profile() 
    pr.enable() 

    for _ in range(passes): 
     process = subprocess32.Popen(
      [ 
       '/path/to/lualatex', 
       '--interaction', 
       'nonstopmode', 
       '--output-directory', 
       tmp_dir, 
       '--jobname', 
       'output', 
       'content.tex', 
      ], 
      cwd=tmp_dir, 
      stdout=FNULL, 
      stderr=FNULL, 
      bufsize=0, 
     ) 

     process.wait() 

     if process.returncode != 0: 
      with open(os.path.join(tmp_dir, 'output.log'), 'rb') as f: 
       raise LatexError(f.read()) 

    pr.disable() 
    pr.dump_stats('/path/to/profile') 

    with open(os.path.join(tmp_dir, 'output.pdf'), 'rb') as pdf: 
     pdf_bytes = pdf.read() 

    shutil.rmtree(tmp_dir) 
    return pdf_bytes 

Профиль "вне" сельдерей

80 function calls in 1.973 seconds 

Ordered by: internal time 

ncalls tottime percall cumtime percall filename:lineno(function) 
    2 1.969 0.985 1.969 0.985 {posix.waitpid} 
    2 0.002 0.001 0.002 0.001 {_posixsubprocess.fork_exec} 
    2 0.001 0.001 0.001 0.001 {posix.read} 
    2 0.000 0.000 0.003 0.002 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1323(_execute_child) 
    2 0.000 0.000 1.969 0.985 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1644(wait) 
    2 0.000 0.000 0.003 0.002 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:713(__init__) 
    4 0.000 0.000 1.970 0.493 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:540(_eintr_retry_call) 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1578(_handle_exitstatus) 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/posixpath.py:127(dirname) 
    2 0.000 0.000 1.969 0.985 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1629(_try_wait) 
    4 0.000 0.000 0.000 0.000 {posix.close} 
    2 0.000 0.000 0.000 0.000 {_posixsubprocess.cloexec_pipe} 
    1 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:872(__del__) 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1245(_get_handles) 
    10 0.000 0.000 0.000 0.000 {isinstance} 
    2 0.000 0.000 0.000 0.000 {sorted} 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:525(_cleanup) 
    2 0.000 0.000 0.000 0.000 {posix.WIFSIGNALED} 
    3 0.000 0.000 0.000 0.000 {method 'get' of 'dict' objects} 
    2 0.000 0.000 0.000 0.000 {method 'release' of 'thread.lock' objects} 
    2 0.000 0.000 0.000 0.000 {method 'rfind' of 'str' objects} 
    1 0.000 0.000 0.000 0.000 {getattr} 
    2 0.000 0.000 0.000 0.000 {thread.allocate_lock} 
    4 0.000 0.000 0.000 0.000 {method 'fileno' of 'file' objects} 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1355(fs_encode) 
    2 0.000 0.000 0.000 0.000 {method 'rstrip' of 'str' objects} 
    2 0.000 0.000 0.000 0.000 {method 'acquire' of 'thread.lock' objects} 
    1 0.000 0.000 0.000 0.000 {range} 
    1 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1593(_internal_poll) 
    2 0.000 0.000 0.000 0.000 {posix.WEXITSTATUS} 
    2 0.000 0.000 0.000 0.000 {sys.getfilesystemencoding} 
    2 0.000 0.000 0.000 0.000 {len} 
    1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 
    2 0.000 0.000 0.000 0.000 {posix.WIFEXITED} 
    2 0.000 0.000 0.000 0.000 {method 'add' of 'set' objects} 

Профиль с сельдереем

80 function calls in 6.260 seconds 

Ordered by: internal time 

ncalls tottime percall cumtime percall filename:lineno(function) 
    2 6.256 3.128 6.256 3.128 {posix.waitpid} 
    2 0.002 0.001 0.002 0.001 {_posixsubprocess.fork_exec} 
    2 0.001 0.001 0.001 0.001 {posix.read} 
    2 0.000 0.000 0.003 0.002 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1323(_execute_child) 
    2 0.000 0.000 0.003 0.002 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:713(__init__) 
    2 0.000 0.000 6.256 3.128 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1644(wait) 
    4 0.000 0.000 6.258 1.564 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:540(_eintr_retry_call) 
    4 0.000 0.000 0.000 0.000 {posix.close} 
    2 0.000 0.000 6.256 3.128 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1629(_try_wait) 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1578(_handle_exitstatus) 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/posixpath.py:127(dirname) 
    2 0.000 0.000 0.000 0.000 {_posixsubprocess.cloexec_pipe} 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1245(_get_handles) 
    1 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:872(__del__) 
    2 0.000 0.000 0.000 0.000 {sorted} 
    10 0.000 0.000 0.000 0.000 {isinstance} 
    2 0.000 0.000 0.000 0.000 {posix.WIFSIGNALED} 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:525(_cleanup) 
    3 0.000 0.000 0.000 0.000 {method 'get' of 'dict' objects} 
    2 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1355(fs_encode) 
    2 0.000 0.000 0.000 0.000 {method 'release' of 'thread.lock' objects} 
    2 0.000 0.000 0.000 0.000 {method 'rfind' of 'str' objects} 
    4 0.000 0.000 0.000 0.000 {method 'fileno' of 'file' objects} 
    1 0.000 0.000 0.000 0.000 {getattr} 
    2 0.000 0.000 0.000 0.000 {thread.allocate_lock} 
    2 0.000 0.000 0.000 0.000 {method 'acquire' of 'thread.lock' objects} 
    2 0.000 0.000 0.000 0.000 {method 'add' of 'set' objects} 
    2 0.000 0.000 0.000 0.000 {method 'rstrip' of 'str' objects} 
    1 0.000 0.000 0.000 0.000 {range} 
    1 0.000 0.000 0.000 0.000 /home/admin/.envs/sydpnl/lib/python2.7/site-packages/subprocess32.py:1593(_internal_poll) 
    2 0.000 0.000 0.000 0.000 {posix.WEXITSTATUS} 
    1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 
    2 0.000 0.000 0.000 0.000 {len} 
    2 0.000 0.000 0.000 0.000 {posix.WIFEXITED} 
    2 0.000 0.000 0.000 0.000 {sys.getfilesystemencoding} 

Факторы, связанные с сайтом

Я использую Debian 7.8 и Python 2.7.3 на своем сервере.

EDIT 01/4/2015

Измененный код и профилировать маленький кусочек, чтобы выделить, где (я думаю) проблема.

Answer 1

Я отвечаю (и закрываю) этот вопрос, чтобы избежать https://xkcd.com/979/.

Кажется, что проблема исходила от менеджера процессов (цирка), который я использовал для управления процессом сельдерея. Цирк, вероятно, как-то уменьшал технологические ресурсы.

Переключение на другого диспетчера процессов разрешило проблему.