Path: csiph.com!usenet.pasdenom.info!weretis.net!feeder1.news.weretis.net!feeder.erje.net!eu.feeder.erje.net!newsfeed.xs4all.nl!newsfeed5.news.xs4all.nl!xs4all!newsgate.cistron.nl!newsgate.news.xs4all.nl!post.news.xs4all.nl!not-for-mail
Sender: Kushal Kumaran <kushal.kumaran@gmail.com>
From: Kushal Kumaran <kushal.kumaran+python@gmail.com>
To: "python-list\@python.org" <python-list@python.org>
Subject: Re: Subprocess puzzle and two questions
In-Reply-To: <09CE8A6B-19D5-46D6-BF36-F8BC7926A0DD@mac.com>
References: <09CE8A6B-19D5-46D6-BF36-F8BC7926A0DD@mac.com>
User-Agent: Notmuch/0.14 (http://notmuchmail.org) Emacs/24.1.1 (x86_64-pc-linux-gnu)
Date: Wed, 14 Nov 2012 12:25:19 +0530
MIME-Version: 1.0
Content-Type: text/plain
Precedence: list
Newsgroups: comp.lang.python
Message-ID: <mailman.3670.1352876131.27098.python-list@python.org>
Lines: 58
NNTP-Posting-Host: 2001:888:2000:d::a6
Xref: csiph.com comp.lang.python:33306

wrw@mac.com writes:

> I need to time the operation of a command-line utility (specifically nslookup) from within a python program I'm writing.  I don't want to use python's timeit function because I'd like to avoid python's subprocess creation overhead.  That leads me to the standard UNIX time function.  So for example, in my bash shell, if I enter:
>

It is unclear to me what overhead you are avoiding.

> 	$ time nslookup www.es.net 8.8.4.4
>
> I get:
>
> 	Server:	 	8.8.4.4
> 	Address:	8.8.4.4#53
>
> 	Non-authoritative answer:
> 	www.es.net	canonical name = www3.es.net.
> 	Name:	www3.es.net
> 	Address: 128.55.22.201
>
> 	 real	0m0.069s
> 	 user	0m0.006s
> 	 sys	0m0.004s 
>
> The first lines are the result of an nslookup of the IP address of "www.es.net" using the server at 8.8.4.4 (Google's public DNS server b).
> The last three lines are what I'm after: the real elapsed wall-clock time, the time spent in user space and the time spent in kernel space.
>
> However, if I try the same operation in the python interpreter using subprocess.Popen like so:
>
>>>> import subprocess
>>>> result = subprocess.Popen(['time', 'nslookup', 'www.es.net', '8.8.4.4'], shell = False, stdout = subprocess.PIPE, stderr = subprocess.PIPE).communicate()
>>>> print result
> ('Server:\t\t8.8.4.4\nAddress:\t8.8.4.4#53\n\nNon-authoritative answer:\nwww.es.net\tcanonical name = www3.es.net.\nName:\twww3.es.net\nAddress: 128.55.22.201\n\n', '        0.06 real         0.00 user         0.00 sys\n')
>
> And the timing information I'm after has been truncated to two digits after the decimal.  It appears that Popen is applying a default format. If I do explicit formatting:
>
>>>> time = result[1].lstrip().split(' ')[0]
>>>> formatted_time = '{: >7.3f}'.format(float(time))
>>>> print formatted_time
>   0.060
>
> I get three digits, BUT that third digit isn't real, the format operation has simply appended a zero.  So:
>
> 1) how can I recover that third digit from the subprocess?
> 2) is there a more pythonic way to do what I'm trying to do?
>
> python 2.7, OS-X 10.8.2
>

It is possible that the "time" invocation from the shell is invoking
your shell's builtin time implementation, and your python code is
running /usr/bin/time or /bin/time.  You should see the same behaviour
from the shell if you run /bin/time or /usr/bin/time (whatever you have)
instead of just "time".  subprocess.Popen should never modify the output
of programs it runs.

-- 
regards,
kushal