芹菜在子流程上的重要减速

Question

在 Web 应用程序的上下文中，我最近将一些耗时的处理（乳胶渲染）从我的 "main program" 切换到 celery。

虽然在开发期间它在我的笔记本电脑上运行得非常好，但在我的生产服务器上执行此处理所需的时间增加了两倍多。

我将问题缩小到核心处理本身，并对其进行了概要分析，但我完全不知道是什么导致了这种差异。

核心处理

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

简介"outside"芹菜

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。

编辑 2015 年 1 月 4 日

稍微更改了代码和配置文件以突出显示（我认为）问题所在。

Answer 1

我正在回答（并结束）这个问题以避免 https://xkcd.com/979/。

看来问题出在我用来管理celery进程的进程管理器（马戏团）。 Circus 可能以某种方式减少了流程资源。

切换到另一个进程管理器解决了这个问题。

芹菜在子流程上的重要减速

Celery important slowdown on subprocess

python

celery