classification
Title: import subprocess hangs for ~25 seconds, time.py file in dir - py 2.7.3, & 2.6.6
Type: Stage: resolved
Components: Versions: Python 2.7, Python 2.6
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: Dave.Jones, icordasc, neologix
Priority: normal Keywords:

Created on 2013-02-04 16:50 by Dave.Jones, last changed 2013-02-04 21:39 by icordasc. This issue is now closed.

Messages (10)
msg181348 - (view) Author: Dave Jones (Dave.Jones) Date: 2013-02-04 16:50
import subprocess hangs for ~25 seconds, 700+ files in dir - py 2.7.3, & 2.6.6

I'm running this test from a LiveCD to make sure the environment is relatively clean.

------------------
localhost Desktop # python --version
Python 2.7.3
-------------------  <<<works fine here>>>
localhost Desktop # cat sp.py
#!/usr/bin/python

import subprocess

print "Done......."

-------------------
localhost Desktop # ls -1 | wc -l
7

-------------------
localhost Desktop # time python sp.py 
Done.......

real	0m0.027s
user	0m0.023s
sys	0m0.003s


--- BUT--- <<< This cannot be right>>>
localhost Desktop # mv sp.py  ..
mv: overwrite `../sp.py'? y
localhost Desktop # cd ..
localhost jonesda0 # cat sp.py
#!/usr/bin/python

import subprocess

print "Done......."
localhost jonesda0 # time python sp.py 
100000000
Done.......

real	0m25.336s
user	0m25.270s
sys	0m0.014s
localhost jonesda0 # ls -1 | wc -l
758

Only change is the number of files in the directory.
I have tested this on several different LiveCDs but the results are the same.  Is there some sort of flag I need to know about?

FWIW, I do not see the problem when using python3..

localhost jonesda0 # yum -y install python3
Loaded plugins: fastestmirror, langpacks, presto, refresh-packagekit
...
Installed:
  python3.i686 0:3.1.2-14.fc14                                                                                                         

Dependency Installed:
  python3-libs.i686 0:3.1.2-14.fc14                                                                                                    

Complete!
localhost jonesda0 # time python3 sp.py  ## (print function...duh)
  File "sp.py", line 5
    print "Done......."
                      ^
SyntaxError: invalid syntax

real	0m0.048s
user	0m0.044s
sys	0m0.004s
localhost jonesda0 # vi sp.py 
localhost jonesda0 # time python3 sp.py 
Done.......

real	0m0.091s
user	0m0.084s
sys	0m0.006s

localhost jonesda0 # python3 --version
Python 3.1.2
msg181350 - (view) Author: Dave Jones (Dave.Jones) Date: 2013-02-04 16:53
That line (100000000) seems to pop up every time the subprocess call "hangs"
msg181351 - (view) Author: Dave Jones (Dave.Jones) Date: 2013-02-04 17:02
Distros tested with include Funduntu 2012-4, Fuduntu 2013-1, Fedora 17, Scientific Linux 6.3 & OpenSUSE 12.2 (all 32-bit) on the same hardware.
msg181370 - (view) Author: Dave Jones (Dave.Jones) Date: 2013-02-04 18:49
I think I found something but I do not know what it means.
Everytime the import hangs, it seems to leave behind a "time.pyc"
There are only 29 files in this directory.

[jonesda0@linux-2py2 pycode]$ ls -1tr
py5.py*
py4.py*
py3.py*
py2.py*
py1.py*
print_func.py
test.py
ex3-4.py
time.py
time2.py
sample.py
os_test.py
params.py
changeparam.py
parity.py
remove_vowels.py
sqlite_version.py
sqlite_version_with.py
sqlite_insert.py
sqlite_insert2.py
sqlite_friends_last.py
sqlite_getall.py
dc4g2-report.rpt
out_dc4g2-report.rpt
num_guess.py
report_db_import.py*
test-sp.py
sp.py
test/
[jonesda0@linux-2py2 pycode]$ python sp.py 
100000000
Done.......
[jonesda0@linux-2py2 pycode]$ ls -1tr
py5.py*
py4.py*
py3.py*
py2.py*
py1.py*
print_func.py
test.py
ex3-4.py
time.py
time2.py
sample.py
os_test.py
params.py
changeparam.py
parity.py
remove_vowels.py
sqlite_version.py
sqlite_version_with.py
sqlite_insert.py
sqlite_insert2.py
sqlite_friends_last.py
sqlite_getall.py
dc4g2-report.rpt
out_dc4g2-report.rpt
num_guess.py
report_db_import.py*
test-sp.py
sp.py
test/
time.pyc <<<<<<<<<<<<<<<
msg181371 - (view) Author: Ian Cordasco (icordasc) * Date: 2013-02-04 18:55
Could you give us the contents of your time.py file? I wonder if there's something in that file that is causing the import to hang. It's the only reason I can think of as to why the time.pyc file shows up.

Also, if you want to check before-hand, make a new directory with just those two files and see what happens.
msg181373 - (view) Author: Ian Cordasco (icordasc) * Date: 2013-02-04 18:57
As a further note, on python 2.6, I just touched a file called time.py, and in the interpreter imported subprocess. It didn't hang because the file was empty but it did generate a pyc file. This is almost certainly the root of your problem. I doubt this is a core python problem.
msg181387 - (view) Author: Dave Jones (Dave.Jones) Date: 2013-02-04 20:59
Hello Ian.
Thank you for the reply.

As I imagine you understand, I delete the "time.pyc" file every time it comes back.

That being said, there *is* a "time.py" script in there from some testing I was doing:

[jonesda0@toshiba pycode]$ ls -1tr *.py* | egrep "sp|time"
time.py
time2.py
test-sp.py
sp.py
--------------------------------------------
[jonesda0@toshiba pycode]$ cat time.py
i = 0
j = 0

while (i < 100000000):
    # i = i + 1
    i+=1
    # j = j + 1
    j+=1

print j

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

[jonesda0@toshiba pycode]$ python sp.py
100000000
Done.......
[jonesda0@toshiba pycode]$ ls -1tr *.py* | egrep "sp|time"
time.py
time2.py
test-sp.py
sp.py
time.pyc

------------------------------
I am not calling any sort of "time.py" anywhere:
[jonesda0@toshiba pycode]$ cat sp.py  ## still took about 25 seconds

import subprocess

print ("Done.......")
------------------------------

So where does this behavior come from?

[jonesda0@toshiba pycode]$ cat time.pyc  ## There is all sorts of Escape code in the file, obviously.

���Pc@s<dZdZx$edkr2ed7Zed7ZqWeGHdS(ii��iN(titj(((s/home/jonesda0/pycode/time.py<module>s

[jonesda0@toshiba pycode]$ file time.pyc
time.pyc: python 2.7 byte-compiled
[jonesda0@toshiba pycode]$ 


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

[jonesda0@toshiba pycode]$ rm -f time.pyc
[jonesda0@toshiba pycode]$ mv time.py time.py.bad
[jonesda0@toshiba pycode]$ time python sp.py
Done.......

real	0m0.027s
user	0m0.021s
sys	0m0.005s

[jonesda0@toshiba pycode]$ ls -1tr *.py* | egrep "sp|time"
time.py.bad
time2.py
test-sp.py
sp.py

--------------------------
Your hypothesis is clearly accurate, but my question is now *WHY*?
I was in no way calling a python time function or time.py, it just happened to be in the directory!

Thanks
msg181388 - (view) Author: Dave Jones (Dave.Jones) Date: 2013-02-04 21:01
Tried to edit subject to make it easier to search
msg181390 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2013-02-04 21:36
You happen to have a script named time.py, so when the subprocess module is imported, it imports this script instead of the correct time module.
Nothing is wrong, closing.
msg181391 - (view) Author: Ian Cordasco (icordasc) * Date: 2013-02-04 21:39
Dave, at some point during the import of subprocess the time module is apparently imported. Because of how imports work, it is importing your local copy instead of the standard library version.

I would wager money that if you ran time python time.py (on your script) it would take roughly 25 seconds. If I run python verbosely and then import subprocess, I get the following output

>>> import subprocess
# /usr/lib64/python2.6/subprocess.pyc matches /usr/lib64/python2.6/subprocess.py
import subprocess # precompiled from /usr/lib64/python2.6/subprocess.pyc
# /usr/lib64/python2.6/traceback.pyc matches /usr/lib64/python2.6/traceback.py
import traceback # precompiled from /usr/lib64/python2.6/traceback.pyc
import gc # builtin
dlopen("/usr/lib64/python2.6/lib-dynload/time.so", 2);
import time # dynamically loaded from /usr/lib64/python2.6/lib-dynload/time.so

That is without the time.py file in the directory. When the file does exist there, I get the following:
>>> import subprocess
# /usr/lib64/python2.6/subprocess.pyc matches /usr/lib64/python2.6/subprocess.py
import subprocess # precompiled from /usr/lib64/python2.6/subprocess.pyc
# /usr/lib64/python2.6/traceback.pyc matches /usr/lib64/python2.6/traceback.py
import traceback # precompiled from /usr/lib64/python2.6/traceback.pyc
import gc # builtin
import time # from time.py
# wrote time.pyc

In short, python checks your current working directory for a file to import. If it finds it, it uses that first. You can examine the order in which python looks for modules and packages by importing sys and looking at sys.path.

This issue can be closed. If you have further questions Dave, feel free to email me personally and I'll do my best to answer them.
History
Date User Action Args
2013-02-04 21:39:56icordascsetmessages: + msg181391
2013-02-04 21:36:27neologixsetstatus: open -> closed

nosy: + neologix
messages: + msg181390

resolution: not a bug
stage: resolved
2013-02-04 21:01:54Dave.Jonessetmessages: + msg181388
title: import subprocess hangs for ~25 seconds, 700+ files in dir - py 2.7.3, & 2.6.6 -> import subprocess hangs for ~25 seconds, time.py file in dir - py 2.7.3, & 2.6.6
2013-02-04 20:59:47Dave.Jonessetmessages: + msg181387
2013-02-04 18:57:57icordascsetmessages: + msg181373
2013-02-04 18:55:36icordascsetnosy: + icordasc
messages: + msg181371
2013-02-04 18:49:06Dave.Jonessetmessages: + msg181370
2013-02-04 17:02:56Dave.Jonessetmessages: + msg181351
2013-02-04 16:53:51Dave.Jonessetmessages: + msg181350
2013-02-04 16:50:54Dave.Jonescreate