9

I was trying to understand why this is happening. I'm calling a command to restart networking on Ubuntu server 12.04.

Fast execution

When I call the command using one of following three ways it takes around 0.1 seconds to execute:

  1. directly in terminal
  2. python script using os.system
  3. python script using subprocess.call

terminal session:

root@ubuntu:~# time /etc/init.d/networking restart
 * Running /etc/init.d/networking restart
 * Reconfiguring network interfaces...
real    0m0.105s

root@ubuntu:~# time python -c "import os;
> os.system('/etc/init.d/networking restart')"
 * Running /etc/init.d/networking restart
 * Reconfiguring network interfaces...
real    0m0.111s

root@ubuntu:~# time python -c "import subprocess;
> subprocess.call(['/etc/init.d/networking', 'restart'])"
 * Running /etc/init.d/networking restart
 * Reconfiguring network interfaces...
real    0m0.111s

Slow execution

However if I use subprocess.check_output or Popen and try and read the output it takes 23 seconds. Way slower. It seems this dramatic difference only happens when I try and use a function that will return the commands output. I would like to understand why this is happening and find a solution to execute this command and get it's output without it taking so long.

terminal session:

root@ubuntu:~# time python -c "import subprocess;
> print subprocess.check_output(['/etc/init.d/networking', 'restart'])"
 * Running /etc/init.d/networking restart
 * Reconfiguring network interfaces...
real    0m23.201s

root@ubuntu:~# time python -c "from subprocess import Popen, PIPE;
> print Popen(['/etc/init.d/networking', 'restart'], stdout=PIPE).stdout.read()"
 * Running /etc/init.d/networking restart
 * Reconfiguring network interfaces...
real    0m23.201s

Update

One of the comments suggested trying out the tee command. The results where very interesting. In the terminal without any involvement of python if tee is used it takes the same 23 seconds. I am still curious why but at least this might give more of a clue as to what's going on.

root@ubuntu:~# time /etc/init.d/networking restart | tee out.txt
 * Running /etc/init.d/networking restart
 * Reconfiguring network interfaces...
real    0m23.181s
andyhasit
  • 14,137
  • 7
  • 49
  • 51
Marwan Alsabbagh
  • 25,364
  • 9
  • 55
  • 65
  • I don't know if either of the following is relevant ([question #10150368](http://stackoverflow.com/questions/10150368/why-is-piping-output-of-subprocess-so-unreliable-with-python), [question #4940607](http://stackoverflow.com/questions/4940607/python-subprocesses-experience-mysterious-delay-in-receiving-stdin-eof) ) but one answer suggests adding `close_fds=True` to popen parameters – James Waldby - jwpat7 Dec 12 '12 at 07:51
  • `subprocess.call()` is just `subprocess.Popen(*popenargs, **kwargs).wait()`. – Blender Dec 12 '12 at 07:56
  • @jwpat7 thanks for the links. I tried close_fds=True it didn't make a difference. – Marwan Alsabbagh Dec 12 '12 at 08:00
  • 5
    how long it takes to execute: `networking restart | tee some_file` (check whether some_file is empty). Try `bufsize=-1` and/or `f = TemporaryFile(); check_call(cmd, stdout=f, stderr=STDOUT); f.seek(0); output = f.read()` – jfs Dec 12 '12 at 08:08
  • @J.F.Sebastian those suggestions were awesome. I posted the results of tee in the question, the file outputed was not empty it contains the output. Your approach of a temp file worked great. If you post it as an answer below I can up vote it. I still don't understand why this is happening though. – Marwan Alsabbagh Dec 12 '12 at 08:30

1 Answers1

11

The code below is based on the excellent comment J.F. Sebastian made. The code below runs in 0.1 seconds as expected and returns the output of the command to a string.

from subprocess import check_call, STDOUT
from tempfile import NamedTemporaryFile

with NamedTemporaryFile() as f:
    check_call(['/etc/init.d/networking', 'restart'], stdout=f, stderr=STDOUT)
    f.seek(0)
    output = f.read()
Marwan Alsabbagh
  • 25,364
  • 9
  • 55
  • 65