So this memory problem had been biting us in the ass for some time. Beagle seemed to be running happily, and then as inotify events on the file system came in, usage would slowly grow and grow. Depending on how long you left it running and how many events were coming in and at what rate, you could very easily have a mammoth daemon overnight.
Every time a file is touched on the file system, we have to do a lookup in the file system index to see if the file has actually been indexed already. You can’t rely on the file name, because they can easily change. We assign a unique ID to files and and store them in the extended attributes or sqlite fallback database and look them up in the index to see if they match. If they do, they’re the same file and don’t require a reindex. If you were copying a huge set of complicated files across filesystems, for example, you really, really want to avoid indexing them all again. Instantiating Lucene’s IndexReader objects is pretty expensive operation, so I originally wrote a patch which cached and reused them if the underlying index hadn’t changed. This gave us a real win when just crawling across your filesystem or doing queries.
Unfortunately, when something happened which did update the index on disk, like copying files or untarring a tarball, you would have to instantiate a new IndexReader. So we lost any gain in that situation.
How did I track this down? First, I set up beagle to only index files in a little sandbox, using heap-buddy:
$ BEAGLE_HOME=/tmp/sandbox beagled --fg --debug-memory --heap-buddy --allow-backend files
The --debug-memory option runs a thread which prints out some statistics every 5 seconds: our VmSize and VmRSS according to our PID in /proc, and GC.GetTotalMemory, which is the current heap size in Mono. The --heap-buddy option gets processed in our wrapper script and essentially adds --profile=heap-buddy to the Mono command line.
Then I touched a file in the sandbox every 3.5 seconds:
$ while /bin/true; do touch /tmp/sandbox/foo.txt; sleep 3.5; done
Since it was the end of the day, I just let it run overnight. When I came back, it was using 300 megs RSS. I shut the daemon down, and examined the heap buddy statistics. The overall summary looked like this:
SUMMARY
Filename: outfile.beagled
Allocated Bytes: 1267.9M
Allocated Objects: 17706676
GCs: 191
Resizes: 39
Final heap size: 186.5M
Distinct Types: 429
Backtraces: 18290
The scary thing there is the final heap size: 186.5 megs. Yikes.
Digging a little deeper, I found the garbage collection history interesting:
00:09:37 | GC 51 | Collected 86724 of 217785 objects (39.8%)
| | Collected 6.1M of 18.3M (33.3%)
| | Heap went from 69.0% to 46.0% capacity
| |
00:10:30 | GC 52 | Collected 86797 of 225661 objects (38.5%)
| | Collected 6.0M of 19.0M (31.6%)
| | Heap went from 71.9% to 49.2% capacity
...
02:43:53 | GC 188 | Collected 59651 of 1437067 objects (4.2%)
| | Collected 4.2M of 143.2M (2.9%)
| | Heap went from 80.2% to 77.9% capacity
| |
02:44:27 | Resize | Grew heap from 178.5M to 186.5M
| | 143.1M in live objects
| | Heap went from 80.2% to 76.8% capacity
| |
02:44:37 | GC 189 | Collected 1379238 of 1440655 objects (95.7%)
| | Collected 141.4M of 143.5M (98.5%)
| | Heap went from 77.0% to 1.1% capacity
| |
02:44:38 | Exit | 61452 live objects using 2.1M
You can see over time that we’re collecting roughly the same number of bytes and objects each time, but the overall percent decreases over time… until the last collection anyway, when we massively collect 95.7% — that’s 141.4 megs — of our objects. So it’s very clear we’re leaking objects somehow that the GC just can’t pick up.
I examined the top four types that are created:
Type # Total AvSz AvAge BT#
byte[] 1445345 596.6M 432.8 4.3 475
string 5959690 273.4M 48.1 1.2 4976
char[] 1113478 74.4M 70.0 11.1 376
System.Collections.Hashtable/Slot[] 275074 67.5M 257.5 11.3 400
Nothing particularly interesting or telling there. Those byte arrays are created pretty often deep in Lucene when we open those IndexReader objects. The average age (AvAge column) of 4.3, which means that on average the object lived for 4.3 collections, is a little suspicious, but that could have just been the caching of IndexReader objects.
What was really interesting was the backtrace report:
Backtrace # Total AvSz AvAge
type=byte[] 40376 237.8M 6176.6 0.1
System.IO.FileStream:InitBuffer
System.IO.FileStream:.ctor
System.IO.FileStream:.ctor
Descriptor:.ctor
Lucene.Net.Store.FSIndexInput:.ctor
Lucene.Net.Store.FSDirectory:OpenInput
Lucene.Net.Index.CompoundFileReader:.ctor
Lucene.Net.Index.SegmentReader:Initialize
Lucene.Net.Index.SegmentReader:Get
Lucene.Net.Index.SegmentReader:Get
AnonymousClassWith:DoBody
With:Run
Lucene.Net.Index.IndexReader:Open
Lucene.Net.Index.IndexReader:Open
Beagle.Daemon.LuceneCommon:GetReader
Beagle.Daemon.LuceneCommon:GetSearcher
Beagle.Daemon.FileSyste...esolver:GetNameInfoById
Beagle.Daemon.FileSyste...SystemQueryable:AddFile
Beagle.Daemon.FileSyste...ueryable:HandleAddEvent
Beagle.Daemon.FileSyste...yBackend:OnInotifyEvent
Beagle.Util.Inotify:SendEvent
Beagle.Util.Inotify:DispatchWorker
Beagle.Util.ExceptionHandlingThread:ThreadStarted
...
type=byte[] 40390 40.1M 1040.0 76.1
Lucene.Net.Store.BufferedIndexInput:Clone
Lucene.Net.Index.SegmentTermEnum:Clone
Lucene.Net.Index.TermInfosReader:Terms
Lucene.Net.Index.TermInfosReader:GetEnum
Lucene.Net.Index.TermInfosReader:Get
Lucene.Net.Index.SegmentReader:DocFreq
Lucene.Net.Index.MultiReader:DocFreq
Lucene.Net.Search.IndexSearcher:DocFreq
Lucene.Net.Search.Similarity:Idf
TermWeight:.ctor
Lucene.Net.Search.TermQuery:CreateWeight
Lucene.Net.Search.Query:Weight
Lucene.Net.Search.IndexSearcher:Search
Beagle.Daemon.FileSyste...esolver:GetNameInfoById
Beagle.Daemon.FileSyste...SystemQueryable:AddFile
Beagle.Daemon.FileSyste...ueryable:HandleAddEvent
Beagle.Daemon.FileSyste...yBackend:OnInotifyEvent
Beagle.Util.Inotify:SendEvent
Beagle.Util.Inotify:DispatchWorker
Beagle.Util.ExceptionHandlingThread:ThreadStarted
The stack traces were sorted by total size allocated, and the first one you see there is the one that allocated the most bytes. Yeah, that’s a lot of data, but there’s nothing especially alarming about it. It’s only there for comparison. About 4 or 5 traces down I saw the second one. That one immediately caught my eye for one reason: Average age was 76.1 collections. That means that objects created there lived an average of 76.1 collections before being cleaned up. Seeing as we only lived for 191 collections, it’s obvious those objects are the ones being leaked. Starting at the lowest level of that stack trace, I worked my way up and found this chunk:
private SegmentTermEnum GetEnum()
{
SegmentTermEnum termEnum = (SegmentTermEnum) System.Threading.Thread.GetData(enumerators);
if (termEnum == null)
{
termEnum = Terms();
System.Threading.Thread.SetData(enumerators, termEnum);
}
return termEnum;
}
The Terms() call is the one that, a few stacks down, instantiates a SegmentTermEnum object and allocates that byte array. The result of that call was being set in thread-local data by Thread.SetData(). Everything else to that point was pretty straightforward: the data was local to an instantiation of an object, so there’s no reason why it wouldn’t have been collected. Suspcious of that assignment call, I hacked out the thread-local bits, including SetData() call, and reran the test. Although the test was only run for about 3 hours instead of overnight, these are the results:
SUMMARY
Filename: outfile.beagled
Allocated Bytes: 724.5M
Allocated Objects: 9241022
GCs: 832
Resizes: 12
Final heap size: 3.7M
Distinct Types: 429
Backtraces: 18655
Final heap size: only 3.7 megs. You can see we did a ton more GCs, which is good. That means that just about every time we instantiated one of those 8k byte arrays, a GC kicked in and cleaned them up very shortly afterward. And we only resized the heap 12 times, a far cry from the 39 previously. The GC history showed a consistent collection of roughly 35% of objects, not a decreasing pattern like the previous run. As for the backtraces, they were pretty much the same, but the trace that had an average age of 76.1 GCs had dropped to an average age of 0.0.
I dug a little into the Mono class code and found that Thread.SetData() was adding whatever you had passed in to a thread-local Hashtable. Because the Hashtable was declared static for the Thread class, it maintained a reference on every single one of those byte arrays passed into it forever. Miguel thankfully passed the issue onto the experts, Dick and Paolo, and it was resolved right away. So if you update to the latest Mono in SVN, this issue is fixed. But since most people aren't running it yet, I also committed a workaround to Beagle in CVS. It's included in the 0.2.3 release I announced earlier today.
If you are interested in the Beagle heap-buddy files to look at the data yourself, the old, exploding one is here (5.4 megs) and the fixed one is here (24 megs). To use them, decompress them and run heap-buddy on them. heap-buddy outfile.beagled.explostion history, heap-buddy outfile.beagled.explostion backtraces, etc.
Heap buddy is really a pleasure to use. The only feature request I have is that although the average age is pretty helpful, it would be even better to know the percentage of an object's lifetime to its total potential lifetime. For the leak, we had an average age of 76.1 GCs. That number is actually hurt by the fact that objects created later in the program's lifecycle will ultimately be collected in fewer GCs than earlier ones. What would have been more helpful is to see that these objects, regardless of when they were created, lived until the last GC. As a result, that percentage would have been very close to 100% for these objects since they were leaked and made it even easier to identify as problematic. So Jon, if you're looking for something to get me for St. Patrick's Day, that would be nice.
-
Pingback from First take on profiling Muine on 19 March 2006 at 7:55 am
-
Pingback from joe shaw on 29 April 2006 at 12:25 pm
Comments are now closed.
3 comments
Trackback link: http://joeshaw.org/2006/03/17/386/trackback