python - Celery important slowdown on subprocess -
in context of web app, switched time consuming processing (latex rendering) "main program" celery.
and while worked fine on laptop during dev, on production server time needed processing have more tripled.
i narrowed down problem core processing in itself, , i've profiled it, i'm lost on cause such difference.
core processing
def process(content, passes=2): tmp_dir = tempfile.mkdtemp() open(os.path.join(tmp_dir, 'content.tex'), 'wb') f: f.write(content.encode('utf-8')) pr = cprofile.profile() pr.enable() _ 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: open(os.path.join(tmp_dir, 'output.log'), 'rb') f: raise latexerror(f.read()) pr.disable() pr.dump_stats('/path/to/profile') open(os.path.join(tmp_dir, 'output.pdf'), 'rb') pdf: pdf_bytes = pdf.read() shutil.rmtree(tmp_dir) return pdf_bytes profile "outside" celery
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} profile celery
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} side facts
i'm running debian 7.8 , python 2.7.3 on server.
edit 01/4/2015
changed code , profile small bit highlight (i think) problem is.
i'm answering (and closing) question avoid https://xkcd.com/979/.
it seems problem coming process manager (circus) used manage celery process. circus reducing process resources somehow.
switching process manager resolved issue.
Comments
Post a Comment