python - 捕获进程输出时的 Posix_spawn 性能

Question

我正在尝试使用posix_spawn而不是fork/exec来获得一些性能提升。我当前的项目是用Python编写的，所以我使用了this Python 绑定(bind)。我还尝试了它的一些分支，之后我在 Cython 中编写了自己的 posix_spawn 绑定(bind)(以摆脱一些依赖项)，但获得了几乎相同的结果。

当我只需要运行进程而不捕获 stdout/stderr 时，确实有显着的加速。但是当我确实需要它时(对于我的项目来说这是必要的)，posix_spawn 调用变得与 fork/exec 调用一样慢。此外，它与 fork/exec 一样取决于分配的内存量。即使该过程实际上没有产生任何输出，它也会发生 - 我检查了/bin/true。我仍然无法解释这种行为。对于 fork/exec(通过 subprocess 模块)，只要输出不是太大，无论我们是否读取进程输出，都没有显着差异。

这是我的测试脚本(省略了导入和分析代码)

 # test.py
 def spawn_no_out(args):
    command = args[0]
    pid = posix_spawn(command, args)
    status, rusage = exits(pid)

 def spawn(args):

    # Prepare pipes to capture stdout and stderr
    stdout_read, stdout_write = os.pipe()
    stderr_read, stderr_write = os.pipe()
    fa = FileActions()
    fa.add_dup2(stdout_write, 1)
    fa.add_close(stdout_read)
    fa.add_dup2(stderr_write, 2)
    fa.add_close(stderr_read)

    # Spawn the process
    command = args[0]
    pid = posix_spawn(command, args, file_actions=fa)

    # Read and close file descriptors
    os.close(stdout_write)
    os.close(stderr_write)
    status, rusage = exits(pid)
    out = os.fdopen(stdout_read)
    err = os.fdopen(stderr_read)
    return out, err

 def fork(args):
    return Popen(args, stdout=PIPE, stderr=PIPE).communicate()

 def fork_no_out(args):
    return subprocess.call(args)

 def run_benchmark(func, args, count):
    for _ in xrange(count):
       func(args)
    print "%s: %ds" % (func.__name__, time.time() - start)

 def main():
    # Reads from stdout the number of process spawns and size of allocated memory
    args = ["/bin/true"]
    count = int(sys.argv[1]) if len(sys.argv) > 1 else 1000
    mem_size = int(sys.argv[2]) if len(sys.argv) > 2 else 10000000
    some_allocated_memory = range(mem_size)
    for func in [spawn, spawn_no_out, fork, fork_no_out]:
        run_benchmark(func, args, count)


 if __name__ == "__main__":
    main()

在不分配额外内存的情况下测试输出:

./test.py 10000 1spawn: 34s         3754834 function calls (3754776 primitive calls) in 33.517 seconds   Ordered by: internal time, cumulative time   List reduced from 144 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)    10000   15.475    0.002   15.475    0.002 {posix.wait4}    10000    5.850    0.001    5.850    0.001 {_cffi__x2c5d2681xf492c09f.posix_spawn}    10000    3.217    0.000   12.750    0.001 /usr/local/lib/python2.7/dist-packages/posix_spawn-0.1-py2.7.egg/posix_spawn/_impl.py:75(posix_spawn)    10000    2.242    0.000   33.280    0.003 ./test.py:23(spawn)   660000    1.777    0.000    3.159    0.000 /usr/local/lib/python2.7/dist-packages/cffi/api.py:212(new)spawn_no_out: 14s         3340013 function calls in 14.631 seconds   Ordered by: internal time, cumulative time   List reduced from 25 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)    10000    7.466    0.001    7.466    0.001 {posix.wait4}    10000    2.012    0.000    2.012    0.000 {_cffi__x2c5d2681xf492c09f.posix_spawn}    10000    1.658    0.000    6.994    0.001 /usr/local/lib/python2.7/dist-packages/posix_spawn-0.1-py2.7.egg/posix_spawn/_impl.py:75(posix_spawn)   650000    1.640    0.000    2.919    0.000 /usr/local/lib/python2.7/dist-packages/cffi/api.py:212(new)   650000    0.496    0.000    0.496    0.000 {_cffi_backend.newp}fork: 40s         840094 function calls in 40.745 seconds   Ordered by: internal time, cumulative time   List reduced from 53 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)    10000   19.460    0.002   19.460    0.002 {posix.read}    10000    6.505    0.001    6.505    0.001 {posix.fork}    10081    4.667    0.000    4.667    0.000 {built-in method poll}    10000    2.773    0.000   30.190    0.003 /usr/lib/python2.7/subprocess.py:1187(_execute_child)    10000    0.814    0.000   32.996    0.003 /usr/lib/python2.7/subprocess.py:650(__init__)fork_no_out: 38s         330013 function calls in 38.488 seconds   Ordered by: internal time, cumulative time   List reduced from 36 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)    10000   18.179    0.002   18.179    0.002 {posix.read}    10000    6.904    0.001    6.904    0.001 {posix.waitpid}    10000    6.613    0.001    6.613    0.001 {posix.fork}    10000    2.633    0.000   28.976    0.003 /usr/lib/python2.7/subprocess.py:1187(_execute_child)    10000    0.880    0.000   30.070    0.003 /usr/lib/python2.7/subprocess.py:650(__init__)

Test output with allocated memory for list of 10000000 integers (had to decrease the number of calls):

./test.py 1000 10000000spawn: 20s         379834 function calls (379776 primitive calls) in 20.022 seconds   Ordered by: internal time, cumulative time   List reduced from 144 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)     1000   10.022    0.010   10.022    0.010 {posix.wait4}     1000    8.705    0.009    8.705    0.009 {_cffi__x2c5d2681xf492c09f.posix_spawn}     1000    0.334    0.000    9.412    0.009 /usr/local/lib/python2.7/dist-packages/posix_spawn-0.1-py2.7.egg/posix_spawn/_impl.py:75(posix_spawn)     1000    0.269    0.000   19.998    0.020 ./test.py:18(spawn)    66000    0.174    0.000    0.318    0.000 /usr/local/lib/python2.7/dist-packages/cffi/api.py:212(new)spawn_no_out: 1s         334013 function calls in 1.480 seconds   Ordered by: internal time, cumulative time   List reduced from 25 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)     1000    0.755    0.001    0.755    0.001 {posix.wait4}     1000    0.198    0.000    0.198    0.000 {_cffi__x2c5d2681xf492c09f.posix_spawn}     1000    0.171    0.000    0.708    0.001 /usr/local/lib/python2.7/dist-packages/posix_spawn-0.1-py2.7.egg/posix_spawn/_impl.py:75(posix_spawn)    65000    0.167    0.000    0.298    0.000 /usr/local/lib/python2.7/dist-packages/cffi/api.py:212(new)    65000    0.050    0.000    0.050    0.000 {_cffi_backend.newp}fork: 18s         84067 function calls in 18.554 seconds   Ordered by: internal time, cumulative time   List reduced from 53 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)     1000    9.399    0.009    9.399    0.009 {posix.read}     1000    7.815    0.008    7.815    0.008 {posix.fork}     1054    0.414    0.000    0.414    0.000 {built-in method poll}     1000    0.274    0.000   17.626    0.018 /usr/lib/python2.7/subprocess.py:1187(_execute_child)     1000    0.078    0.000   17.871    0.018 /usr/lib/python2.7/subprocess.py:650(__init__)fork_no_out: 18s         33013 function calls in 18.732 seconds   Ordered by: internal time, cumulative time   List reduced from 36 to 5 due to restriction    ncalls  tottime  percall  cumtime  percall filename:lineno(function)     1000    9.467    0.009    9.467    0.009 {posix.read}     1000    8.020    0.008    8.020    0.008 {posix.fork}     1000    0.603    0.001    0.603    0.001 {posix.waitpid}     1000    0.280    0.000   17.910    0.018 /usr/lib/python2.7/subprocess.py:1187(_execute_child)     1000    0.072    0.000   18.000    0.018 /usr/lib/python2.7/subprocess.py:650(__init__)

Without profiling the results are the same.As we can see, there is a huge difference (1.4s vs 20s!) in performance for the cases when we call posix_spawn with and without capturing process output. There is no additional heavy calls - posix.wait4 just takes more time.What could I have done wrong here? Does someone have an idea why it happens and how to get better performance for posix_spawn?

P.S. Tested on Linux Mint 17 and CentOS 6.5 - same results.

UPDATE:The same performance degradation happens even if we pass empty FileActions object to posix_spawn, without actually reading stdout/stderr:

def spawn(args):
    command = args[0]
    pid = posix_spawn(command, args, file_actions=FileActions())
    status, rusage = exits(pid)

Answer 1

好吧，对于后代 - 似乎如果设置了 file_actions 并且未设置某些标志，posix_spawn 仅使用 fork: https://sourceware.org/git/?p=glibc.git;a=blob;f=sysdeps/posix/spawni.c;h=2d3ae941dd19f0348ed95c0b957c68c3c0e9815d;hb=c758a6861537815c759cba2018a3b1abb1943842#l97