Repository navigation
Cache locked errors when download cache dir is on NFS #9970
Description
Description
We use Astropy on the LIGO-Caltech computing cluster on which users' home directories are shared across all worker nodes using NFS. We are finding that when users are running many Python scripts at once that use Astropy, a large fraction of the jobs are failing with the error:
RuntimeError: Cache is locked after 5.02 s. This may indicate an astropy bug or that kill -9 was used. If you want to unlock the cache remove the directory /home/leo.singer/.astropy/cache/download/py3/lock. Lock claims to be held by process 14764.
The error even happens if we run the script once first on the submit node to pre-populate the cache before running it on the worker nodes.
We know that we could work around this issue by setting environment variables to put the cache directory on a non-NFS filesystem (e.g. in /tmp). However, this is a new issue in the most recent version of Astropy: we are only seeing this error with Astropy 4.0, and not with 3.2.3. So in the past, Astropy seemed to be more robust on our clusters when running with the cache in an NFS mount, without any environment tuning.
I've created a minimal test case that is able to reproduce the failure by getting the EarthLocation site registry.
These symptoms are similar to #9642, but that was fixed in Astropy 4.0, and we are seeing this issue in Astropy 4.0.
Expected behavior
In every run, including the runs on the worker nodes, the test Python script runs to completion, prints the text All OK, and exits with status 0.
Actual behavior
In many runs on the worker nodes, the Python script raises this exception and crashes:
WARNING: leap-second auto-update failed due to the following exception: RuntimeError('Cache is locked after 5.02 s. This may indicate an astropy bug or that kill -9 was used. If you want to unlock the cache remove the directory /home/leo.singer/.astropy/cache/download/py3/lock. Lock claims to be held by process 26260.',) [astropy.time.core]
Traceback (most recent call last):
File "/home/leo.singer/astropy-4.0-test/./test.py", line 3, in <module>
EarthLocation._get_site_registry()
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/coordinates/earth.py", line 529, in _get_site_registry
reg = get_downloaded_sites()
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/coordinates/sites.py", line 135, in get_downloaded_sites
content = get_pkg_data_contents('coordinates/sites.json', encoding='UTF-8')
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/utils/data.py", line 701, in get_pkg_data_contents
cache=cache) as fd:
File "/usr/lib64/python3.6/contextlib.py", line 81, in __enter__
return next(self.gen)
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/utils/data.py", line 505, in get_pkg_data_fileobj
conf.dataurl_mirror + data_name],
File "/usr/lib64/python3.6/contextlib.py", line 81, in __enter__
return next(self.gen)
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/utils/data.py", line 236, in get_readable_fileobj
http_headers=http_headers)
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/utils/data.py", line 1127, in download_file
with _cache(pkgname) as (dldir, url2hash):
File "/usr/lib64/python3.6/contextlib.py", line 81, in __enter__
return next(self.gen)
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/utils/data.py", line 1690, in _cache
with _cache_lock(pkgname), shelve.open(urlmapfn, flag="r") as url2hash:
File "/usr/lib64/python3.6/contextlib.py", line 81, in __enter__
return next(self.gen)
File "/home/leo.singer/astropy-4.0-test/env/lib64/python3.6/site-packages/astropy/utils/data.py", line 1591, in _cache_lock
raise RuntimeError(msg)
RuntimeError: Cache is locked after 5.02 s. This may indicate an astropy bug or that kill -9 was used. If you want to unlock the cache remove the directory /home/leo.singer/.astropy/cache/download/py3/lock. Lock claims to be held by process 14764.Steps to Reproduce
- Clean all cache data:
$ rm -rf ~/.cache ~/.astropy
- Run test script once on the submit node to prime the cache:
$ ./test.py
Downloading https://hpiers.obspm.fr/iers/bul/bulc/Leap_Second.dat
|=======================================================================================| 1.3k/1.3k (100.00%) 0s
Downloading http://data.astropy.org/coordinates/sites.json
|=======================================================================================| 23k/ 23k (100.00%) 0s
All OK
- Submit 100 instances of the script to the HTCondor scheduler to farm them out to the worker nodes:
$ mkdir -p logs
$ condor_submit test.sub
Submitting job(s)....................................................................................................
100 job(s) submitted to cluster 141880176.
Python script test.py:
#!/usr/bin/env python
from astropy.coordinates import EarthLocation
EarthLocation._get_site_registry()
print('All OK')HTCondor submit file test.sub:
accounting_group = ligo.dev.o3.cbc.pe.bayestar
universe = vanilla
executable = ./test.py
getenv = true
error = logs/$(Cluster).$(Process).err
queue 100
System Details
Linux-3.10.0-1062.12.1.el7.x86_64-x86_64-with-redhat-7.7-Nitrogen
Python 3.6.8 (default, Aug 7 2019, 19:55:42)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-39)]
Numpy 1.18.1
astropy 4.0
(scipy not installed)
I will ask the LIGO Lab computing team to post relevant details about file system configuration.
Activity
stuartthebruce commentedon Feb 20, 2020
This occurred for NFS v3 over TCP. Note, the backend Solaris 11 NFS server is occasionally overloaded with a large number of NFS clients, including lockd_kproc that processes NFS file locks. This is one of the reasons we are in the processes of evaluating a move from NFS to Ceph.
However, independent of that, I recommend that these jobs run inside the HTCondor managed sandbox and not rely on NFS.
pllim commentedon Feb 20, 2020
@aarchiba , do we need to lock the cache in read-only mode?
astropy/astropy/utils/data.py
Lines 1686 to 1690 in aa3856e
p.s. Okay, maybe we need to lock it so a write cannot happen while reading. I need to dig more...
pllim commentedon Feb 20, 2020
@aarchiba , do you think
astropy/astropy/utils/data.py
Line 1567 in aa3856e
also needs to be in the
except FileExistsErrorblock? If the cache is locked for reading and another process comes and tries to read the same file too, it should be okay?aarchiba commentedon Feb 20, 2020
Under normal operation, the behaviour should be:
If the cache is determined to be read-only, no locking is done at all; it's not necessary in this case and this is meant as an in-case-of-emergency sort of solution to the kind of problem the OP is having.
If the shelve is backed by gdbm, as it normally is on linux (though not under Anaconda), the shelve itself is under a reader-writer lock that is difficult for astropy to recover from; Astropy's own locking mechanism is designed to ensure the shelve is only accessed by one thread/process at a time.
Astropy's cache locking mechanism is based on the atomic nature of mkdir; this is a property that is supposed to be enforced by UNIX filesystems as well as Windows, and as far as I know NFS implementations respect it, though AFS does not.
The 4.0 modifications to the caching mechanism replaced a number of situations where the shelve was accessed in an unsafe concurrent way, moving them behind locks. So while the lock-unavailable exceptions are very unfortunate, I think that they replace potential corruption of the shelve and mysterious failures. Nevertheless they should not occur under any kind of reasonable operating condition.
aarchiba commentedon Feb 20, 2020
The
assume_cache_readonlycondition is for when the cache cannot be modified on disk and so write operations should fail but read operations do not need locking. It is distinct from, though unfortunately the name is similar to, the question of whether the lock was requested for reading or writing.aarchiba commentedon Feb 20, 2020
Sorry to assign you homework, as it were, but would you mind testing an even-more-minimal example?
prepare.pyto set up the cache (wipe it and pre-load with a local file):hammer.pyto run on the nodes (try to pull the file out of the cache, refusing to try re-downloading):Ideally you should get a "downloading" message from
prepare.pyand successful runs with no output fromhammer.py. But given that you are encountering problems, if this simple setup is enough to reproduce them, you should see the same "cache locked" error from (some of) thehammer.pyinvocations. If you get "couldn't download file" errors something strange is happening.If this misbehaves as predicted it at least localizes where the problem might be. I'll see if I have access to a machine/cluster where I can reproduce the problem. The two major branches on the problem-solving tree at the moment are, is lock contention really just taking that long? Or is something leaving the lock in place after it terminates?
aarchiba commentedon Feb 20, 2020
One sign that the caching has gone wrong is if you hit the stage of deleting the lock directory and it's already gone:
astropy/astropy/utils/data.py
Line 1606 in aa3856e
Unfortunately this happens every time in
clear_download_cache()because the whole cache is gone. Or it happens if the cache directory was readonly so we never made the lock directory. But perhaps I could detect both of those conditions and signal a problem in any other case where the directory is unexpectedly missing. Not guaranteed this would catch the OP's case, since they are seeing too few lock removals rather than too many but it might alert users to non-atomicmkdir()or internal astropy bugs.lpsinger commentedon Feb 24, 2020
@aarchiba, prepare.py prints the warning "Not clearing data from cache...Directory not empty", even if I first nuke the entire astropy directory with
rm -rf ~/.astropy.Of 100 instances of hammer.py, 60 succeeded and 40 failed with a RuntimeError. In one of the 40 failures, the PID in the RuntimeError message was blank. In the other 39 failures, there was an integer pid PID in the RuntimeError message.
pllim commentedon Feb 24, 2020
Thanks, @lpsinger . Your
shutils.rmtreefailing inprepare.pysounds a lot like ansible/ansible#34335 (comment) . Do you have other things that are accessing the cache at that time that is unrelated to the scripts being run here?lpsinger commentedon Feb 24, 2020
No, I don't. No other jobs on the cluster, no cron jobs, etc.
lpsinger commentedon Feb 25, 2020
@aarchiba, @pllim: just after shutil.rmtree fails, the only file in the cache directory is an NFS hidden file:
lpsinger commentedon Feb 25, 2020
Looks like the
.nfsNNNN....file above is an NFS "silly rename", an artifact of how NFS fakes the UNIX practice of deleting an open file. The question is, which file was that? Is that the lock file? If so, maybe the problem is that the cache is still locked while it is being deleted?2 remaining items
aarchiba commentedon Feb 25, 2020
Indeed it is, and
clear_download_cache()is unnecessarily making trouble here. This I can fix.aarchiba commentedon Feb 25, 2020
Thanks! Hmm.
Okay, so there's definitely some kind of lock contention problem. I'll have to think about how to diagnose it further.
lpsinger commentedon Feb 25, 2020
Is this a mutual exclusion lock? Or can there be multiple readers simultaneously?
aarchiba commentedon Feb 25, 2020
It's a simple mutex, implemented by using the (supposed) atomicity of
os.mkdir. No long operation is ever carried out with the lock held; it's essentially just opening a shelve object and doing a lookup or modification.If there is a slow step, it's almost certainly the
os.mkdiritself - for it to be atomic NFS has to synchronize with the server.One could use a reader/writer lock, and in fact if the shelve object is using the gdbm backend it includes a reader-writer lock, but I'm not sure how that's implemented (in particular whether it works on NFS at all) and the gdbm backend is often not available; plus the
os.mkdirsetup is compatible with Astropy versions going way back (modulo their locking bugs).It might be possible to come up with a lock-free implementation (breaking backward compatibility) that abandoned shelve entirely and used a directory as the url->hash mapping. This would possibly cause problems for very long URLs, and clearing or updating url content might be able to cause concurrency problems, but it would ensure clean fast operation for the majority of cases even over NFS. (Actually I'd just store the content in a file named by the quoted url...) The challenge would be avoiding compatibility headaches with older versions of astropy on the same machine.
zonca commentedon Apr 16, 2020
we are seeing the same issue accessing the astropy cache from multiple MPI processes, see healpy/healpy#609
wumpus commentedon Jun 1, 2020
My astronomy colleagues are also having difficulty using astropy in MPI jobs. Home directories on this supercomputer are NFS mounted, and the behavior they see differs depending on load.
In the last couple of jobs I preloaded the astropy cache with the one file that I actually need, and got 1099 warnings for a 672 core job running across 14 nodes. When all was said and done the py3/lock/ directory remained present, despite the fact that no parts of the job exited. Which is a "can't happen" situation.
Here's what /proc/mounts has for an example home directory on a compute node:
zonca commentedon Jun 1, 2020
Only workaround I've found for now is to first check a local folder, and make sure all HPC jobs first have all the necessary data downloaded locally
pllim commentedon Jun 2, 2020
If anyone has idea on how to fix this in https://github.com/astropy/astropy/blob/master/astropy/utils/data.py , please feel free to submit an exploratory PR (you can even mark it as Draft PR if you want). My drastic approach (if I ever find time to revisit this) would be to remove locking bit by bit until this works, but I understand that @aarchiba is not very thrilled about it. 😅
aarchiba commentedon Jun 2, 2020
I can't reproduce the problem on the cluster I have access to - home directory over nfs4, a hundred hammer jobs submitted through slurm run fine. (It's a busy cluster so maybe they're not all running at once?) Frustrating, because some people are clearly having problems.
There is a lock-free implementation possible, but it'll take some time.
In the meantime a workaround that should work is to pre-populate the cache and then set it to read-only (that is, all files and directories read-only, or the whole filesystem); when it's read-only no locking is done.
aarchiba commentedon Jun 2, 2020
If you just remove the locks, you will crash into the gdbm reader-writer lock. What will happen on other shelve backends is unclear, but cache corruption or other locking problems are both possibilities (as they are with gdbm over NFS; the current lock scheme resolved certain locking problems even on single machines). I did put it in for a reason, and as conservatively as I could.
As far as I can tell the problem must be that some NFS implementations do not have an atomic mkdir(), though what that means is unclear to me - currently I assume that it either succeeds and creates a directory which will remain until removed, or it raises an exception. I think to break things mkdir() must claim to have succeeded on two different machines, so that when they exit they both unlock the lock?
wumpus commentedon Jun 3, 2020
With the read-only workaround, I was a bit nervous that problems might develop if a colleague is accidentally left with a read-only cache for years. There's a lot of noise if a new file is needed and can't be written to the cache. Looking at the IERS downloading code -- it re-downloads itself after 30 days -- it appears that it will be noisy in that case, too.
I don't have any good suggestions for a backward-compatible fix. Do users actually have large enough caches to be bothered by an incompatible change in a new astropy version? Anything that avoids a lock for reading will make everyone's supercomputing lives easier.
aarchiba commentedon Jun 3, 2020
Yeah, if the file needs re-downloading and isn't in the cache every node will request it over the Net. That's not ideal. Neither, as you say, is having to switch between read-only and not. But it should allow people to use this version of astropy until a better option is available (see PR, which I am going to need help testing on machines that exhibit the problem).
aarchiba commentedon Jun 5, 2020
We have one report of #10437 solving the problem - certainly it is lock-free, and it passes the extensive test suite.