[ python-Bugs-1634739 ] Problem running a subprocess

[SourceForge.net]

Bugs item #1634739, was opened at 2007-01-13 15:46
Message generated for change (Comment added) made by frougon
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1634739&group_id=5470

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Python Library
Group: Python 2.5
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Florent Rougon (frougon)
Assigned to: Nobody/Anonymous (nobody)
Summary: Problem running a subprocess

Initial Comment:
Hello,

I have a problem running a subprocess from Python (see below). I first ran into it with the subprocess module, but it's also triggered by a simple os.fork() followed by os.execvp().

So, what is the problem, exactly? I have written the exact same minimal program in C and in Python, which uses fork() and execvp() in the most straightforward way to run the following command:

  transcode -i /tmp/file.mpg -c 100-101 -o snapshot -y im,null -F png

(whose effect is to extract the 100th frame of /tmp/file.mpg and store it into snapshot.png)

The C program runs fast with no error, while the one in Python takes from 60 to 145 times longer (!), and triggers error messages from transcode. This shouldn't happen, since both programs are merely calling transcode in the same way to perform the exact same thing.

Experiments
------------

1. First, I run the C program (extract_frame) twice on a first .mpg file (MPEG 2 PS) [the first time fills the block IO cache], and store the output in extract_frame.output:

  % time ./extract_frame >extract_frame.output 2>&1
  ./extract_frame > extract_frame.output 2>& 1  0.82s user 0.33s system 53% cpu 2.175 total
  % time ./extract_frame >extract_frame.output 2>&1
  ./extract_frame > extract_frame.output 2>& 1  0.79s user 0.29s system 96% cpu 1.118 total

Basically, this takes 1 or 2 seconds. extract_frame.output is attached.

Second, I run the Python program (extract_frame.py) on the same .mpg file, and store the output in extract_frame.py.output:

  % time ./extract_frame.py >extract_frame.py.output 2>&1 
  ./extract_frame.py > extract_frame.py.output 2>& 1  81.59s user 25.98s system 66% cpu 2:42.51 total

This takes more than 2 *minutes*, not seconds!
(of course, the system is idle for all tests)

In extract_frame.py.output, the following error message appears quickly after the process is started:

  failed to write Y plane of frame(demuxer.c) write program stream packet: Broken pipe

which is in fact composed of two error messages, the second one starting at "(demuxer.c)".

Once these messages are printed, the transcode subprocesses[1] seem to hang (with relatively high CPU usage), but eventually complete, after 2 minutes or so.

There are no such error messages in extract_frame.output.

2. Same test with another .mpg file. As far as time is concerned, we have the same problem:

  [C program]
  % time ./extract_frame >extract_frame.output2 2>&1     
  ./extract_frame > extract_frame.output2 2>& 1  0.73s user 0.28s system 43% cpu 2.311 total

  [Python program]
  % time ./extract_frame.py >extract_frame.py.output2 2>&1
  ./extract_frame.py > extract_frame.py.output2 2>& 1  92.84s user 12.20s system 76% cpu 2:18.14 total

We also get the first error message in extract_frame.py.output2:

  failed to write Y plane of frame

when running extract_frame.py, but this time, we do *not* have the second error message:

  (demuxer.c) write program stream packet: Broken pipe

All this is reproducible with Python 2.3, 2.4 and 2.5 (Debian packages in sarge for 2.3 and 2.4, vanilla Python 2.5).

  % python2.5 -c 'import sys; print sys.version; print "%x" % sys.hexversion'
  2.5 (r25:51908, Jan  5 2007, 17:35:09) 
  [GCC 3.3.5 (Debian 1:3.3.5-13)]
  20500f0

  % transcode --version
  transcode v1.0.2 (C) 2001-2003 Thomas Oestreich, 2003-2004 T. Bitterberg

I'd hazard that Python is tweaking some process or threading parameter that is inherited by subprocesses and disturbs transcode, which doesn't happen when calling fork() and execvp() from a C program, but am unfortunately unable to precisely diagnose the problem.

Many thanks for considering.

Regards,

Florent

  [1] Plural because the transcode process spawns several childs: tcextract, tcdemux, etc.

----------------------------------------------------------------------

>Comment By: Florent Rougon (frougon)
Date: 2007-01-13 15:49

Message:
Logged In: YES 
user_id=310088
Originator: YES

File Added: Makefile

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1634739&group_id=5470