<div dir="ltr">Adding a printing destructor to threading.Event seems to aggravate timing problems, causing several tests to fail to make their inferiors and that seemingly keeps us below the open file limit. That aside, the destructor did fire many hundreds of times, so there's not a general problem stopping all or even most of those to be cleaned up.<div><br></div><div>The event objects that I'm seeing with the Sysinternals tools are likely Windows Events that Python creates to facilitate the interprocess communication.</div><div><br></div><div>I'm looking at the ProcessDriver lifetimes now.</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Oct 6, 2015 at 9:54 AM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Okay.<div><br></div><div>A promising avenue might be to look at how Windows cleans up the threading.Event objects. Chasing that thread might yield why the events are not going away (assuming those are the events that are lingering on your end). One thing you could consider doing is patching in a replacement destructor for the threading.Event and print something when it fires off, verifying that they're really going away from the Python side. If they're not, perhaps there's a retain bloat issue where we're not getting rid of some python objects due to some unintended references living beyond expectations.</div><div><br></div><div>The dosep.py call_with_timeout method drives the child process operation chain. That thing creates a ProcessDriver and collects the results from it when done. Everything within the ProcessDriver (including the event) should be cleaned up by the time the call_with_timeout() call wraps up as there shouldn't be any references outstanding. It might also be worth you adding a destructor to the ProcessDriver to make sure that's going away, one per Python test inferior executed.</div></div><div class="gmail_extra"><div><div class="h5"><br><div class="gmail_quote">On Tue, Oct 6, 2015 at 9:48 AM, Adrian McCarthy <span dir="ltr"><<a href="mailto:amccarth@google.com" target="_blank">amccarth@google.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Python 2.7.10 made no difference. I'm dealing with other issues this afternoon, so I'll probably return to this on Wednesday. It's not critical since there are workarounds.</div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Oct 6, 2015 at 9:41 AM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><br><div class="gmail_extra"><br><div class="gmail_quote"><span>On Mon, Oct 5, 2015 at 3:58 PM, Adrian McCarthy <span dir="ltr"><<a href="mailto:amccarth@google.com" target="_blank">amccarth@google.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div>Different tools are giving me different numbers.</div><div><br></div><div><div>At the time of the error, Windbg says there are about 2000 open handles, most of them are Event handles, not File handles. That's higher than I'd expect, but not really concerning.</div></div><div><br></div></div></blockquote><div><br></div></span><div>Ah, that's useful. I am using events (python threading.Event). These don't afford any clean up mechanisms on them, so I assume these go away when the Python objects that hold them go away.</div><span><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div></div><div>Process Explorer, however, shows ~20k open handles per Python process running dotest.exe. It also says that about 2000 of those are the process's "own handles." I'm researching to see what that means. I suspect it means that the process has about ~18k handles to objects owned by another process and 2k of ones that it actually owns.</div><div><br></div><div>I found this Stack Overflow post, which suggests is may be an interaction with using Python subprocess in a loop and having those subprocesses work with files that are still open in the parent process, but I don't entirely understand the answer:<br></div><div><div><br></div><div><a href="http://stackoverflow.com/questions/16526783/python-subprocess-too-many-open-files" target="_blank">http://stackoverflow.com/questions/16526783/python-subprocess-too-many-open-files</a><br></div><div><br></div></div></div></blockquote><div><br></div></span><div>Hmm I'll read through that.</div><span><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div><div></div><div>It might be a problem with Python subprocess that's been fixed in a newer version. I'm going to try upgrading from Python 2.7.9 to 2.7.10 to see if that makes a difference.</div></div></div><div class="gmail_extra"><br></div></blockquote><div><br></div></span><div>Okay, we're on 2.7.10 on latest OS X. I *think* I'm using Python 2.7.6 on Ubuntu 14.04. Checking now... (yes, 2.7.6 on 14.04). Ubuntu 15.10 beta 1 is using Python 2.7.10.</div><div><br></div><div>Seems reasonable to check that out. Let me know what you find out!</div><div><br></div><div>-Todd</div><div><div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="gmail_extra"><div class="gmail_quote">On Mon, Oct 5, 2015 at 12:02 PM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">It's possible. However, I was monitoring actual open files during the course of the run (i.e. what the kernel thought was open for the master driver process, which is the only place that makes sense to see leaks accumulate) in both threading and threading-pool (on OS X), and I saw only the handful of file handles that I'd expect to be open - pipes (stdout,stderr,stdin) from the main test runner to the inferior test runners, the shared libraries loaded as part of the test runner, and (in my case, but probably not yours for the configuration), the tcp sockets for gathering the test events. There was no growth, and I didn't see things hanging around longer than I'd expect.<div><br></div><div>The SysInternals process viewer tool is great for this kind of thing - glad you're using it. Once you find out which file handles are getting leaked and where they came from, we can probably figure out which part of the implementation is leaking it. I don't *expect* it to be on our side given that it's not showing up on a POSIX-y system, but maybe it really is but isn't in the form of a file handle on the POSIX side. I should have a look at the memory growth...</div></div><div class="gmail_extra"><div><div><br><div class="gmail_quote">On Mon, Oct 5, 2015 at 11:41 AM, Adrian McCarthy <span dir="ltr"><<a href="mailto:amccarth@google.com" target="_blank">amccarth@google.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">I'm poking around with some SysInternals tools. Over the course of test run, there are about 602k opens (CreateFiles) and 405k closes (CloseFiles) system-wide.<div><br></div><div>I'm looking for a way to stop it once the error happens, so I can see how many files each process has open. As it stands, the OS cleans up once the error is hit.</div><div><br></div><div>I wonder if it's not a matter of actually leaking open file handles but that the closes are happening too late so that we cross the threshold shortly before the test runner would have shut everything down.</div></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Mon, Oct 5, 2015 at 11:32 AM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">On OS X, I'm also not seeing growth in the --test-runner-name threading-pool (the one you were using on Windows).<div><br></div><div>Perhaps you can dig into if you're experiencing some kind of file leak on Windows. It's possible you're hitting a platform-specific leak? I recall Ed Maste hitting a FreeBSD-only leak in one or more of the python 2.7.x releases.</div></div><div class="gmail_extra"><div><div><br><div class="gmail_quote">On Mon, Oct 5, 2015 at 11:26 AM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hmm, on OS X the file handles seem to be well behaved on the --test-runner-name threading. I'm not seeing any file handle growth beyond the file handles I expect to be open.<div><br></div><div>I'll see if the threading-pool behaves differently. (That is similar to threading but uses the multiprocessing.pool mechanism, at the expense of me not being able to catch Ctrl-C at all).</div><div><br></div><div>It's possible the pool is introducing some leakage at the file level.</div></div><div class="gmail_extra"><div><div><br><div class="gmail_quote">On Mon, Oct 5, 2015 at 11:20 AM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Interesting, okay..<div><br></div><div>This does appear to be an accumulation issue. You made it most of the way through before the issue hit. I suspect we're leaking file handles. It probably doesn't hit the per-process limit on multiprocessing because the leaked files get spread across more processes.</div><div><br></div><div>(All speculation but does fit the results).</div><div><br></div><div>I'll see if I can look into what's there - if we've got an obvious leak, I'll take care of it.</div></div><div class="gmail_extra"><div><div><br><div class="gmail_quote">On Mon, Oct 5, 2015 at 9:58 AM, Adrian McCarthy <span dir="ltr"><<a href="mailto:amccarth@google.com" target="_blank">amccarth@google.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Thanks for the ideas.<div><br></div><div><span style="font-size:16px">With `--test-runner-name threading-pool`, I get too many open files.</span><br></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">With `</span><span style="font-size:16px">--test-runner-name multiprocessing-pool`, the suite runs fine.</span></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">My machine has 40 logical cores.</span></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">With `--threads=20`: SUCCESS (and perhaps _faster_).</span></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">With </span><span style="font-size:16px">`--threads=30`: SUCCESS.</span></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">With </span><span style="font-size:16px">`--threads=36`: SUCCESS.</span><span style="font-size:16px"><br></span></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">With </span><span style="font-size:16px">`--threads=38`: TOO MANY OPEN FILES.</span><span style="font-size:16px"><br></span></div><div><span style="font-size:16px"><br></span></div><div><span style="font-size:16px">So we're right at the edge. I'll keep investigating.</span></div><div><br></div><div>So it seems we're on the bleeding edge.</div><div><br></div></div><div><div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Oct 2, 2015 at 5:38 PM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">(swapped out the lldb list for the newer one)<div class="gmail_extra"><div><div><br><div class="gmail_quote">On Fri, Oct 2, 2015 at 5:37 PM, Todd Fiala <span dir="ltr"><<a href="mailto:todd.fiala@gmail.com" target="_blank">todd.fiala@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hmm, sounds suspicious.<div><br></div><div>Can you try running the tests with two options and see if you get different results?</div><div><br></div><div># should be equivalent for the default on Windows, thus should match your above results. This one uses a thread per worker queue.</div><div>--test-runner-name threading-pool</div><div><br></div><div># should use a different test runner. This one uses a process per worker queue.</div><div>--test-runner-name multiprocessing-pool</div><div><br></div><div>Aside from that, it seems like the total number of open files is exceeding some process/system maximum, which sounds like (maybe) we're leaking files somewhere. Not enough info yet to guess where that might be coming in from, but maybe a part of the test runner isn't closing files somewhere.</div><div><br></div><div>The other thing you can try is reducing the total number of threads, with:</div><div>--threads {some-number-lower-than-your-total-number-of-logical-cores}</div><div><br></div><div>in the event that your machine has a mongo number of logical cores, and perhaps it is trying to do too much. (In that case, the multiprocessing-pool runner might actually help).</div><div><br></div><div>Thanks!</div><div><br></div><div>-Todd</div></div><div class="gmail_extra"><div><div><br><div class="gmail_quote">On Fri, Oct 2, 2015 at 5:31 PM, Adrian McCarthy <span dir="ltr"><<a href="mailto:amccarth@google.com" target="_blank">amccarth@google.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">When running LLDB tests on Windows, I started getting a "too many open files" error from Python. I used git bisect to narrow it down to this revision:<div><br></div><div><a href="http://llvm.org/viewvc/llvm-project?view=revision&revision=249182" target="_blank">http://llvm.org/viewvc/llvm-project?view=revision&revision=249182</a><br></div><div><br></div><div>The error output is:</div><div><br></div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div><div><font face="monospace, monospace" size="1">Command invoked: D:\src\Python-2.7.9\PCbuild\python_d.exe D:\src\llvm\llvm\tools\lldb\test\dotest.py -q --arch=i686 --executable D:/src/llvm/build/ninja/bin/lldb.exe -s D:/src/llvm/build/ninja/lldb-test-traces -u CXXFLAGS -u CFLAGS --enable-crash-dialog -C D:\src\llvm\build\ninja_release\bin\clang.exe --inferior -p TestRecursiveTypes.py D:\src\llvm\llvm\tools\lldb\test --event-add-entries worker_index=7:int</font></div></div><div><div><font face="monospace, monospace" size="1">384 out of 400 test suites processed - TestRecursiveTypes.py Traceback (most recent call last):</font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:/src/llvm/llvm/tools/lldb/test/dotest.py", line 1457, in <module></font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:\src\llvm\llvm\tools\lldb\test\dosep.py", line 1355, in main</font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:\src\llvm\llvm\tools\lldb\test\dosep.py", line 968, in walk_and_invoke</font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:\src\llvm\llvm\tools\lldb\test\dosep.py", line 1095, in <lambda></font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:\src\llvm\llvm\tools\lldb\test\dosep.py", line 889, in threading_test_runner_pool</font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:\src\llvm\llvm\tools\lldb\test\dosep.py", line 774, in map_async_run_loop</font></div></div><div><div><font face="monospace, monospace" size="1"> File "D:\src\Python-2.7.9\Lib\multiprocessing\pool.py", line 558, in get</font></div></div><div><div><font face="monospace, monospace" size="1">OSError: [Errno 24] Too many open files</font></div></div><div><div><font face="monospace, monospace" size="1">[77809 refs]</font></div></div><div><div><font face="monospace, monospace" size="1">ninja: build stopped: subcommand failed.</font></div></div></blockquote><div><br></div><div>Any clue what might have caused this or what can be done to fix it?</div><div><br></div><div>It's Friday afternoon, so there's no urgency from my perspective. I'll probably get back to this on Monday morning.</div><div><br></div><div>Thanks,</div><div>Adrian McCarthy</div></div>
</blockquote></div><br><br clear="all"><div><br></div></div></div><span><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></div>
</blockquote></div><br><br clear="all"><div><br></div></div></div><span><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></div></div>
</blockquote></div><br></div>
</div></div></blockquote></div><br><br clear="all"><div><br></div></div></div><span><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></div>
</blockquote></div><br><br clear="all"><div><br></div></div></div><span><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></div>
</blockquote></div><br><br clear="all"><span><font color="#888888"><div><br></div></font></span></div></div><span><font color="#888888"><span><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></font></span></div><span><font color="#888888">
</font></span></blockquote></div><span><font color="#888888"><br></font></span></div><span><font color="#888888">
</font></span></div></div></blockquote></div><span><font color="#888888"><br><br clear="all"><div><br></div></font></span></div></div><span><font color="#888888"><span><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></font></span></div>
</blockquote></div><br></div>
</blockquote></div></div></div><span><font color="#888888"><br><br clear="all"><div><br></div>-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></div></div>
</blockquote></div><br></div>
</div></div></blockquote></div><br><br clear="all"><div><br></div></div></div><span class="HOEnZb"><font color="#888888">-- <br><div><div dir="ltr">-Todd</div></div>
</font></span></div>
</blockquote></div><br></div>