T
tow
I'm seeing a very strange effect which is confusing me - in brief, one
python process appears to temporarily affect the os.stat results of
another - perhaps someone can enlighten me.
This is on Mac OS X Leopard, using the system python (2.5)
The issue arises using Django. The default Django http server runs a
watcher thread, which checks if any code is changing, and reloads
itself. It does this by iterating over all loaded modules, and
checking the mtime of each __file__. This was behaving oddly, and
finding out why exposed this strangeness. (The relevant code is in
django/utils/autoreload.py)
Some of the code running under this django server imports simplejson,
the C-implemented module of which has been put at /Users/tow/.python-
eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so
This hasn't been touched since it was installed:
ls -l ~/.python-eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/
simplejson/_speedups.so
-rwxr-xr-x 1 tow staff 77596 12 Aug 17:56 /Users/tow/.python-eggs/
simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so
If I check the mtime of that file from within django, it finds it
correctly:
print datetime.datetime.utcfromtimestamp(os.stat("/Users/tow/.python-
eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so").st_mtime)
2009-08-12 17:56:02
The strange effect occurs when I open another python process, and
import simplejson there as well. As soon as I've done that, the mtime
that Django sees slips by an hour:
print datetime.datetime.utcfromtimestamp(os.stat("/Users/tow/.python-
eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so").st_mtime)
2009-08-12 16:56:02
In fact, to be precise, this happens as soon as the
simplejson._speedups module *finishes* being imported. (Tested by
stepping through every line with pdb)
The second Python process still sees the correct mtime, though, both
before and after it imports simplejson.
Restarting the Django process resets its view of the world, and it
sees the correct mtime again.
The current time as seen by the Django process is correct both before
and after the mtime slippage.
This seems to be 100% reproducible here, except for the time offset.
Usually it loses one hour, sometimes it gains 5 hours. (For what it's
worth, I'm currently on GMT, but the file was created during daylight
savings time).
I haven't managed to replicate it when the first process is something
other than Django. I've seen the effect on other Mac OS machines, but
haven't tested it on Linux so far. I've only seen the effect with
simplejson's C module, but I think this is the only C module which
might be being imported twice in this way for me.
Does anyone have any ideas what might be going on, or where further to
look? I'm at a bit of a loss.
Toby
python process appears to temporarily affect the os.stat results of
another - perhaps someone can enlighten me.
This is on Mac OS X Leopard, using the system python (2.5)
The issue arises using Django. The default Django http server runs a
watcher thread, which checks if any code is changing, and reloads
itself. It does this by iterating over all loaded modules, and
checking the mtime of each __file__. This was behaving oddly, and
finding out why exposed this strangeness. (The relevant code is in
django/utils/autoreload.py)
Some of the code running under this django server imports simplejson,
the C-implemented module of which has been put at /Users/tow/.python-
eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so
This hasn't been touched since it was installed:
ls -l ~/.python-eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/
simplejson/_speedups.so
-rwxr-xr-x 1 tow staff 77596 12 Aug 17:56 /Users/tow/.python-eggs/
simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so
If I check the mtime of that file from within django, it finds it
correctly:
print datetime.datetime.utcfromtimestamp(os.stat("/Users/tow/.python-
eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so").st_mtime)
2009-08-12 17:56:02
The strange effect occurs when I open another python process, and
import simplejson there as well. As soon as I've done that, the mtime
that Django sees slips by an hour:
print datetime.datetime.utcfromtimestamp(os.stat("/Users/tow/.python-
eggs/simplejson-2.0.9-py2.5-macosx-10.5-i386.egg-tmp/simplejson/
_speedups.so").st_mtime)
2009-08-12 16:56:02
In fact, to be precise, this happens as soon as the
simplejson._speedups module *finishes* being imported. (Tested by
stepping through every line with pdb)
The second Python process still sees the correct mtime, though, both
before and after it imports simplejson.
Restarting the Django process resets its view of the world, and it
sees the correct mtime again.
The current time as seen by the Django process is correct both before
and after the mtime slippage.
This seems to be 100% reproducible here, except for the time offset.
Usually it loses one hour, sometimes it gains 5 hours. (For what it's
worth, I'm currently on GMT, but the file was created during daylight
savings time).
I haven't managed to replicate it when the first process is something
other than Django. I've seen the effect on other Mac OS machines, but
haven't tested it on Linux so far. I've only seen the effect with
simplejson's C module, but I think this is the only C module which
might be being imported twice in this way for me.
Does anyone have any ideas what might be going on, or where further to
look? I'm at a bit of a loss.
Toby