Retry --open-files check once after garbage collection - #4002

Shouldn't we expect files to be closed without needing to run the cyclical garbage collector? I think if they aren't being closed that indicates that we've created a cycle somewhere that really shouldn't have been, and this could be a problem in real user code if files aren't being closed before the garbage collector. (In other words, I worry this is just papering over a legitimate problem here).

It's entirely possible that a cycle is created somewhere (probably in the table code--in fact I think @taldcroft recently made some changes there that may be reintroduced a reference cycle that we decided was harmless). But those sorts of reference cycles are, I think, generally not a problem as long as they can be garbage collected. It's only a problem if one the objects in the cycle holds on to a reference to a file handle too. But even that's rarely a problem in of itself outside of extreme cases like this one.

Where by "this one" I mean running lots of tests in succession and being very strict about when file handles are closed.

@embray - in case it's useful in this discussion, here is some more about the reintroduction of a reference cycle. This was discussed in #3896. I didn't end up changing the parent_table. This is a cycle between a column and its parent table, which is perhaps trickier for GC because it is a three element cycle involving also the Table.columns ordered dict.

The ref. cycle that I got rid of in f112b35 was a brand new one first introduced in the info descriptor in #3731.

Well, I've tried several times now, under varying circumstances, to manually run the test that was failing, and even with automatic garbage collection disabled completely I can't reproduce the problem. No files are being left open.

However, before this fix, when I ran the full test suite with ./setup.py test --open-files I was able to reproduce it every time (but not if I used --package=io.fits which is why I figured it was an accident of timing with the garbage collector).

Ah, actually if I switch to my branch in #4001 I am able to reproduce exactly once in a session. That is, I start Python, I set up the test, I run the test, then I call _get_open_file_list() and the file is in there. I run gc.collect() manually (it is disabled up to this point) and the file goes away. But then after subsequent runs of the test the file in question never shows up in the open file list again, even with gc disabled.

Welp--that just took all afternoon, but I think I tracked down the source of the reference cycle in question, and I guess it's good that it was caught. It's extremely subtle--more later.

I still think this is a potentially useful patch, since in general I don't think we care about file handles caught in reference cycles as long as they can be garbage collected? But what do you think @mdboom?

I really like to have predictable file closing (i.e. right after the with block), where possible, particularly on Windows where the file sharing semantics aren't quite as flexible as POSIX -- keeping a file open too long on Windows can be a real pain. But whenever you memmap numpy arrays and pass them around that ideal gets much trickier, since you have more references to the open file being passed around.

I suppose at the end of the day, if the gc gets it eventually, that's less worrisome than if not -- at least it means you don't get the "running off with 100+ file handles problems" that crop up occasionally in Python. I wonder -- is there some use of the py.test "marking" mechanism we could use so situations where the gc run is required are noted but don't cause the test suite to fail? (Essentially turn that into a warning rather than an exception)?

Yeah we could add a marker for that where necessary. The thing is, there could be any number of tests in our test suite where it might be "necessary" but we've never caught it just due to the timing of the garbage collection happening to allow the test to pass.

That's what happened in this case--I made a mostly unrelated change that caused the timing of a test to be just such that the garbage collection didn't happen in time on that test. The reference cycle was there before the test started failing--the open-files check didn't catch it because the open file handle in question (and yes it was attached to a memmap array) was attached to a reference cycle that is cleaned up properly as soon as the garbage collector runs.

I agree with you philosophically though and am glad this was caught--I would prefer not to have open file handles be part of a reference cycle. But it was still mostly an accident that this was caught at all by the open-files check.

@embray: That all makes sense. It seems like nothing will help us find all true positives.

For the marker -- I wasn't clear: I just meant that the open file checker would mark the test as "possibly has open files" if it fails before the gc is run (and then fail the test if it still fails after the gc runs as now). Then, you'd get a summary at the end saying something like "N tests possibly have open files". I didn't mean explicitly marking tests that we know fail sometimes.

@mdboom Oh, I think I understand what you're saying. That could be done, I think. Sounds worthwhile.

On another note, what do you know about the details of reference counting in Python? I'm getting some truly bizarre behavior with respect to trying to debug this reference cycle. I have a very trivial test that exhibits this behavior:

# Write simple test data:
import os
from astropy.io import fits
from astropy.table import Table
from astropy.io.fits.tests.test_connect import TestSingleTable
from astropy import units as u

if not os.path.exists('test.fits'):
    tst = TestSingleTable()
    tst.setup_class()
    table = Table(tst.data)
    table['a'].unit = u.m
    table['c'].unit = u.km / u.s
    table.write('test.fits')

# The actual test that exhibits the reference leak
def test():
    Table.read('test.fits')

If I run:

import gc
gc.disable()
test()
objgraph.by_type('ColDefs')

the last line returns a single ColDefs object, which is still tracked by the garbage collector. But there's no reason that should be hanging around. Table.read() by default copies all the data out of the FITS_rec array into new arrays that become the columns of the table.

But it gets worse. If I manually call gc.collect() that ColDefs object gets deleted and is no longer tracked by the garbage collector--suggesting that it is part of a reference cycle that gets cleaned up when the gc runs. But if I run test() any number of subsequent times I never see a ColDefs object left over. It only happens the first time around.

I did actually find a very subtle reference cycle through the implementation of the NotifierMixin class, which was keeping a reference alive through a closure (ugh). But that should be fixed by this patch:

diff --git a/astropy/io/fits/util.py b/astropy/io/fits/util.py
index 037a773..83db88a 100644
--- a/astropy/io/fits/util.py
+++ b/astropy/io/fits/util.py
@@ -34,6 +34,7 @@ from ...extern.six import (string_types, integer_types, text_type,
                            binary_type, next)
 from ...extern.six.moves import zip
 from ...utils import wraps
+from ...utils.compat import ignored
 from ...utils.compat import gzip as _astropy_gzip
 from ...utils.exceptions import AstropyUserWarning

@@ -103,18 +104,9 @@ class NotifierMixin(object):
         """

         if self._listeners is None:
-            self._listeners = []
+            self._listeners = weakref.WeakValueDictionary()

-        def remove(p):
-            self._listeners.remove(p)
-
-        # Make sure this object is not already in the listeners:
-        for ref in self._listeners:
-            if ref() is listener:
-                return
-
-        ref = weakref.ref(listener, remove)
-        self._listeners.append(ref)
+        self._listeners[id(listener)] = listener

     def _remove_listener(self, listener):
         """
@@ -125,10 +117,8 @@ class NotifierMixin(object):
         if self._listeners is None:
             return

-        for idx, ref in enumerate(self._listeners[:]):
-            if ref() is listener:
-                del self._listeners[idx]
-                break
+        with ignored(KeyError):
+            del self._listeners[id(listener)]

     def _notify(self, notification, *args, **kwargs):
...skipping...
 from ...utils.exceptions import AstropyUserWarning

@@ -103,18 +104,9 @@ class NotifierMixin(object):
         """

         if self._listeners is None:
-            self._listeners = []
+            self._listeners = weakref.WeakValueDictionary()

-        def remove(p):
-            self._listeners.remove(p)
-
-        # Make sure this object is not already in the listeners:
-        for ref in self._listeners:
-            if ref() is listener:
-                return
-
-        ref = weakref.ref(listener, remove)
-        self._listeners.append(ref)
+        self._listeners[id(listener)] = listener

     def _remove_listener(self, listener):
         """
@@ -125,10 +117,8 @@ class NotifierMixin(object):
         if self._listeners is None:
             return

-        for idx, ref in enumerate(self._listeners[:]):
-            if ref() is listener:
-                del self._listeners[idx]
-                break
+        with ignored(KeyError):
+            del self._listeners[id(listener)]

     def _notify(self, notification, *args, **kwargs):
         """
@@ -144,7 +134,7 @@ class NotifierMixin(object):
             return

         method_name = '_update_{0}'.format(notification)
-        for listener in self._listeners:
+        for listener in self._listeners.itervaluerefs():
             listener = listener()  # dereference weakref
             if hasattr(listener, method_name):
                 method = getattr(listener, method_name)

But even that doesn't seem to fix the issue, and now I'm at a total loss. What's worse is when I try to debug this in Python I'll have references to objects just disappear suddenly. I think I need to drop in to gcc to see what's really going on with this...

Also, this only seems to happen if I go through Table.read(). If I go through the normal io.fits interfaces and read columns and the like I can't reproduce this.

Okay, getting a little deeper on this--the test that failed might not be due to an innocent timing accident after all, and may have actually caught a real problem directly related to the units code...?

I don't know what I know about reference cycles that you don't already -- I see you've already discoverd objgraph which can sometimes be helpful here.

I'm poking around with your example, but haven't found much yet. Where did your investigation with Units lead you to? That's a surprising one, since they are pretty simple data types underneath (not saying it isn't possible, though, just that nothing obvious comes to mind...)

I think there's a reference cycle somewhere involving the units parsing code that's holding on to a traceback object that in turn references a stack frame that references the HDUList object. Haven't worked out exactly where the cycle is, but the fact that it only happens on the first call to the test function is also indicative of something going on in the units package, since it has a number of parts that involve lazy evaluation.

Ah -- I think I've seen that kind of thing before with exceptions... I don't know if this is relevant, but the lifetime of exceptions changed between 2 and 3.

For example the following works in Python 2, but on Python 3 the e is not available outside of the except block:

def foo():
    raise ValueError("HERE")

try:
    foo()
except ValueError as e:
    pass

print(e)

Also, in Python 3, the interpreter assigns special __context__ and __cause__ members when you raise from within an except block. The unit code does do that...

(However, maybe none of that's relevant since the leak seems to appear on both Python 2 and 3).

Yes, the same issue appears in 2 and 3. I know about the possibility of leaks through exception variables, and I found a couple seemingly relevant cases in the units code, but that didn't seem to fix it.

I think, unfortunately, this actually goes all the way into PLY. Here's what I know so far: The memmap that's staying in memory is tied all the way back to an HDUList object that's hanging around, which itself is referenced by a couple of frame objects which, by this point, should no longer exist. I haven't figured out exactly what's holding on those frames (though I should now in a bit), but what I also found is that if I make sure the astropy.units.format.Fits parser and lexer are created before running the test, then the problem doesn't appear. So that implies that something in PLY (which as you know is full of magic) is holding on to references to those stack frames (which are parent frames to the call trace that led to the lex and yacc functions being called).

Turns out this actually did catch a real issue, albeit a minor one. It was still a reference cycle that was able to be cleaned up by the garbage collector, but it was still a really good catch nonetheless--I don't like file handles hanging around in reference cycles.

But I would like to update this to still collect a list of tests that may have problems like this, and report that at the end of the test, while still not failing the test outright, as @mdboom suggested.

I concluded from the dicussions that this PR was incomplete and unlikely will be worked on anymore. So closing.