Python subprocesses experience mysterious delay in receiving stdin EOF

[MRAB]

On 09/02/2011 01:59, Yang Zhang wrote:
> I reduced a problem I was seeing in my application down into the
> following test case. In this code, a parent process concurrently
> spawns 2 (you can spawn more) subprocesses that read a big message
> from the parent over stdin, sleep for 5 seconds, and write something
> back. However, there's unexpected waiting happening somewhere, causing
> the code to complete in 10 seconds instead of the expected 5.
>
> If you set `verbose=True`, you can see that the straggling subprocess
> is receiving most of the messages, then waiting for the last chunk of
> 3 chars---it's not detecting that the pipe has been closed.
> Furthermore, if I simply don't do anything with the second process
> (`doreturn=True`), the first process will *never* see the EOF.
>
> Any ideas what's happening? Further down is some example output.
> Thanks in advance.
>
>      from subprocess import *
>      from threading import *
>      from time import *
>      from traceback import *
>      import sys
>      verbose = False
>      doreturn = False
>      msg = (20*4096+3)*'a'
>      def elapsed(): return '%7.3f' % (time() - start)
>      if sys.argv[1:]:
>        start = float(sys.argv[2])
>        if verbose:
>          for chunk in iter(lambda: sys.stdin.read(4096), ''):
>            print>>  sys.stderr, '..', time(), sys.argv[1], 'read', len(chunk)
>        else:
>          sys.stdin.read()
>        print>>  sys.stderr, elapsed(), '..', sys.argv[1], 'done reading'
>        sleep(5)
>        print msg
>      else:
>        start = time()
>        def go(i):
>          print elapsed(), i, 'starting'
>          p = Popen(['python','stuckproc.py',str(i), str(start)],
> stdin=PIPE, stdout=PIPE)
>          if doreturn and i == 1: return
>          print elapsed(), i, 'writing'
>          p.stdin.write(msg)
>          print elapsed(), i, 'closing'
>          p.stdin.close()
>          print elapsed(), i, 'reading'
>          p.stdout.read()
>          print elapsed(), i, 'done'
>        ts = [Thread(target=go, args=(i,)) for i in xrange(2)]
>        for t in ts: t.start()
>        for t in ts: t.join()
>
> Example output:
>
>        0.001 0 starting
>        0.003 1 starting
>        0.005 0 writing
>        0.016 1 writing
>        0.093 0 closing
>        0.093 0 reading
>        0.094 1 closing
>        0.094 1 reading
>        0.098 .. 1 done reading
>        5.103 1 done
>        5.108 .. 0 done reading
>       10.113 0 done
>
I changed 'python' to the path of python.exe and 'stuckproc.py' to its
full path and tried it with Python 2.7 on Windows XP Pro. It worked as
expected.