|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
As part of the Ruby Summer of Code, Tim Felgentreff has been building out C extension support for JRuby. He's already made great progress, with simple libraries like Thin and Mongrel working now and larger libraries like RMagick and Yajl starting to
... [More]
function. And we haven't even reached the mid-term evaluation yet. I'd say he gets an "A" so far.I figured it was time I talked a bit about C extensions, what they mean (or don't mean) for JRuby, and how you can help.The Promise of C ExtensionsOne of the "last mile" features keeping people from migrating to JRuby has been their dependence on C extensions that only work on regular Ruby. In some cases, these extensions have been written to improve performance, like the various json libraries. Some of that performance could be less of a concern under Ruby 1.9, but it's hard to claim that any implementation will be able to run Ruby as fast as C for general-purpose libraries any time soon.However, a large number of extensions – perhaps a majority of extensions – exist only to wrap a well-known and well-trusted C library. Nokogiri, for example, wraps the excellent libxml. RMagick wraps ImageMagick. For these cases, there's no alternative on regular Ruby...it's the C library or nothing (or in the case of Nokogiri, your alternatives are only slow and buggy pure-Ruby XML libraries).For the performance case, C extensions on JRuby don't mean a whole lot. In most cases, it would be easier and just as performant to write that code in Java, and many pure-Ruby libraries perform well enough to reduce the need for native code. In addition, there are often libraries that already do what the perf-driven extensions were written for, and it's trivial to just call those libraries directly from Ruby code.But the library case is a bit stickier. Nokogiri does have an FFI version, but it's a maintenance headache for them and a bug report headache for us, due to the lack of a C compiler tying the two halves together. There's a pure-Java Nokogiri in progress, but building both the Ruby bindings and emulating libxml behavior takes a long time to get right. For libraries like RMagick or the native MySQL and SQLite drivers, there are basically no options on the JVM. The Google Summer of Code project RMagick4J, by Sergio Arbeo, was a monumental effort that still has a lot of work left to be done. JDBC libraries work for databases, but they provide a very different interface from the native drivers and don't support things like UNIX domain sockets.There's a very good chance that JRuby C extension support won't perform as well as C extensions on C Ruby, but in many cases that won't matter. Where there's no equivalent library now, having something that's only 5-10x slower to call – but still runs fast and matches API – may be just fine. Think about the coarse-grained operations you feed to a MySQL or SQLite and you get the picture.So ultimately, I think C extensions will be a good thing for JRuby, even if they only serve as a stopgap measure to help people migrate small applications over to native Java equivalents. Why should the end goal be native Java equivalents, you ask?The Peril of C ExtensionsNow that we're done with the happy, glowing discussion of how great C extension support will be, I can make a confession: I hate C extensions. No feature of C Ruby has done more to hold it back than the desire for backward compatibility with C extensions. Because they have direct pointer access, there's no easy way to build a better garbage collector or easily support multiple runtimes in the same VM, even though various research efforts have tried. I've talked with Koichi Sasada, the creator of Ruby 1.9's "YARV" VM, and there's many things he would have liked to do with YARV that he couldn't because of C extension backward compatibility.For JRuby, supporting C extensions will limit many features that make JRuby compelling in the first place. For example, because C extensions often use a lot of global variables, you can't use them from multiple JRuby runtimes in the same process. Because they expect a Ruby-like threading model, we need to restrict concurrency when calling out from Java to C. And all the great memory tooling I've blogged about recently won't see C extensions or the libraries they call, so it introduces an unknown.All that said, I think it's a good milestone to show that we can support C extensions, and it may make for a "better JNI" for people who really just want to write C or who simply need to wrap a native library.How You Can HelpThere's a few things I think users like you can help with.First off, we'd love to know what extensions you are using today, so we can explore what it would take to run them under JRuby (and so we can start exploring pure-Java alternatives, too.) Post your list in the comments, and we'll see what we can come up with.Second, anyone that knows C and the Ruby C API (like folks who work on extensions) could help us fill out bits and pieces that are missing. Set up the JRuby cext branch (I'll show you how in a moment), and try to get your extensions to build and load. Tim has already done the heavy lifting of making "gem install xyz" attempt to build the extension and "require 'xyz'" try to load the resulting native library, so you can follow the usual processes (including extconf.rb/mkmf.rb for non-gem building and testing.) If it doesn't build ok, help us figure out what's missing or incorrect. If it builds but doesn't run, help us figure out what it's doing incorrectly.Building JRuby with C Extension SupportLike building JRuby proper, building the cext work is probably the easiest thing you'll do all day (assuming the C compiler/build/toolchain doesn't bite you.
Check out (or fork and check out) the JRuby repository from http://github.com/jruby/jruby:git clone git://github.com/jruby/jruby.git
Switch to the "cext" branch:git checkout -b cext origin/cext
Do a clean build of JRuby plus the cext subsystem:ant clean build-jruby-cext-native
At this point you should have a JRuby build (run with bin/jruby) that can gem install and load native extensions. [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
As part of the Ruby Summer of Code, Tim Felgentreff has been building out C extension support for JRuby. He's already made great progress, with simple libraries like Thin and Mongrel working now and larger libraries like RMagick and Yajl starting to
... [More]
function. And we haven't even reached the mid-term evaluation yet. I'd say he gets an "A" so far.I figured it was time I talked a bit about C extensions, what they mean (or don't mean) for JRuby, and how you can help.The Promise of C ExtensionsOne of the "last mile" features keeping people from migrating to JRuby has been their dependence on C extensions that only work on regular Ruby. In some cases, these extensions have been written to improve performance, like the various json libraries. Some of that performance could be less of a concern under Ruby 1.9, but it's hard to claim that any implementation will be able to run Ruby as fast as C for general-purpose libraries any time soon.However, a large number of extensions – perhaps a majority of extensions – exist only to wrap a well-known and well-trusted C library. Nokogiri, for example, wraps the excellent libxml. RMagick wraps ImageMagick. For these cases, there's no alternative on regular Ruby...it's the C library or nothing (or in the case of Nokogiri, your alternatives are only slow and buggy pure-Ruby XML libraries).For the performance case, C extensions on JRuby don't mean a whole lot. In most cases, it would be easier and just as performant to write that code in Java, and many pure-Ruby libraries perform well enough to reduce the need for native code. In addition, there are often libraries that already do what the perf-driven extensions were written for, and it's trivial to just call those libraries directly from Ruby code.But the library case is a bit stickier. Nokogiri does have an FFI version, but it's a maintenance headache for them and a bug report headache for us, due to the lack of a C compiler tying the two halves together. There's a pure-Java Nokogiri in progress, but building both the Ruby bindings and emulating libxml behavior takes a long time to get right. For libraries like RMagick or the native MySQL and SQLite drivers, there are basically no options on the JVM. The Google Summer of Code project RMagick4J, by Sergio Arbeo, was a monumental effort that still has a lot of work left to be done. JDBC libraries work for databases, but they provide a very different interface from the native drivers and don't support things like UNIX domain sockets.There's a very good chance that JRuby C extension support won't perform as well as C extensions on C Ruby, but in many cases that won't matter. Where there's no equivalent library now, having something that's only 5-10x slower to call – but still runs fast and matches API – may be just fine. Think about the coarse-grained operations you feed to a MySQL or SQLite and you get the picture.So ultimately, I think C extensions will be a good thing for JRuby, even if they only serve as a stopgap measure to help people migrate small applications over to native Java equivalents. Why should the end goal be native Java equivalents, you ask?The Peril of C ExtensionsNow that we're done with the happy, glowing discussion of how great C extension support will be, I can make a confession: I hate C extensions. No feature of C Ruby has done more to hold it back than the desire for backward compatibility with C extensions. Because they have direct pointer access, there's no easy way to build a better garbage collector or easily support multiple runtimes in the same VM, even though various research efforts have tried. I've talked with Koichi Sasada, the creator of Ruby 1.9's "YARV" VM, and there's many things he would have liked to do with YARV that he couldn't because of C extension backward compatibility.For JRuby, supporting C extensions will limit many features that make JRuby compelling in the first place. For example, because C extensions often use a lot of global variables, you can't use them from multiple JRuby runtimes in the same process. Because they expect a Ruby-like threading model, we need to restrict concurrency when calling out from Java to C. And all the great memory tooling I've blogged about recently won't see C extensions or the libraries they call, so it introduces an unknown.All that said, I think it's a good milestone to show that we can support C extensions, and it may make for a "better JNI" for people who really just want to write C or who simply need to wrap a native library.How You Can HelpThere's a few things I think users like you can help with.First off, we'd love to know what extensions you are using today, so we can explore what it would take to run them under JRuby (and so we can start exploring pure-Java alternatives, too.) Post your list in the comments, and we'll see what we can come up with.Second, anyone that knows C and the Ruby C API (like folks who work on extensions) could help us fill out bits and pieces that are missing. Set up the JRuby cext branch (I'll show you how in a moment), and try to get your extensions to build and load. Tim has already done the heavy lifting of making "gem install xyz" attempt to build the extension and "require 'xyz'" try to load the resulting native library, so you can follow the usual processes (including extconf.rb/mkmf.rb for non-gem building and testing.) If it doesn't build ok, help us figure out what's missing or incorrect. If it builds but doesn't run, help us figure out what it's doing incorrectly.Building JRuby with C Extension SupportLike building JRuby proper, building the cext work is probably the easiest thing you'll do all day (assuming the C compiler/build/toolchain doesn't bite you.
Check out (or fork and check out) the JRuby repository from http://github.com/jruby/jruby:git clone git://github.com/jruby/jruby.git
Switch to the "cext" branch:git checkout -b cext origin/cext
Do a clean build of JRuby plus the cext subsystem:ant clean build-jruby-cext-native
At this point you should have a JRuby build (run with bin/jruby) that can gem install and load native extensions. [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
This is the third post in a series. The first two were on Browsing Memory the JRuby Way and Finding Leaks in Ruby Apps with Eclipse Memory AnalyzerHello again, friends! I'm back with more exciting memory analysis tips and tricks! Ready? Here we
... [More]
go!After my previous two posts, several folks asked if it's possible to do all this stuff from Ruby, rather than using Java or C-based apps shipped with the JVM. The answer is yes! Because of the maturity of the Java platform, there are standard Java APIs you can use to access all the same information the previous tools consumed. And since we're talking about JRuby, that means you have Ruby APIs you can use to access that information.That's what I'm going to show you today.Introducing JDIThe APIs we'll be using are part of the Java Debug Interface (JDI), a set of Java APIs for remotely inspecting a running application. It's part of the Java Platform Debugger Architecture, which also includes a C/++ API, a wire protocol, and a raw wire protocol API. Exploring those is left as an exercise for the reader...but they're also pretty cool.We'll use the Rails app from before, inspecting it immediately after boot. JDI provides a number of ways to connect up to a running VM, using VirtualMachineManager; you can either have the debugger make the connection or the target VM make the connection, and optionally have the target VM launch the debugger or the debugger launch the target VM. For our example, we'll have the debugger attach to a target VM listening for connections.Preparing the Target VMThe first step is to start up the application with the appropriate debugger endpoint installed. This new flag is a bit of a mouthful (and we should make a standard flag for JRuby users), but we're simply setting up a socket-based listener on port 12345, running as a server, and we don't want to suspend the JVM when the debugger connects.jruby -J-agentlib:jdwp=transport=dt_socket,server=y,address=12345,suspend=n -J-Djruby.reify.classes=true script/server -e productionThe -J-Djruby.reify.classes bit I talked about in my first post. It makes Ruby classes show up as Java classes for purposes of heap inspection.The rest is just running the server in production mode.As you can see, remote debugging is already baked into the JVM, which means we didn't have to write it or debug it. And that's pretty awesome.Let's connect to our Rails process and see what we can do.Connecting to the target VMIn order to connect to the target VM, you need to do the Java factory dance. We start with the com.sun.jdi.Bootstrap class, get a com.sun.jdi.VirtualMachineManager, and then connect to a target VM to get a com.sun.jdi.VirtualMachine object.vmm = Bootstrap.virtual_machine_managersock_conn = vmm.attaching_connectors[0] # not guaranteed to be Socketargs = sock_conn.default_argumentsargs['hostname].value = "localhost"args['port'].value = "12345"vm = sock_conn.attach(args)Notice that I didn't dig out the socket connector explicitly here, because on my system, the first connector always appears to be the socket connector. Here's the full list for me on OS X:➔ jruby -rjava -e "puts com.sun.jdi.Bootstrap.virtual_machine_manager.attaching_connectors> "[com.sun.jdi.SocketAttach (defaults: timeout=, hostname=charles-nutters-macbook-pro.local, port=),com.sun.jdi.ProcessAttach (defaults: pid=, timeout=)]The ProcessAttach connector there isn't as magical as it looks; all it does is query the target process to find out what transport it's using (dt_socket in our case) and then calls the right connector (e.g. SocketAttach in the case of dt_socket or SharedMemoryAttach if you use dt_shmem on Windows). In our case, we know it's listening on a socket, so we're using the SocketAttach connector directly.The rest is pretty simple: we get the default arguments from the connector, twiddle them to have the right hostname and port number, and attach to the VM. Now we have a VirtualMachine object we can query and twiddle; we're inside the matrix.With Great Power...So, what can we do with this VirtualMachine object? We can:walk all classes and objects on the heapinstall breakpoints and step-debug any running codeinspect and modify the current state of any running thread, even manipulating in-flight arguments and variablesreplace already-loaded classes with new definitions (such as to install custom instrumentation)Here's the output from JRuby's ri command when we ask about VirtualMachine:➔ ri --java com.sun.jdi.VirtualMachine-------------------------------------- Class: com.sun.jdi.VirtualMachine (no description...)------------------------------------------------------------------------Instance methods:----------------- allClasses, allThreads, canAddMethod, canBeModified, canForceEarlyReturn, canGetBytecodes, canGetClassFileVersion, canGetConstantPool, canGetCurrentContendedMonitor, canGetInstanceInfo, canGetMethodReturnValues, canGetMonitorFrameInfo, canGetMonitorInfo, canGetOwnedMonitorInfo, canGetSourceDebugExtension, canGetSyntheticAttribute, canPopFrames, canRedefineClasses, canRequestMonitorEvents, canRequestVMDeathEvent, canUnrestrictedlyRedefineClasses, canUseInstanceFilters, canUseSourceNameFilters, canWatchFieldAccess, canWatchFieldModification, classesByName, description, dispose, eventQueue, eventRequestManager, exit, getDefaultStratum, instanceCounts, mirrorOf, mirrorOfVoid, name, process, redefineClasses, resume, setDebugTraceMode, setDefaultStratum, suspend, toString, topLevelThreadGroups, version, virtualMachineWe can basically make the target VM dance any way we want, even going so far as to write our own debugger entirely in Ruby code. But that's a topic for another day. Right now, we're going to do some memory inspection.Creating a Histogram of the HeapThe simplest heap inspection we might do is to produce a histogram of all objects on the heap. And as you might expect, this is one of the easiest things to do, because it's the first thing everyone looks for when debugging a memory issue.classes = VM.all_classescounts = VM.instance_counts(classes)classes.zip(counts)VirtualMachine.all_classes gives you a list (a java.util.List, but we make those behave mostly like a Ruby Array) of every class the JVM has loaded, including Ruby classes, JRuby core and runtime classes, and other Java classes that JRuby and the JVM use. VirtualMachine.instance_counts takes that list of classes and returns another list of instance counts. Zip the two together, and we have an array of classes and instance counts. So easy!Let's take these two pieces and put them together in an easy-to-use classrequire 'java'module JRuby class Debugger VMM = com.sun.jdi.Bootstrap.virtual_machine_manager attr_accessor :vm def initialize(options = {}) connectors = VMM.attaching_connectors if options[:port] connector = connectors.find {|ac| ac.name =~ /Socket/} elsif options[:pid] connector = connectors.find {|ac| ac.name =~ /Process/} end args = connector.default_arguments for k, v in options args[k.to_s].value = v.to_s end @vm = connector.attach(args) end # Generate a histogram of all classes in the system def histogram classes = @vm.all_classes counts = @vm.instance_counts(classes) classes.zip(counts) end endendI've taken the liberty of expanding the connection process to handle pids and other arguments passed in. So to get a histogram from a VM listening on localhost port 12345, we can simply do:JRuby::Debugger.new(:hostname => 'localhost', :port => 12345).histogramNow of course this list is going to have a lot of JRuby and Java objects that we might not be interested in, so we'll want to filter it to just the Ruby classes. On JRuby master, all the generated Ruby classes start with a package name "ruby". Unfortunately, jitted Ruby methods start with a package of "ruby.jit" right now, so we'll want to filter those out too (unless you're interested in them, of course...JRuby is an open book!)require 'jruby_debugger'# connect to the VMdebugr = JRuby::Debugger.new(:hostname => 'localhost', :port => 12345)histo = debugr.histogram# sort by counthisto.sort! {|a,b| b[1] <=> a[1]}# filter to only user-created Ruby classes with >0 instanceshisto.each do |cls,num| next if num == 0 || cls.name[0..4] != 'ruby.' || cls.name[5..7] == 'jit' puts "#{num} instances of #{cls.name[5..-1].gsub('.', '::')}"endIf we run this short script against our Rails application, we see similar results to the previous posts (but it's cooler, because we're doing it all from Ruby!)➔ jruby ruby_histogram.rb | head -1011685 instances of TZInfo::TimezoneTransitionInfo1071 instances of Gem::Version1012 instances of Gem::Requirement592 instances of TZInfo::TimezoneOffsetInfo432 instances of Gem::Dependency289 instances of Gem::Specification142 instances of ActiveSupport::TimeZone118 instances of TZInfo::DataTimezoneInfo118 instances of TZInfo::DataTimezone45 instances of Gem::PlatformJust so we're all on the same page, it's important to know what we're actually dealing with here. VirtualMachine.all_classes returns a list of com.sun.jdi.ReferenceType objects. Let's ri that.➔ ri --java com.sun.jdi.ReferenceType--------------------------------------- Class: com.sun.jdi.ReferenceType (no description...)------------------------------------------------------------------------Instance methods:----------------- allFields, allLineLocations, allMethods, availableStrata, classLoader, classObject, compareTo, constantPool, constantPoolCount, defaultStratum, equals, failedToInitialize, fieldByName, fields, genericSignature, getValue, getValues, hashCode, instances, isAbstract, isFinal, isInitialized, isPackagePrivate, isPrepared, isPrivate, isProtected, isPublic, isStatic, isVerified, locationsOfLine, majorVersion, methods, methodsByName, minorVersion, modifiers, name, nestedTypes, signature, sourceDebugExtension, sourceName, sourceNames, sourcePaths, toString, virtualMachine, visibleFields, visibleMethodsYou can see there's quite a bit more you can do with a ReferenceType. Let's try something.Digging Deeper Into TimezoneTransitionInfoLet's actually take some time to explore our old friend TimezoneTransitionInfo (hereafter referred to as TTI). Instead of walking all classes in the system, we'll want to just grab TTI directly. For that we use VirtualMachine.classes_by_name, which returns a list of classes on the target VM of that name. There should be only one, since we only have a single JRuby instance in our server, so we'll grab that class and request exactly one instance of it...any old instance.tti_class = debugr.vm.classes_by_name('ruby.TZInfo.TimezoneTransitionInfo')[0]tti_obj = tti_class.instances(1)[0]puts tti_objRunning this we can see we've got the reference we're looking for.➔ jruby tti_digger.rbinstance of ruby.TZInfo.TimezoneTransitionInfo(id=2)ReferenceType.instances returns a list (no larger than the specified size, or all instances if you specify 0) of com.sun.jdi.ObjectReference objects.➔ ri --java com.sun.jdi.ObjectReference------------------------------------- Class: com.sun.jdi.ObjectReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, owningThread, referenceType, referringObjects, setValue, toString, type, uniqueID, virtualMachine, waitingThreadsAmong the weirder things like disabling garbage collection for this object or listing all threads waiting on this object's monitor (a la 'synchronize' in Java), we can access the object's fields through getValue and setValue.Let's examine the instance variables TTI contains. You may recall from previous posts that all Ruby objects in JRuby store their instance variables in an array, to avoid the large memory and cpu cost of storing them in a map. We can grab a reference to that array and display its contents.var_table_field = tti_class.field_by_name('varTable')tti_vars = tti_obj.get_value(var_table_field)puts "varTable: #{tti_vars}"puts tti_vars.values.map(&:to_s)And the new output:➔ jruby tti_digger.rbvarTable: instance of java.lang.Object[7] (id=13)instance of ruby.TZInfo.TimezoneOffsetInfo(id=15)instance of ruby.TZInfo.TimezoneOffsetInfo(id=16)instance of org.jruby.RubyFixnum(id=17)instance of org.jruby.RubyFixnum(id=18)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)Since the varTable field is a simple Object[] in Java, the reference we get to it is of type com.sun.jdi.ArrayReference.➔ ri --java com.sun.jdi.ArrayReference-------------------------------------- Class: com.sun.jdi.ArrayReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, length, owningThread, referenceType, referringObjects, setValue, setValues, toString, type, uniqueID, virtualMachine, waitingThreadsOf course each of these references can be further explored, but already we can see that this TTI instance has seven instance variables: two TimezoneOffsetInfo objects, two Fixnums, and three nils. But we don't have instance variable names!Instance variable names are only stored on the object's class. There, a table of names to offsets is kept up-to-date as new instance variable names are discovered. We can access this from the TTI class reference and combine it with the variable table to get the output we want to see.# get the metaclass object and class referencemetaclass_field = tti_class.field_by_name('metaClass')tti_class_obj = tti_obj.get_value(metaclass_field)tti_class_class = tti_class_obj.reference_type# get the variable names from the metaclass objectvar_names_field = tti_class_class.field_by_name('variableNames')var_names = tti_class_obj.get_value(var_names_field)# splice the names and values togethertable = var_names.values.zip(tti_vars.values)puts tableThis looks a bit complicated, but there's actually a lot of boilerplate here we could put into a utility class. For example, the metaClass and variableNames fields are standard on all (J)Ruby objects and classes, respectively. But considering that we're actually walking a remote VM's *live* heap...this is pretty simple code.Here's what our script outputs now:➔ jruby tti_digger.rb"@offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=25)"@previous_offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=26)"@numerator_or_time"instance of org.jruby.RubyFixnum(id=27)"@denominator"instance of org.jruby.RubyFixnum(id=28)"@at"instance of org.jruby.RubyNil(id=29)"@local_end"instance of org.jruby.RubyNil(id=29)"@local_start"instance of org.jruby.RubyNil(id=29)We could go even deeper, but I think you get the idea.Your TurnHere's a gist of the three scripts we've created, so you can refer to and build off of them. And of course the javadocs and ri docs will help you as well, plus everything we've done here you can do in a jirb session.There's a lot to the JDI API, but once you've got the VirtualMachine object in hand it's pretty easy to follow. As you'd expect from any debugger API, you need to know a bit about how things work on the inside, but through the magic of JRuby it's actually possible to write most of those fancy memory and debugging tools entirely in Ruby. Perhaps this article has peaked your interest in exploring JRuby internals using JDI and you might start to write debugging tools. Perhaps we can ship a few utilities to make some of the boilerplate go away. In any case, I hope this series of articles shows that JRuby users have an amazing library of tools available to them, and you don't even have to leave your comfort zone if you don't want to.Note: The variableNames field is a recent addition to JRuby master, so if you'd like to play with that you'll probably want to build JRuby yourself or wait for a nightly build that picks it up. But you can certainly do a lot of exploring even without that patch. [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
This is the third post in a series. The first two were on Browsing Memory the JRuby Way and Finding Leaks in Ruby Apps with Eclipse Memory AnalyzerHello again, friends! I'm back with more exciting memory analysis tips and tricks! Ready? Here we
... [More]
go!After my previous two posts, several folks asked if it's possible to do all this stuff from Ruby, rather than using Java or C-based apps shipped with the JVM. The answer is yes! Because of the maturity of the Java platform, there are standard Java APIs you can use to access all the same information the previous tools consumed. And since we're talking about JRuby, that means you have Ruby APIs you can use to access that information.That's what I'm going to show you today.Introducing JDIThe APIs we'll be using are part of the Java Debug Interface (JDI), a set of Java APIs for remotely inspecting a running application. It's part of the Java Platform Debugger Architecture, which also includes a C/++ API, a wire protocol, and a raw wire protocol API. Exploring those is left as an exercise for the reader...but they're also pretty cool.We'll use the Rails app from before, inspecting it immediately after boot. JDI provides a number of ways to connect up to a running VM, using VirtualMachineManager; you can either have the debugger make the connection or the target VM make the connection, and optionally have the target VM launch the debugger or the debugger launch the target VM. For our example, we'll have the debugger attach to a target VM listening for connections.Preparing the Target VMThe first step is to start up the application with the appropriate debugger endpoint installed. This new flag is a bit of a mouthful (and we should make a standard flag for JRuby users), but we're simply setting up a socket-based listener on port 12345, running as a server, and we don't want to suspend the JVM when the debugger connects.jruby -J-agentlib:jdwp=transport=dt_socket,server=y,address=12345,suspend=n -J-Djruby.reify.classes=true script/server -e productionThe -J-Djruby.reify.classes bit I talked about in my first post. It makes Ruby classes show up as Java classes for purposes of heap inspection.The rest is just running the server in production mode.As you can see, remote debugging is already baked into the JVM, which means we didn't have to write it or debug it. And that's pretty awesome.Let's connect to our Rails process and see what we can do.Connecting to the target VMIn order to connect to the target VM, you need to do the Java factory dance. We start with the com.sun.jdi.Bootstrap class, get a com.sun.jdi.VirtualMachineManager, and then connect to a target VM to get a com.sun.jdi.VirtualMachine object.vmm = Bootstrap.virtual_machine_managersock_conn = vmm.attaching_connectors[0] # not guaranteed to be Socketargs = sock_conn.default_argumentsargs['hostname].value = "localhost"args['port'].value = "12345"vm = sock_conn.attach(args)Notice that I didn't dig out the socket connector explicitly here, because on my system, the first connector always appears to be the socket connector. Here's the full list for me on OS X:➔ jruby -rjava -e "puts com.sun.jdi.Bootstrap.virtual_machine_manager.attaching_connectors> "[com.sun.jdi.SocketAttach (defaults: timeout=, hostname=charles-nutters-macbook-pro.local, port=),com.sun.jdi.ProcessAttach (defaults: pid=, timeout=)]The ProcessAttach connector there isn't as magical as it looks; all it does is query the target process to find out what transport it's using (dt_socket in our case) and then calls the right connector (e.g. SocketAttach in the case of dt_socket or SharedMemoryAttach if you use dt_shmem on Windows). In our case, we know it's listening on a socket, so we're using the SocketAttach connector directly.The rest is pretty simple: we get the default arguments from the connector, twiddle them to have the right hostname and port number, and attach to the VM. Now we have a VirtualMachine object we can query and twiddle; we're inside the matrix.With Great Power...So, what can we do with this VirtualMachine object? We can:walk all classes and objects on the heapinstall breakpoints and step-debug any running codeinspect and modify the current state of any running thread, even manipulating in-flight arguments and variablesreplace already-loaded classes with new definitions (such as to install custom instrumentation)Here's the output from JRuby's ri command when we ask about VirtualMachine:➔ ri --java com.sun.jdi.VirtualMachine-------------------------------------- Class: com.sun.jdi.VirtualMachine (no description...)------------------------------------------------------------------------Instance methods:----------------- allClasses, allThreads, canAddMethod, canBeModified, canForceEarlyReturn, canGetBytecodes, canGetClassFileVersion, canGetConstantPool, canGetCurrentContendedMonitor, canGetInstanceInfo, canGetMethodReturnValues, canGetMonitorFrameInfo, canGetMonitorInfo, canGetOwnedMonitorInfo, canGetSourceDebugExtension, canGetSyntheticAttribute, canPopFrames, canRedefineClasses, canRequestMonitorEvents, canRequestVMDeathEvent, canUnrestrictedlyRedefineClasses, canUseInstanceFilters, canUseSourceNameFilters, canWatchFieldAccess, canWatchFieldModification, classesByName, description, dispose, eventQueue, eventRequestManager, exit, getDefaultStratum, instanceCounts, mirrorOf, mirrorOfVoid, name, process, redefineClasses, resume, setDebugTraceMode, setDefaultStratum, suspend, toString, topLevelThreadGroups, version, virtualMachineWe can basically make the target VM dance any way we want, even going so far as to write our own debugger entirely in Ruby code. But that's a topic for another day. Right now, we're going to do some memory inspection.Creating a Histogram of the HeapThe simplest heap inspection we might do is to produce a histogram of all objects on the heap. And as you might expect, this is one of the easiest things to do, because it's the first thing everyone looks for when debugging a memory issue.classes = VM.all_classescounts = VM.instance_counts(classes)classes.zip(counts)VirtualMachine.all_classes gives you a list (a java.util.List, but we make those behave mostly like a Ruby Array) of every class the JVM has loaded, including Ruby classes, JRuby core and runtime classes, and other Java classes that JRuby and the JVM use. VirtualMachine.instance_counts takes that list of classes and returns another list of instance counts. Zip the two together, and we have an array of classes and instance counts. So easy!Let's take these two pieces and put them together in an easy-to-use classrequire 'java'module JRuby class Debugger VMM = com.sun.jdi.Bootstrap.virtual_machine_manager attr_accessor :vm def initialize(options = {}) connectors = VMM.attaching_connectors if options[:port] connector = connectors.find {|ac| ac.name =~ /Socket/} elsif options[:pid] connector = connectors.find {|ac| ac.name =~ /Process/} end args = connector.default_arguments for k, v in options args[k.to_s].value = v.to_s end @vm = connector.attach(args) end # Generate a histogram of all classes in the system def histogram classes = @vm.all_classes counts = @vm.instance_counts(classes) classes.zip(counts) end endendI've taken the liberty of expanding the connection process to handle pids and other arguments passed in. So to get a histogram from a VM listening on localhost port 12345, we can simply do:JRuby::Debugger.new(:hostname => 'localhost', :port => 12345).histogramNow of course this list is going to have a lot of JRuby and Java objects that we might not be interested in, so we'll want to filter it to just the Ruby classes. On JRuby master, all the generated Ruby classes start with a package name "ruby". Unfortunately, jitted Ruby methods start with a package of "ruby.jit" right now, so we'll want to filter those out too (unless you're interested in them, of course...JRuby is an open book!)require 'jruby_debugger'# connect to the VMdebugr = JRuby::Debugger.new(:hostname => 'localhost', :port => 12345)histo = debugr.histogram# sort by counthisto.sort! {|a,b| b[1] <=> a[1]}# filter to only user-created Ruby classes with >0 instanceshisto.each do |cls,num| next if num == 0 || cls.name[0..4] != 'ruby.' || cls.name[5..7] == 'jit' puts "#{num} instances of #{cls.name[5..-1].gsub('.', '::')}"endIf we run this short script against our Rails application, we see similar results to the previous posts (but it's cooler, because we're doing it all from Ruby!)➔ jruby ruby_histogram.rb | head -1011685 instances of TZInfo::TimezoneTransitionInfo1071 instances of Gem::Version1012 instances of Gem::Requirement592 instances of TZInfo::TimezoneOffsetInfo432 instances of Gem::Dependency289 instances of Gem::Specification142 instances of ActiveSupport::TimeZone118 instances of TZInfo::DataTimezoneInfo118 instances of TZInfo::DataTimezone45 instances of Gem::PlatformJust so we're all on the same page, it's important to know what we're actually dealing with here. VirtualMachine.all_classes returns a list of com.sun.jdi.ReferenceType objects. Let's ri that.➔ ri --java com.sun.jdi.ReferenceType--------------------------------------- Class: com.sun.jdi.ReferenceType (no description...)------------------------------------------------------------------------Instance methods:----------------- allFields, allLineLocations, allMethods, availableStrata, classLoader, classObject, compareTo, constantPool, constantPoolCount, defaultStratum, equals, failedToInitialize, fieldByName, fields, genericSignature, getValue, getValues, hashCode, instances, isAbstract, isFinal, isInitialized, isPackagePrivate, isPrepared, isPrivate, isProtected, isPublic, isStatic, isVerified, locationsOfLine, majorVersion, methods, methodsByName, minorVersion, modifiers, name, nestedTypes, signature, sourceDebugExtension, sourceName, sourceNames, sourcePaths, toString, virtualMachine, visibleFields, visibleMethodsYou can see there's quite a bit more you can do with a ReferenceType. Let's try something.Digging Deeper Into TimezoneTransitionInfoLet's actually take some time to explore our old friend TimezoneTransitionInfo (hereafter referred to as TTI). Instead of walking all classes in the system, we'll want to just grab TTI directly. For that we use VirtualMachine.classes_by_name, which returns a list of classes on the target VM of that name. There should be only one, since we only have a single JRuby instance in our server, so we'll grab that class and request exactly one instance of it...any old instance.tti_class = debugr.vm.classes_by_name('ruby.TZInfo.TimezoneTransitionInfo')[0]tti_obj = tti_class.instances(1)[0]puts tti_objRunning this we can see we've got the reference we're looking for.➔ jruby tti_digger.rbinstance of ruby.TZInfo.TimezoneTransitionInfo(id=2)ReferenceType.instances returns a list (no larger than the specified size, or all instances if you specify 0) of com.sun.jdi.ObjectReference objects.➔ ri --java com.sun.jdi.ObjectReference------------------------------------- Class: com.sun.jdi.ObjectReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, owningThread, referenceType, referringObjects, setValue, toString, type, uniqueID, virtualMachine, waitingThreadsAmong the weirder things like disabling garbage collection for this object or listing all threads waiting on this object's monitor (a la 'synchronize' in Java), we can access the object's fields through getValue and setValue.Let's examine the instance variables TTI contains. You may recall from previous posts that all Ruby objects in JRuby store their instance variables in an array, to avoid the large memory and cpu cost of storing them in a map. We can grab a reference to that array and display its contents.var_table_field = tti_class.field_by_name('varTable')tti_vars = tti_obj.get_value(var_table_field)puts "varTable: #{tti_vars}"puts tti_vars.values.map(&:to_s)And the new output:➔ jruby tti_digger.rbvarTable: instance of java.lang.Object[7] (id=13)instance of ruby.TZInfo.TimezoneOffsetInfo(id=15)instance of ruby.TZInfo.TimezoneOffsetInfo(id=16)instance of org.jruby.RubyFixnum(id=17)instance of org.jruby.RubyFixnum(id=18)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)Since the varTable field is a simple Object[] in Java, the reference we get to it is of type com.sun.jdi.ArrayReference.➔ ri --java com.sun.jdi.ArrayReference-------------------------------------- Class: com.sun.jdi.ArrayReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, length, owningThread, referenceType, referringObjects, setValue, setValues, toString, type, uniqueID, virtualMachine, waitingThreadsOf course each of these references can be further explored, but already we can see that this TTI instance has seven instance variables: two TimezoneOffsetInfo objects, two Fixnums, and three nils. But we don't have instance variable names!Instance variable names are only stored on the object's class. There, a table of names to offsets is kept up-to-date as new instance variable names are discovered. We can access this from the TTI class reference and combine it with the variable table to get the output we want to see.# get the metaclass object and class referencemetaclass_field = tti_class.field_by_name('metaClass')tti_class_obj = tti_obj.get_value(metaclass_field)tti_class_class = tti_class_obj.reference_type# get the variable names from the metaclass objectvar_names_field = tti_class_class.field_by_name('variableNames')var_names = tti_class_obj.get_value(var_names_field)# splice the names and values togethertable = var_names.values.zip(tti_vars.values)puts tableThis looks a bit complicated, but there's actually a lot of boilerplate here we could put into a utility class. For example, the metaClass and variableNames fields are standard on all (J)Ruby objects and classes, respectively. But considering that we're actually walking a remote VM's *live* heap...this is pretty simple code.Here's what our script outputs now:➔ jruby tti_digger.rb"@offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=25)"@previous_offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=26)"@numerator_or_time"instance of org.jruby.RubyFixnum(id=27)"@denominator"instance of org.jruby.RubyFixnum(id=28)"@at"instance of org.jruby.RubyNil(id=29)"@local_end"instance of org.jruby.RubyNil(id=29)"@local_start"instance of org.jruby.RubyNil(id=29)We could go even deeper, but I think you get the idea.Your TurnHere's a gist of the three scripts we've created, so you can refer to and build off of them. And of course the javadocs and ri docs will help you as well, plus everything we've done here you can do in a jirb session.There's a lot to the JDI API, but once you've got the VirtualMachine object in hand it's pretty easy to follow. As you'd expect from any debugger API, you need to know a bit about how things work on the inside, but through the magic of JRuby it's actually possible to write most of those fancy memory and debugging tools entirely in Ruby. Perhaps this article has peaked your interest in exploring JRuby internals using JDI and you might start to write debugging tools. Perhaps we can ship a few utilities to make some of the boilerplate go away. In any case, I hope this series of articles shows that JRuby users have an amazing library of tools available to them, and you don't even have to leave your comfort zone if you don't want to.Note: The variableNames field is a recent addition to JRuby master, so if you'd like to play with that you'll probably want to build JRuby yourself or wait for a nightly build that picks it up. But you can certainly do a lot of exploring even without that patch. [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
This is the third post in a series. The first two were on Browsing Memory the JRuby Way and Finding Leaks in Ruby Apps with Eclipse Memory AnalyzerHello again, friends! I'm back with more exciting memory analysis tips and tricks! Ready? Here we
... [More]
go!After my previous two posts, several folks asked if it's possible to do all this stuff from Ruby, rather than using Java or C-based apps shipped with the JVM. The answer is yes! Because of the maturity of the Java platform, there are standard Java APIs you can use to access all the same information the previous tools consumed. And since we're talking about JRuby, that means you have Ruby APIs you can use to access that information.That's what I'm going to show you today.Introducing JDIThe APIs we'll be using are part of the Java Debug Interface (JDI), a set of Java APIs for remotely inspecting a running application. It's part of the Java Platform Debugger Architecture, which also includes a C/++ API, a wire protocol, and a raw wire protocol API. Exploring those is left as an exercise for the reader...but they're also pretty cool.We'll use the Rails app from before, inspecting it immediately after boot. JDI provides a number of ways to connect up to a running VM, using VirtualMachineManager; you can either have the debugger make the connection or the target VM make the connection, and optionally have the target VM launch the debugger or the debugger launch the target VM. For our example, we'll have the debugger attach to a target VM listening for connections.Preparing the Target VMThe first step is to start up the application with the appropriate debugger endpoint installed. This new flag is a bit of a mouthful (and we should make a standard flag for JRuby users), but we're simply setting up a socket-based listener on port 12345, running as a server, and we don't want to suspend the JVM when the debugger connects.jruby -J-agentlib:jdwp=transport=dt_socket,server=y,address=12345,suspend=n -J-Djruby.reify.classes=true script/server -e productionThe -J-Djruby.reify.classes bit I talked about in my first post. It makes Ruby classes show up as Java classes for purposes of heap inspection.The rest is just running the server in production mode.As you can see, remote debugging is already baked into the JVM, which means we didn't have to write it or debug it. And that's pretty awesome.Let's connect to our Rails process and see what we can do.Connecting to the target VMIn order to connect to the target VM, you need to do the Java factory dance. We start with the com.sun.jdi.Bootstrap class, get a com.sun.jdi.VirtualMachineManager, and then connect to a target VM to get a com.sun.jdi.VirtualMachine object.vmm = Bootstrap.virtual_machine_managersock_conn = vmm.attaching_connectors[0] # not guaranteed to be Socketargs = sock_conn.default_argumentsargs['hostname].value = "localhost"args['port'].value = "12345"vm = sock_conn.attach(args)Notice that I didn't dig out the socket connector explicitly here, because on my system, the first connector always appears to be the socket connector. Here's the full list for me on OS X:➔ jruby -rjava -e "puts com.sun.jdi.Bootstrap.virtual_machine_manager.attaching_connectors> "[com.sun.jdi.SocketAttach (defaults: timeout=, hostname=charles-nutters-macbook-pro.local, port=),com.sun.jdi.ProcessAttach (defaults: pid=, timeout=)]The ProcessAttach connector there isn't as magical as it looks; all it does is query the target process to find out what transport it's using (dt_socket in our case) and then calls the right connector (e.g. SocketAttach in the case of dt_socket or SharedMemoryAttach if you use dt_shmem on Windows). In our case, we know it's listening on a socket, so we're using the SocketAttach connector directly.The rest is pretty simple: we get the default arguments from the connector, twiddle them to have the right hostname and port number, and attach to the VM. Now we have a VirtualMachine object we can query and twiddle; we're inside the matrix.With Great Power...So, what can we do with this VirtualMachine object? We can:
walk all classes and objects on the heap
install breakpoints and step-debug any running code
inspect and modify the current state of any running thread, even manipulating in-flight arguments and variables
replace already-loaded classes with new definitions (such as to install custom instrumentation)
Here's the output from JRuby's ri command when we ask about VirtualMachine:➔ ri --java com.sun.jdi.VirtualMachine-------------------------------------- Class: com.sun.jdi.VirtualMachine (no description...)------------------------------------------------------------------------Instance methods:----------------- allClasses, allThreads, canAddMethod, canBeModified, canForceEarlyReturn, canGetBytecodes, canGetClassFileVersion, canGetConstantPool, canGetCurrentContendedMonitor, canGetInstanceInfo, canGetMethodReturnValues, canGetMonitorFrameInfo, canGetMonitorInfo, canGetOwnedMonitorInfo, canGetSourceDebugExtension, canGetSyntheticAttribute, canPopFrames, canRedefineClasses, canRequestMonitorEvents, canRequestVMDeathEvent, canUnrestrictedlyRedefineClasses, canUseInstanceFilters, canUseSourceNameFilters, canWatchFieldAccess, canWatchFieldModification, classesByName, description, dispose, eventQueue, eventRequestManager, exit, getDefaultStratum, instanceCounts, mirrorOf, mirrorOfVoid, name, process, redefineClasses, resume, setDebugTraceMode, setDefaultStratum, suspend, toString, topLevelThreadGroups, version, virtualMachineWe can basically make the target VM dance any way we want, even going so far as to write our own debugger entirely in Ruby code. But that's a topic for another day. Right now, we're going to do some memory inspection.Creating a Histogram of the HeapThe simplest heap inspection we might do is to produce a histogram of all objects on the heap. And as you might expect, this is one of the easiest things to do, because it's the first thing everyone looks for when debugging a memory issue.classes = VM.all_classescounts = VM.instance_counts(classes)classes.zip(counts)VirtualMachine.all_classes gives you a list (a java.util.List, but we make those behave mostly like a Ruby Array) of every class the JVM has loaded, including Ruby classes, JRuby core and runtime classes, and other Java classes that JRuby and the JVM use. VirtualMachine.instance_counts takes that list of classes and returns another list of instance counts. Zip the two together, and we have an array of classes and instance counts. So easy!Let's take these two pieces and put them together in an easy-to-use classrequire 'java'module JRuby class Debugger VMM = com.sun.jdi.Bootstrap.virtual_machine_manager attr_accessor :vm def initialize(options = {}) connectors = VMM.attaching_connectors if options[:port] connector = connectors.find {|ac| ac.name =~ /Socket/} elsif options[:pid] connector = connectors.find {|ac| ac.name =~ /Process/} end args = connector.default_arguments for k, v in options args[k.to_s].value = v.to_s end @vm = connector.attach(args) end # Generate a histogram of all classes in the system def histogram classes = @vm.all_classes counts = @vm.instance_counts(classes) classes.zip(counts) end endendI've taken the liberty of expanding the connection process to handle pids and other arguments passed in. So to get a histogram from a VM listening on localhost port 12345, we can simply do:JRuby::Debugger.new(:hostname => 'localhost', :port => 12345).histogramNow of course this list is going to have a lot of JRuby and Java objects that we might not be interested in, so we'll want to filter it to just the Ruby classes. On JRuby master, all the generated Ruby classes start with a package name "ruby". Unfortunately, jitted Ruby methods start with a package of "ruby.jit" right now, so we'll want to filter those out too (unless you're interested in them, of course...JRuby is an open book!)require 'jruby_debugger'# connect to the VMdebugr = JRuby::Debugger.new(:hostname => 'localhost', :port => 12345)histo = debugr.histogram# sort by counthisto.sort! {|a,b| b[1] <=> a[1]}# filter to only user-created Ruby classes with >0 instanceshisto.each do |cls,num| next if num == 0 || cls.name[0..4] != 'ruby.' || cls.name[5..7] == 'jit' puts "#{num} instances of #{cls.name[5..-1].gsub('.', '::')}"endIf we run this short script against our Rails application, we see similar results to the previous posts (but it's cooler, because we're doing it all from Ruby!)➔ jruby ruby_histogram.rb | head -1011685 instances of TZInfo::TimezoneTransitionInfo1071 instances of Gem::Version1012 instances of Gem::Requirement592 instances of TZInfo::TimezoneOffsetInfo432 instances of Gem::Dependency289 instances of Gem::Specification142 instances of ActiveSupport::TimeZone118 instances of TZInfo::DataTimezoneInfo118 instances of TZInfo::DataTimezone45 instances of Gem::PlatformJust so we're all on the same page, it's important to know what we're actually dealing with here. VirtualMachine.all_classes returns a list of com.sun.jdi.ReferenceType objects. Let's ri that.➔ ri --java com.sun.jdi.ReferenceType--------------------------------------- Class: com.sun.jdi.ReferenceType (no description...)------------------------------------------------------------------------Instance methods:----------------- allFields, allLineLocations, allMethods, availableStrata, classLoader, classObject, compareTo, constantPool, constantPoolCount, defaultStratum, equals, failedToInitialize, fieldByName, fields, genericSignature, getValue, getValues, hashCode, instances, isAbstract, isFinal, isInitialized, isPackagePrivate, isPrepared, isPrivate, isProtected, isPublic, isStatic, isVerified, locationsOfLine, majorVersion, methods, methodsByName, minorVersion, modifiers, name, nestedTypes, signature, sourceDebugExtension, sourceName, sourceNames, sourcePaths, toString, virtualMachine, visibleFields, visibleMethodsYou can see there's quite a bit more you can do with a ReferenceType. Let's try something.Digging Deeper Into TimezoneTransitionInfoLet's actually take some time to explore our old friend TimezoneTransitionInfo (hereafter referred to as TTI). Instead of walking all classes in the system, we'll want to just grab TTI directly. For that we use VirtualMachine.classes_by_name, which returns a list of classes on the target VM of that name. There should be only one, since we only have a single JRuby instance in our server, so we'll grab that class and request exactly one instance of it...any old instance.tti_class = debugr.vm.classes_by_name('ruby.TZInfo.TimezoneTransitionInfo')[0]tti_obj = tti_class.instances(1)[0]puts tti_objRunning this we can see we've got the reference we're looking for.➔ jruby tti_digger.rbinstance of ruby.TZInfo.TimezoneTransitionInfo(id=2)ReferenceType.instances returns a list (no larger than the specified size, or all instances if you specify 0) of com.sun.jdi.ObjectReference objects.➔ ri --java com.sun.jdi.ObjectReference------------------------------------- Class: com.sun.jdi.ObjectReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, owningThread, referenceType, referringObjects, setValue, toString, type, uniqueID, virtualMachine, waitingThreadsAmong the weirder things like disabling garbage collection for this object or listing all threads waiting on this object's monitor (a la 'synchronize' in Java), we can access the object's fields through getValue and setValue.Let's examine the instance variables TTI contains. You may recall from previous posts that all Ruby objects in JRuby store their instance variables in an array, to avoid the large memory and cpu cost of storing them in a map. We can grab a reference to that array and display its contents.var_table_field = tti_class.field_by_name('varTable')tti_vars = tti_obj.get_value(var_table_field)puts "varTable: #{tti_vars}"puts tti_vars.values.map(&:to_s)And the new output:➔ jruby tti_digger.rbvarTable: instance of java.lang.Object[7] (id=13)instance of ruby.TZInfo.TimezoneOffsetInfo(id=15)instance of ruby.TZInfo.TimezoneOffsetInfo(id=16)instance of org.jruby.RubyFixnum(id=17)instance of org.jruby.RubyFixnum(id=18)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)Since the varTable field is a simple Object[] in Java, the reference we get to it is of type com.sun.jdi.ArrayReference.➔ ri --java com.sun.jdi.ArrayReference-------------------------------------- Class: com.sun.jdi.ArrayReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, length, owningThread, referenceType, referringObjects, setValue, setValues, toString, type, uniqueID, virtualMachine, waitingThreadsOf course each of these references can be further explored, but already we can see that this TTI instance has seven instance variables: two TimezoneOffsetInfo objects, two Fixnums, and three nils. But we don't have instance variable names!Instance variable names are only stored on the object's class. There, a table of names to offsets is kept up-to-date as new instance variable names are discovered. We can access this from the TTI class reference and combine it with the variable table to get the output we want to see.# get the metaclass object and class referencemetaclass_field = tti_class.field_by_name('metaClass')tti_class_obj = tti_obj.get_value(metaclass_field)tti_class_class = tti_class_obj.reference_type# get the variable names from the metaclass objectvar_names_field = tti_class_class.field_by_name('variableNames')var_names = tti_class_obj.get_value(var_names_field)# splice the names and values togethertable = var_names.values.zip(tti_vars.values)puts tableThis looks a bit complicated, but there's actually a lot of boilerplate here we could put into a utility class. For example, the metaClass and variableNames fields are standard on all (J)Ruby objects and classes, respectively. But considering that we're actually walking a remote VM's *live* heap...this is pretty simple code.Here's what our script outputs now:➔ jruby tti_digger.rb"@offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=25)"@previous_offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=26)"@numerator_or_time"instance of org.jruby.RubyFixnum(id=27)"@denominator"instance of org.jruby.RubyFixnum(id=28)"@at"instance of org.jruby.RubyNil(id=29)"@local_end"instance of org.jruby.RubyNil(id=29)"@local_start"instance of org.jruby.RubyNil(id=29)We could go even deeper, but I think you get the idea.Your TurnHere's a gist of the three scripts we've created, so you can refer to and build off of them. And of course the javadocs and ri docs will help you as well, plus everything we've done here you can do in a jirb session.There's a lot to the JDI API, but once you've got the VirtualMachine object in hand it's pretty easy to follow. As you'd expect from any debugger API, you need to know a bit about how things work on the inside, but through the magic of JRuby it's actually possible to write most of those fancy memory and debugging tools entirely in Ruby. Perhaps this article has peaked your interest in exploring JRuby internals using JDI and you might start to write debugging tools. Perhaps we can ship a few utilities to make some of the boilerplate go away. In any case, I hope this series of articles shows that JRuby users have an amazing library of tools available to them, and you don't even have to leave your comfort zone if you don't want to.Note: The variableNames field is a recent addition to JRuby master, so if you'd like to play with that you'll probably want to build JRuby yourself or wait for a nightly build that picks it up. But you can certainly do a lot of exploring even without that patch. [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
This is the third post in a series. The first two were on Browsing Memory the JRuby Way and Finding Leaks in Ruby Apps with Eclipse Memory AnalyzerHello again, friends! I'm back with more exciting memory analysis tips and tricks! Ready? Here we
... [More]
go!After my previous two posts, several folks asked if it's possible to do all this stuff from Ruby, rather than using Java or C-based apps shipped with the JVM. The answer is yes! Because of the maturity of the Java platform, there are standard Java APIs you can use to access all the same information the previous tools consumed. And since we're talking about JRuby, that means you have Ruby APIs you can use to access that information.That's what I'm going to show you today.Introducing JDIThe APIs we'll be using are part of the Java Debug Interface (JDI), a set of Java APIs for remotely inspecting a running application. It's part of the Java Platform Debugger Architecture, which also includes a C/++ API, a wire protocol, and a raw wire protocol API. Exploring those is left as an exercise for the reader...but they're also pretty cool.We'll use the Rails app from before, inspecting it immediately after boot. JDI provides a number of ways to connect up to a running VM, using VirtualMachineManager; you can either have the debugger make the connection or the target VM make the connection, and optionally have the target VM launch the debugger or the debugger launch the target VM. For our example, we'll have the debugger attach to a target VM listening for connections.Preparing the Target VMThe first step is to start up the application with the appropriate debugger endpoint installed. This new flag is a bit of a mouthful (and we should make a standard flag for JRuby users), but we're simply setting up a socket-based listener on port 12345, running as a server, and we don't want to suspend the JVM when the debugger connects.jruby -J-agentlib:jdwp=transport=dt_socket,server=y,address=12345,suspend=n -J-Djruby.reify.classes=true script/server -e productionThe -J-Djruby.reify.classes bit I talked about in my first post. It makes Ruby classes show up as Java classes for purposes of heap inspection.The rest is just running the server in production mode.As you can see, remote debugging is already baked into the JVM, which means we didn't have to write it or debug it. And that's pretty awesome.Let's connect to our Rails process and see what we can do.Connecting to the target VMIn order to connect to the target VM, you need to do the Java factory dance. We start with the com.sun.jdi.Bootstrap class, get a com.sun.jdi.VirtualMachineManager, and then connect to a target VM to get a com.sun.jdi.VirtualMachine object.vmm = Bootstrap.virtual_machine_managersock_conn = vmm.attaching_connectors[0] # not guaranteed to be Socketargs = sock_conn.default_argumentsargs['hostname].value = "localhost"args['port'].value = "12345"vm = sock_conn.attach(args)Notice that I didn't dig out the socket connector explicitly here, because on my system, the first connector always appears to be the socket connector. Here's the full list for me on OS X:➔ jruby -rjava -e "puts com.sun.jdi.Bootstrap.virtual_machine_manager.attaching_connectors> "[com.sun.jdi.SocketAttach (defaults: timeout=, hostname=charles-nutters-macbook-pro.local, port=),com.sun.jdi.ProcessAttach (defaults: pid=, timeout=)]The ProcessAttach connector there isn't as magical as it looks; all it does is query the target process to find out what transport it's using (dt_socket in our case) and then calls the right connector (e.g. SocketAttach in the case of dt_socket or SharedMemoryAttach if you use dt_shmem on Windows). In our case, we know it's listening on a socket, so we're using the SocketAttach connector directly.The rest is pretty simple: we get the default arguments from the connector, twiddle them to have the right hostname and port number, and attach to the VM. Now we have a VirtualMachine object we can query and twiddle; we're inside the matrix.With Great Power...So, what can we do with this VirtualMachine object? We can:
walk all classes and objects on the heap
install breakpoints and step-debug any running code
inspect and modify the current state of any running thread, even manipulating in-flight arguments and variables
replace already-loaded classes with new definitions (such as to install custom instrumentation)
Here's the output from JRuby's ri command when we ask about VirtualMachine:➔ ri --java com.sun.jdi.VirtualMachine-------------------------------------- Class: com.sun.jdi.VirtualMachine (no description...)------------------------------------------------------------------------Instance methods:----------------- allClasses, allThreads, canAddMethod, canBeModified, canForceEarlyReturn, canGetBytecodes, canGetClassFileVersion, canGetConstantPool, canGetCurrentContendedMonitor, canGetInstanceInfo, canGetMethodReturnValues, canGetMonitorFrameInfo, canGetMonitorInfo, canGetOwnedMonitorInfo, canGetSourceDebugExtension, canGetSyntheticAttribute, canPopFrames, canRedefineClasses, canRequestMonitorEvents, canRequestVMDeathEvent, canUnrestrictedlyRedefineClasses, canUseInstanceFilters, canUseSourceNameFilters, canWatchFieldAccess, canWatchFieldModification, classesByName, description, dispose, eventQueue, eventRequestManager, exit, getDefaultStratum, instanceCounts, mirrorOf, mirrorOfVoid, name, process, redefineClasses, resume, setDebugTraceMode, setDefaultStratum, suspend, toString, topLevelThreadGroups, version, virtualMachineWe can basically make the target VM dance any way we want, even going so far as to write our own debugger entirely in Ruby code. But that's a topic for another day. Right now, we're going to do some memory inspection.Creating a Histogram of the HeapThe simplest heap inspection we might do is to produce a histogram of all objects on the heap. And as you might expect, this is one of the easiest things to do, because it's the first thing everyone looks for when debugging a memory issue.classes = VM.all_classescounts = VM.instance_counts(classes)classes.zip(counts)VirtualMachine.all_classes gives you a list (a java.util.List, but we make those behave mostly like a Ruby Array) of every class the JVM has loaded, including Ruby classes, JRuby core and runtime classes, and other Java classes that JRuby and the JVM use. VirtualMachine.instance_counts takes that list of classes and returns another list of instance counts. Zip the two together, and we have an array of classes and instance counts. So easy!Let's take these two pieces and put them together in an easy-to-use classrequire 'java'module JRuby class Debugger VMM = com.sun.jdi.Bootstrap.virtual_machine_manager attr_accessor :vm def initialize(options = {}) connectors = VMM.attaching_connectors if options[:port] connector = connectors.find {|ac| ac.name =~ /Socket/} elsif options[:pid] connector = connectors.find {|ac| ac.name =~ /Process/} end args = connector.default_arguments for k, v in options args[k.to_s].value = v.to_s end @vm = connector.attach(args) end # Generate a histogram of all classes in the system def histogram classes = @vm.all_classes counts = @vm.instance_counts(classes) classes.zip(counts) end endendI've taken the liberty of expanding the connection process to handle pids and other arguments passed in. So to get a histogram from a VM listening on localhost port 12345, we can simply do:JRuby::Debugger.new(:hostname => 'localhost', :port => 12345).histogramNow of course this list is going to have a lot of JRuby and Java objects that we might not be interested in, so we'll want to filter it to just the Ruby classes. On JRuby master, all the generated Ruby classes start with a package name "ruby". Unfortunately, jitted Ruby methods start with a package of "ruby.jit" right now, so we'll want to filter those out too (unless you're interested in them, of course...JRuby is an open book!)require 'jruby_debugger'# connect to the VMdebugr = JRuby::Debugger.new(:hostname => 'localhost', :port => 12345)histo = debugr.histogram# sort by counthisto.sort! {|a,b| b[1] <=> a[1]}# filter to only user-created Ruby classes with >0 instanceshisto.each do |cls,num| next if num == 0 || cls.name[0..4] != 'ruby.' || cls.name[5..7] == 'jit' puts "#{num} instances of #{cls.name[5..-1].gsub('.', '::')}"endIf we run this short script against our Rails application, we see similar results to the previous posts (but it's cooler, because we're doing it all from Ruby!)➔ jruby ruby_histogram.rb | head -1011685 instances of TZInfo::TimezoneTransitionInfo1071 instances of Gem::Version1012 instances of Gem::Requirement592 instances of TZInfo::TimezoneOffsetInfo432 instances of Gem::Dependency289 instances of Gem::Specification142 instances of ActiveSupport::TimeZone118 instances of TZInfo::DataTimezoneInfo118 instances of TZInfo::DataTimezone45 instances of Gem::PlatformJust so we're all on the same page, it's important to know what we're actually dealing with here. VirtualMachine.all_classes returns a list of com.sun.jdi.ReferenceType objects. Let's ri that.➔ ri --java com.sun.jdi.ReferenceType--------------------------------------- Class: com.sun.jdi.ReferenceType (no description...)------------------------------------------------------------------------Instance methods:----------------- allFields, allLineLocations, allMethods, availableStrata, classLoader, classObject, compareTo, constantPool, constantPoolCount, defaultStratum, equals, failedToInitialize, fieldByName, fields, genericSignature, getValue, getValues, hashCode, instances, isAbstract, isFinal, isInitialized, isPackagePrivate, isPrepared, isPrivate, isProtected, isPublic, isStatic, isVerified, locationsOfLine, majorVersion, methods, methodsByName, minorVersion, modifiers, name, nestedTypes, signature, sourceDebugExtension, sourceName, sourceNames, sourcePaths, toString, virtualMachine, visibleFields, visibleMethodsYou can see there's quite a bit more you can do with a ReferenceType. Let's try something.Digging Deeper Into TimezoneTransitionInfoLet's actually take some time to explore our old friend TimezoneTransitionInfo (hereafter referred to as TTI). Instead of walking all classes in the system, we'll want to just grab TTI directly. For that we use VirtualMachine.classes_by_name, which returns a list of classes on the target VM of that name. There should be only one, since we only have a single JRuby instance in our server, so we'll grab that class and request exactly one instance of it...any old instance.tti_class = debugr.vm.classes_by_name('ruby.TZInfo.TimezoneTransitionInfo')[0]tti_obj = tti_class.instances(1)[0]puts tti_objRunning this we can see we've got the reference we're looking for.➔ jruby tti_digger.rbinstance of ruby.TZInfo.TimezoneTransitionInfo(id=2)ReferenceType.instances returns a list (no larger than the specified size, or all instances if you specify 0) of com.sun.jdi.ObjectReference objects.➔ ri --java com.sun.jdi.ObjectReference------------------------------------- Class: com.sun.jdi.ObjectReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, owningThread, referenceType, referringObjects, setValue, toString, type, uniqueID, virtualMachine, waitingThreadsAmong the weirder things like disabling garbage collection for this object or listing all threads waiting on this object's monitor (a la 'synchronize' in Java), we can access the object's fields through getValue and setValue.Let's examine the instance variables TTI contains. You may recall from previous posts that all Ruby objects in JRuby store their instance variables in an array, to avoid the large memory and cpu cost of storing them in a map. We can grab a reference to that array and display its contents.var_table_field = tti_class.field_by_name('varTable')tti_vars = tti_obj.get_value(var_table_field)puts "varTable: #{tti_vars}"puts tti_vars.values.map(&:to_s)And the new output:➔ jruby tti_digger.rbvarTable: instance of java.lang.Object[7] (id=13)instance of ruby.TZInfo.TimezoneOffsetInfo(id=15)instance of ruby.TZInfo.TimezoneOffsetInfo(id=16)instance of org.jruby.RubyFixnum(id=17)instance of org.jruby.RubyFixnum(id=18)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)instance of org.jruby.RubyNil(id=19)Since the varTable field is a simple Object[] in Java, the reference we get to it is of type com.sun.jdi.ArrayReference.➔ ri --java com.sun.jdi.ArrayReference-------------------------------------- Class: com.sun.jdi.ArrayReference (no description...)------------------------------------------------------------------------Instance methods:----------------- disableCollection, enableCollection, entryCount, equals, getValue, getValues, hashCode, invokeMethod, isCollected, length, owningThread, referenceType, referringObjects, setValue, setValues, toString, type, uniqueID, virtualMachine, waitingThreadsOf course each of these references can be further explored, but already we can see that this TTI instance has seven instance variables: two TimezoneOffsetInfo objects, two Fixnums, and three nils. But we don't have instance variable names!Instance variable names are only stored on the object's class. There, a table of names to offsets is kept up-to-date as new instance variable names are discovered. We can access this from the TTI class reference and combine it with the variable table to get the output we want to see.# get the metaclass object and class referencemetaclass_field = tti_class.field_by_name('metaClass')tti_class_obj = tti_obj.get_value(metaclass_field)tti_class_class = tti_class_obj.reference_type# get the variable names from the metaclass objectvar_names_field = tti_class_class.field_by_name('variableNames')var_names = tti_class_obj.get_value(var_names_field)# splice the names and values togethertable = var_names.values.zip(tti_vars.values)puts tableThis looks a bit complicated, but there's actually a lot of boilerplate here we could put into a utility class. For example, the metaClass and variableNames fields are standard on all (J)Ruby objects and classes, respectively. But considering that we're actually walking a remote VM's *live* heap...this is pretty simple code.Here's what our script outputs now:➔ jruby tti_digger.rb"@offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=25)"@previous_offset"instance of ruby.TZInfo.TimezoneOffsetInfo(id=26)"@numerator_or_time"instance of org.jruby.RubyFixnum(id=27)"@denominator"instance of org.jruby.RubyFixnum(id=28)"@at"instance of org.jruby.RubyNil(id=29)"@local_end"instance of org.jruby.RubyNil(id=29)"@local_start"instance of org.jruby.RubyNil(id=29)We could go even deeper, but I think you get the idea.Your TurnHere's a gist of the three scripts we've created, so you can refer to and build off of them. And of course the javadocs and ri docs will help you as well, plus everything we've done here you can do in a jirb session.There's a lot to the JDI API, but once you've got the VirtualMachine object in hand it's pretty easy to follow. As you'd expect from any debugger API, you need to know a bit about how things work on the inside, but through the magic of JRuby it's actually possible to write most of those fancy memory and debugging tools entirely in Ruby. Perhaps this article has peaked your interest in exploring JRuby internals using JDI and you might start to write debugging tools. Perhaps we can ship a few utilities to make some of the boilerplate go away. In any case, I hope this series of articles shows that JRuby users have an amazing library of tools available to them, and you don't even have to leave your comfort zone if you don't want to.Note: The variableNames field is a recent addition to JRuby master, so if you'd like to play with that you'll probably want to build JRuby yourself or wait for a nightly build that picks it up. But you can certainly do a lot of exploring even without that patch. [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
After my post on Browsing Memory the JRuby Way, one commenter and several other folks suggested I actually show using Eclipse MAT with JRuby. So without further ado...The Eclipse Memory Analyzer, like many Eclipse-based applications, starts up with a
... [More]
"for dummies" page linking to various actions.The most interesting use of MAT is to analyze a heap dump in a bit more interactive way than with the "jhat" tool. The analysis supports the "jmap" dump format, so we'll proceed to get a jmap dump of a "leaky" Rails application.I've added this controller to a simple application:class LeakyController < ApplicationController class MyData def initialize(params) @params = params end end LEAKING_ARRAY = {} def index LEAKING_ARRAY[Time.now] = MyData.new(params) render :text => "There are #{LEAKING_ARRAY.size} elements now!" endendSome genius has decided to save all recent request parameters into a constant on the LeakyController, keyed by time, wrapped in a custom type, and never cleaned out. Perhaps this was done temporarily for debugging, or perhaps we have a moron on staff. Either way, we need to find this problem and fix it.We'll run this application and crank 10000 requests through the /leaky index, so the final request should output "There are 10000 elements now!"~ ➔ ab -n 10000 http://localhost:3000/leakyThis is ApacheBench, Version 2.3 <$Revision: 655654 $>Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/Licensed to The Apache Software Foundation, http://www.apache.org/Benchmarking localhost (be patient)Completed 1000 requestsCompleted 2000 requests...After 10000 requests have completed, we notice this application seems to grow and grow until it maxes out the heap (JRuby, being on the JVM, automatically limits heap sizes for you). Let's start by using jmap to investigate the problem.~ ➔ jps -l61976 org/jruby/Main61999 sun.tools.jps.Jps61837~ ➔ jmap -histo 61976 | grep " ruby\." | head -5 37: 11685 280440 ruby.TZInfo.TimezoneTransitionInfo 40: 10000 240000 ruby.LeakyController.MyData133: 970 23280 ruby.Gem.Version137: 914 21936 ruby.Gem.Requirement170: 592 14208 ruby.TZInfo.TimezoneOffsetInfoWe can see our old friend TimezoneTransitionInfo in there, but of course we've learned to accept that one. But what's this LeakyController::MyData object we've apparently got 10000 instances of? Where are they coming from? Who's holding on to them?At this point, we can proceed to get a memory dump and move over to MAT, or have MAT acquire and open the dump in one shot, similar to VisualVM. Let's have MAT do it for us.Getting Our Heap Into MAT(Caveat: While preparing this post, I discovered that the jmap tool for the current OS X Java 6 (build 1.6.0_20-b02-279-10M3065) is not properly dumping all information. As a result, many fields and objects don't show up in dump analysis tools like MAT. Fortunately, there's a way out; on OS X, you can grab Soylatte or OpenJDK builds from various sources that work properly. In my case, I'm using a local build of OpenJDK 7.)From the File menu, we select Acquire Heap Dump.The resulting dialog should be familiar, since it lists the same JVM processes the "jps" command listed above. (If you had to specify a specific JDK home, like me, you'll need to click the "Configure" button and set the "jdkhome" flag" for "HPROF jmap dump provider".)We'll pick our Rails instance (pid 61976) and proceed.MAT connects to the process, pulls a heap dump to disk, and immediately proceeds to parse and open it.Once it has completed parsing, we're presented with a few different paths to follow.On other days, we might be interested in doing some component-by-component browsing to look for fat objects or minor leaks, or we might want to revisit the results of previous analyses against this heap. But today, we really need to figure out this MyData leak, so we'll run the Leak Suspects Report.Leak Suspects?Are you kidding? A tool that can search out and report possible leaks in a running system? Yes, Virginia, there is a Santa Claus!This is the good side of the "plague of choices" we have on the JVM. Because there's so many tools for almost every basic purpose (like the dozen – at least – memory inspection tools), tool developers have moved on to more specific needs like leak analysis. MAT is my favorite tool for leak-hunting (and it uses less memory than jhat for heap-browsing, which is great for larger dumps).Once MAT has finished chewing on our heap, it presents a pie chart of possible leak suspects. The logic used essentially seeks out data structures whose accumulated size is large in comparison to the rest of the heap. In this case, MAT has identified three suspects that in total comprise over half of the live heap data.Scrolling down we start to get details about these leak candidates.So there's a Hash, a Module, and 711 Class objects in our list of suspects. The Class objects are probably just loaded classes, since the JRuby core classes and additional classes loaded from Rails and its dependent libraries will easily number in the hundreds. We'll ignore that one for now. There's also an unusually large Module taking up almost 4MB of memory. We'll come back to that.The Hash seems like the most likely candidate. Let's expand that.The first new block of information gives us a list of "shortest paths" to the "accumulation point", or the point at which all this potentially-leaking data is gathering. There's more to this in the actual application, but I'm showing the top of the "path" here.At the top of this list, we see the RubyHash object originally reported as a suspect, and a tree of objects that lead to it. In this case, we go from the Hash itself into a ConcurrentHashMap (note that we're hiding nothing here; you can literally browse anything in memory) which in turn is referenced by the "constants" field of a Class. So already we know that this hash is being referenced in some class's constant table. Pretty cool, eh?Let's make sure we've got the right Hash and not some harmless data structure inside Rails. If we scroll down a bit more, we see a listing of all the objects this Hash has accumulated. Let's see what's in there.Ok, so it's a hashtable structure with a table of entries. Can we get more out of this?Of course like most of these tools, just about everything is clickable. We can dive into one of the hash entries and see what's in there. Clicking on an entry gives us several new ways to display the downstream objects we've managed to aggregate. In this case, we'll just do "List Objects", and the suboption "With Outgoing References" for downstream data.Now finally in the resulting view of this particular RubyHashEntry, we can see that our MyData object is happily tucked away inside.Ok, so we definitely have the right data structure. Not only that, but we can see that the entry's "key" is a Time object (org.jruby.RubyTime). Let's go back to the "Shortest Paths" view and examine the ConcurrentHashMap entry that's holding this Hash object. Each entry in this hash maps a constant name to a value, so we should be able to see which constant is holding the leaking references.(At this point you'll see the side effects of my switch to OpenJDK 7; the memory addresses have changed, but the structure is the same.)We'll do another "List Objects" "with outgoing references" against the the HashEntry object immediately referencing our RubyHash.And there it is! In the "key" field of the HashEntry, we see our constant name "LEAKING_ARRAY".What About That Module?Oh yeah, what about that Module that showed up in the leak suspects? It was responsible for almost 4MB of the heap. Let's go back and check it out.A-ha! Eclipse MAT has flagged the Gem module as being a potential leak suspect. But why? Let's go back to the suspect report and look at the Accumulated Objects by Class table, toward the bottom.Ok, so the Gem module eventually references nearly 6000 Gem::Specification objects, which makes up the bulk of our 3.8MB. I guarantee I don't have 6000 gem versions installed. Perhaps that's something that RubyGems should endeavor to fix? Perhaps we've just used JRuby and Eclipse MAT to discover either a leak or wasteful memory use in RubyGems?Evan Phoenix pointed out that I misread the columns. It's actually 249 Specification objects, their "self" size is almost 6000 bytes, and their "retained" size is 3.8MB. But that gives me an opportunity to show off another feature of MAT: Customized Retained Set calculation.In this case, the retained size seems a bit suspect. Could there really be 3.8MB of data kept alive by Gem::Specification objects? It seems like a bit much, to be sure, but digging through the tree of references from the Gem module down shows there's several references to classes and modules, which in turn reference constant tables, method tables, and so on. How can we filter out that extra noise?First we'll return to the view of the Gem module (two screenshots up) by going back to leak suspect #2, expanding "Shortest Paths". The topmost RubyModule in that list is the Gem module, so we're all set to calculate a Customized Retained Set.The resulting dialog provides a list of options through which you can specify classes or fields to ignore when calculating the retained set from a given starting point. In this case, it's simple enough to filter out org.jruby.RubyClass and org.jruby.RubyModule, so that references from Gem::Specification back into the class/module hierarchy don't get included in calculations.Which results in a similar view to those we've seen, but with objects sorted by retained heap.Well what the heck? It looks like it's all String data?JRuby's String implementation is an org.jruby.RubyString object, aggregating an org.jruby.util.ByteList object, aggregating a byte array, so the top three entries there in total are essentially all String memory. The best way to investigate where they're coming from is to do "List Objects" on RubyString, but instead of "with outgoing references" we'll use "with incoming references" to show where all those Strings are coming from.Finally we have a view that lets us hunt through all these strings and see where they're coming from. Poking at the first few shows they're stored in constant tables of the Gem module (that last RubyModule I haven't expanded in). That's probably not a big deal. But if we sort the the list of RubyString objects by their retained sizes, we get a different picture of the system.If we dig into the *largest* String objects, they appear to be referenced by Gem::Specification instance variables! So there's probably something worth investigating here.It's also worth noting that any Ruby application is going to have a lot of Strings in it, so this isn't all that unusual to see. But it's nice to have a tool that lets you investigate potential inefficiencies (even down to the raw bytes!), and it's nice to know that at least some of that retained data for the Gem module is "real" and not just references back into the class hierarchy.(And I'm not convinced all those Strings really *need* to be alive...but you're welcome to take it from here!)Your TurnEclipse MAT is probably one of the nicest of the free tools. In addition to object browsing, leak detection, GC root analysis, and object query language support, there's a ton of other features, both in the main distribution and available from third parties. If you're hunting for memory leaks, or just want to investigate the memory usage of your (J)Ruby application, MAT is a tool worth playing with (and as always, I hope you will blog and report your experiences!) [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
After my post on Browsing Memory the JRuby Way, one commenter and several other folks suggested I actually show using Eclipse MAT with JRuby. So without further ado...The Eclipse Memory Analyzer, like many Eclipse-based applications, starts up with a
... [More]
"for dummies" page linking to various actions.The most interesting use of MAT is to analyze a heap dump in a bit more interactive way than with the "jhat" tool. The analysis supports the "jmap" dump format, so we'll proceed to get a jmap dump of a "leaky" Rails application.I've added this controller to a simple application:class LeakyController < ApplicationController class MyData def initialize(params) @params = params end end LEAKING_ARRAY = {} def index LEAKING_ARRAY[Time.now] = MyData.new(params) render :text => "There are #{LEAKING_ARRAY.size} elements now!" endendSome genius has decided to save all recent request parameters into a constant on the LeakyController, keyed by time, wrapped in a custom type, and never cleaned out. Perhaps this was done temporarily for debugging, or perhaps we have a moron on staff. Either way, we need to find this problem and fix it.We'll run this application and crank 10000 requests through the /leaky index, so the final request should output "There are 10000 elements now!"~ ➔ ab -n 10000 http://localhost:3000/leakyThis is ApacheBench, Version 2.3 <$Revision: 655654 $>Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/Licensed to The Apache Software Foundation, http://www.apache.org/Benchmarking localhost (be patient)Completed 1000 requestsCompleted 2000 requests...After 10000 requests have completed, we notice this application seems to grow and grow until it maxes out the heap (JRuby, being on the JVM, automatically limits heap sizes for you). Let's start by using jmap to investigate the problem.~ ➔ jps -l61976 org/jruby/Main61999 sun.tools.jps.Jps61837~ ➔ jmap -histo 61976 | grep " ruby\." | head -5 37: 11685 280440 ruby.TZInfo.TimezoneTransitionInfo 40: 10000 240000 ruby.LeakyController.MyData133: 970 23280 ruby.Gem.Version137: 914 21936 ruby.Gem.Requirement170: 592 14208 ruby.TZInfo.TimezoneOffsetInfoWe can see our old friend TimezoneTransitionInfo in there, but of course we've learned to accept that one. But what's this LeakyController::MyData object we've apparently got 10000 instances of? Where are they coming from? Who's holding on to them?At this point, we can proceed to get a memory dump and move over to MAT, or have MAT acquire and open the dump in one shot, similar to VisualVM. Let's have MAT do it for us.Getting Our Heap Into MAT(Caveat: While preparing this post, I discovered that the jmap tool for the current OS X Java 6 (build 1.6.0_20-b02-279-10M3065) is not properly dumping all information. As a result, many fields and objects don't show up in dump analysis tools like MAT. Fortunately, there's a way out; on OS X, you can grab Soylatte or OpenJDK builds from various sources that work properly. In my case, I'm using a local build of OpenJDK 7.)From the File menu, we select Acquire Heap Dump.The resulting dialog should be familiar, since it lists the same JVM processes the "jps" command listed above. (If you had to specify a specific JDK home, like me, you'll need to click the "Configure" button and set the "jdkhome" flag" for "HPROF jmap dump provider".)We'll pick our Rails instance (pid 61976) and proceed.MAT connects to the process, pulls a heap dump to disk, and immediately proceeds to parse and open it.Once it has completed parsing, we're presented with a few different paths to follow.On other days, we might be interested in doing some component-by-component browsing to look for fat objects or minor leaks, or we might want to revisit the results of previous analyses against this heap. But today, we really need to figure out this MyData leak, so we'll run the Leak Suspects Report.Leak Suspects?Are you kidding? A tool that can search out and report possible leaks in a running system? Yes, Virginia, there is a Santa Claus!This is the good side of the "plague of choices" we have on the JVM. Because there's so many tools for almost every basic purpose (like the dozen – at least – memory inspection tools), tool developers have moved on to more specific needs like leak analysis. MAT is my favorite tool for leak-hunting (and it uses less memory than jhat for heap-browsing, which is great for larger dumps).Once MAT has finished chewing on our heap, it presents a pie chart of possible leak suspects. The logic used essentially seeks out data structures whose accumulated size is large in comparison to the rest of the heap. In this case, MAT has identified three suspects that in total comprise over half of the live heap data.Scrolling down we start to get details about these leak candidates.So there's a Hash, a Module, and 711 Class objects in our list of suspects. The Class objects are probably just loaded classes, since the JRuby core classes and additional classes loaded from Rails and its dependent libraries will easily number in the hundreds. We'll ignore that one for now. There's also an unusually large Module taking up almost 4MB of memory. We'll come back to that.The Hash seems like the most likely candidate. Let's expand that.The first new block of information gives us a list of "shortest paths" to the "accumulation point", or the point at which all this potentially-leaking data is gathering. There's more to this in the actual application, but I'm showing the top of the "path" here.At the top of this list, we see the RubyHash object originally reported as a suspect, and a tree of objects that lead to it. In this case, we go from the Hash itself into a ConcurrentHashMap (note that we're hiding nothing here; you can literally browse anything in memory) which in turn is referenced by the "constants" field of a Class. So already we know that this hash is being referenced in some class's constant table. Pretty cool, eh?Let's make sure we've got the right Hash and not some harmless data structure inside Rails. If we scroll down a bit more, we see a listing of all the objects this Hash has accumulated. Let's see what's in there.Ok, so it's a hashtable structure with a table of entries. Can we get more out of this?Of course like most of these tools, just about everything is clickable. We can dive into one of the hash entries and see what's in there. Clicking on an entry gives us several new ways to display the downstream objects we've managed to aggregate. In this case, we'll just do "List Objects", and the suboption "With Outgoing References" for downstream data.Now finally in the resulting view of this particular RubyHashEntry, we can see that our MyData object is happily tucked away inside.Ok, so we definitely have the right data structure. Not only that, but we can see that the entry's "key" is a Time object (org.jruby.RubyTime). Let's go back to the "Shortest Paths" view and examine the ConcurrentHashMap entry that's holding this Hash object. Each entry in this hash maps a constant name to a value, so we should be able to see which constant is holding the leaking references.(At this point you'll see the side effects of my switch to OpenJDK 7; the memory addresses have changed, but the structure is the same.)We'll do another "List Objects" "with outgoing references" against the the HashEntry object immediately referencing our RubyHash.And there it is! In the "key" field of the HashEntry, we see our constant name "LEAKING_ARRAY".What About That Module?Oh yeah, what about that Module that showed up in the leak suspects? It was responsible for almost 4MB of the heap. Let's go back and check it out.A-ha! Eclipse MAT has flagged the Gem module as being a potential leak suspect. But why? Let's go back to the suspect report and look at the Accumulated Objects by Class table, toward the bottom.Ok, so the Gem module eventually references nearly 6000 Gem::Specification objects, which makes up the bulk of our 3.8MB. I guarantee I don't have 6000 gem versions installed. Perhaps that's something that RubyGems should endeavor to fix? Perhaps we've just used JRuby and Eclipse MAT to discover either a leak or wasteful memory use in RubyGems?Evan Phoenix pointed out that I misread the columns. It's actually 249 Specification objects, their "self" size is almost 6000 bytes, and their "retained" size is 3.8MB. But that gives me an opportunity to show off another feature of MAT: Customized Retained Set calculation.In this case, the retained size seems a bit suspect. Could there really be 3.8MB of data kept alive by Gem::Specification objects? It seems like a bit much, to be sure, but digging through the tree of references from the Gem module down shows there's several references to classes and modules, which in turn reference constant tables, method tables, and so on. How can we filter out that extra noise?First we'll return to the view of the Gem module (two screenshots up) by going back to leak suspect #2, expanding "Shortest Paths". The topmost RubyModule in that list is the Gem module, so we're all set to calculate a Customized Retained Set.The resulting dialog provides a list of options through which you can specify classes or fields to ignore when calculating the retained set from a given starting point. In this case, it's simple enough to filter out org.jruby.RubyClass and org.jruby.RubyModule, so that references from Gem::Specification back into the class/module hierarchy don't get included in calculations.Which results in a similar view to those we've seen, but with objects sorted by retained heap.Well what the heck? It looks like it's all String data?JRuby's String implementation is an org.jruby.RubyString object, aggregating an org.jruby.util.ByteList object, aggregating a byte array, so the top three entries there in total are essentially all String memory. The best way to investigate where they're coming from is to do "List Objects" on RubyString, but instead of "with outgoing references" we'll use "with incoming references" to show where all those Strings are coming from.Finally we have a view that lets us hunt through all these strings and see where they're coming from. Poking at the first few shows they're stored in constant tables of the Gem module (that last RubyModule I haven't expanded in). That's probably not a big deal. But if we sort the the list of RubyString objects by their retained sizes, we get a different picture of the system.If we dig into the *largest* String objects, they appear to be referenced by Gem::Specification instance variables! So there's probably something worth investigating here.It's also worth noting that any Ruby application is going to have a lot of Strings in it, so this isn't all that unusual to see. But it's nice to have a tool that lets you investigate potential inefficiencies (even down to the raw bytes!), and it's nice to know that at least some of that retained data for the Gem module is "real" and not just references back into the class hierarchy.(And I'm not convinced all those Strings really *need* to be alive...but you're welcome to take it from here!)Your TurnEclipse MAT is probably one of the nicest of the free tools. In addition to object browsing, leak detection, GC root analysis, and object query language support, there's a ton of other features, both in the main distribution and available from third parties. If you're hunting for memory leaks, or just want to investigate the memory usage of your (J)Ruby application, MAT is a tool worth playing with (and as always, I hope you will blog and report your experiences!) [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
After my post on Browsing Memory the JRuby Way, one commenter and several other folks suggested I actually show using Eclipse MAT with JRuby. So without further ado...The Eclipse Memory Analyzer, like many Eclipse-based applications, starts up with a
... [More]
"for dummies" page linking to various actions.The most interesting use of MAT is to analyze a heap dump in a bit more interactive way than with the "jhat" tool. The analysis supports the "jmap" dump format, so we'll proceed to get a jmap dump of a "leaky" Rails application.I've added this controller to a simple application:class LeakyController < ApplicationController class MyData def initialize(params) @params = params end end LEAKING_ARRAY = {} def index LEAKING_ARRAY[Time.now] = MyData.new(params) render :text => "There are #{LEAKING_ARRAY.size} elements now!" endendSome genius has decided to save all recent request parameters into a constant on the LeakyController, keyed by time, wrapped in a custom type, and never cleaned out. Perhaps this was done temporarily for debugging, or perhaps we have a moron on staff. Either way, we need to find this problem and fix it.We'll run this application and crank 10000 requests through the /leaky index, so the final request should output "There are 10000 elements now!"~ ➔ ab -n 10000 http://localhost:3000/leakyThis is ApacheBench, Version 2.3 <$Revision: 655654 $>Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/Licensed to The Apache Software Foundation, http://www.apache.org/Benchmarking localhost (be patient)Completed 1000 requestsCompleted 2000 requests...After 10000 requests have completed, we notice this application seems to grow and grow until it maxes out the heap (JRuby, being on the JVM, automatically limits heap sizes for you). Let's start by using jmap to investigate the problem.~ ➔ jps -l61976 org/jruby/Main61999 sun.tools.jps.Jps61837~ ➔ jmap -histo 61976 | grep " ruby\." | head -5 37: 11685 280440 ruby.TZInfo.TimezoneTransitionInfo 40: 10000 240000 ruby.LeakyController.MyData133: 970 23280 ruby.Gem.Version137: 914 21936 ruby.Gem.Requirement170: 592 14208 ruby.TZInfo.TimezoneOffsetInfoWe can see our old friend TimezoneTransitionInfo in there, but of course we've learned to accept that one. But what's this LeakyController::MyData object we've apparently got 10000 instances of? Where are they coming from? Who's holding on to them?At this point, we can proceed to get a memory dump and move over to MAT, or have MAT acquire and open the dump in one shot, similar to VisualVM. Let's have MAT do it for us.Getting Our Heap Into MAT(Caveat: While preparing this post, I discovered that the jmap tool for the current OS X Java 6 (build 1.6.0_20-b02-279-10M3065) is not properly dumping all information. As a result, many fields and objects don't show up in dump analysis tools like MAT. Fortunately, there's a way out; on OS X, you can grab Soylatte or OpenJDK builds from various sources that work properly. In my case, I'm using a local build of OpenJDK 7.)From the File menu, we select Acquire Heap Dump.The resulting dialog should be familiar, since it lists the same JVM processes the "jps" command listed above. (If you had to specify a specific JDK home, like me, you'll need to click the "Configure" button and set the "jdkhome" flag" for "HPROF jmap dump provider".)We'll pick our Rails instance (pid 61976) and proceed.MAT connects to the process, pulls a heap dump to disk, and immediately proceeds to parse and open it.Once it has completed parsing, we're presented with a few different paths to follow.On other days, we might be interested in doing some component-by-component browsing to look for fat objects or minor leaks, or we might want to revisit the results of previous analyses against this heap. But today, we really need to figure out this MyData leak, so we'll run the Leak Suspects Report.Leak Suspects?Are you kidding? A tool that can search out and report possible leaks in a running system? Yes, Virginia, there is a Santa Claus!This is the good side of the "plague of choices" we have on the JVM. Because there's so many tools for almost every basic purpose (like the dozen – at least – memory inspection tools), tool developers have moved on to more specific needs like leak analysis. MAT is my favorite tool for leak-hunting (and it uses less memory than jhat for heap-browsing, which is great for larger dumps).Once MAT has finished chewing on our heap, it presents a pie chart of possible leak suspects. The logic used essentially seeks out data structures whose accumulated size is large in comparison to the rest of the heap. In this case, MAT has identified three suspects that in total comprise over half of the live heap data.Scrolling down we start to get details about these leak candidates.So there's a Hash, a Module, and 711 Class objects in our list of suspects. The Class objects are probably just loaded classes, since the JRuby core classes and additional classes loaded from Rails and its dependent libraries will easily number in the hundreds. We'll ignore that one for now. There's also an unusually large Module taking up almost 4MB of memory. We'll come back to that.The Hash seems like the most likely candidate. Let's expand that.The first new block of information gives us a list of "shortest paths" to the "accumulation point", or the point at which all this potentially-leaking data is gathering. There's more to this in the actual application, but I'm showing the top of the "path" here.At the top of this list, we see the RubyHash object originally reported as a suspect, and a tree of objects that lead to it. In this case, we go from the Hash itself into a ConcurrentHashMap (note that we're hiding nothing here; you can literally browse anything in memory) which in turn is referenced by the "constants" field of a Class. So already we know that this hash is being referenced in some class's constant table. Pretty cool, eh?Let's make sure we've got the right Hash and not some harmless data structure inside Rails. If we scroll down a bit more, we see a listing of all the objects this Hash has accumulated. Let's see what's in there.Ok, so it's a hashtable structure with a table of entries. Can we get more out of this?Of course like most of these tools, just about everything is clickable. We can dive into one of the hash entries and see what's in there. Clicking on an entry gives us several new ways to display the downstream objects we've managed to aggregate. In this case, we'll just do "List Objects", and the suboption "With Outgoing References" for downstream data.Now finally in the resulting view of this particular RubyHashEntry, we can see that our MyData object is happily tucked away inside.Ok, so we definitely have the right data structure. Not only that, but we can see that the entry's "key" is a Time object (org.jruby.RubyTime). Let's go back to the "Shortest Paths" view and examine the ConcurrentHashMap entry that's holding this Hash object. Each entry in this hash maps a constant name to a value, so we should be able to see which constant is holding the leaking references.(At this point you'll see the side effects of my switch to OpenJDK 7; the memory addresses have changed, but the structure is the same.)We'll do another "List Objects" "with outgoing references" against the the HashEntry object immediately referencing our RubyHash.And there it is! In the "key" field of the HashEntry, we see our constant name "LEAKING_ARRAY".What About That Module?Oh yeah, what about that Module that showed up in the leak suspects? It was responsible for almost 4MB of the heap. Let's go back and check it out.A-ha! Eclipse MAT has flagged the Gem module as being a potential leak suspect. But why? Let's go back to the suspect report and look at the Accumulated Objects by Class table, toward the bottom.Ok, so the Gem module eventually references nearly 6000 Gem::Specification objects, which makes up the bulk of our 3.8MB. I guarantee I don't have 6000 gem versions installed. Perhaps that's something that RubyGems should endeavor to fix? Perhaps we've just used JRuby and Eclipse MAT to discover either a leak or wasteful memory use in RubyGems?Evan Phoenix pointed out that I misread the columns. It's actually 249 Specification objects, their "self" size is almost 6000 bytes, and their "retained" size is 3.8MB. But that gives me an opportunity to show off another feature of MAT: Customized Retained Set calculation.In this case, the retained size seems a bit suspect. Could there really be 3.8MB of data kept alive by Gem::Specification objects? It seems like a bit much, to be sure, but digging through the tree of references from the Gem module down shows there's several references to classes and modules, which in turn reference constant tables, method tables, and so on. How can we filter out that extra noise?First we'll return to the view of the Gem module (two screenshots up) by going back to leak suspect #2, expanding "Shortest Paths". The topmost RubyModule in that list is the Gem module, so we're all set to calculate a Customized Retained Set.The resulting dialog provides a list of options through which you can specify classes or fields to ignore when calculating the retained set from a given starting point. In this case, it's simple enough to filter out org.jruby.RubyClass and org.jruby.RubyModule, so that references from Gem::Specification back into the class/module hierarchy don't get included in calculations.Which results in a similar view to those we've seen, but with objects sorted by retained heap.Well what the heck? It looks like it's all String data?JRuby's String implementation is an org.jruby.RubyString object, aggregating an org.jruby.util.ByteList object, aggregating a byte array, so the top three entries there in total are essentially all String memory. The best way to investigate where they're coming from is to do "List Objects" on RubyString, but instead of "with outgoing references" we'll use "with incoming references" to show where all those Strings are coming from.Finally we have a view that lets us hunt through all these strings and see where they're coming from. Poking at the first few shows they're stored in constant tables of the Gem module (that last RubyModule I haven't expanded in). That's probably not a big deal. But if we sort the the list of RubyString objects by their retained sizes, we get a different picture of the system.If we dig into the *largest* String objects, they appear to be referenced by Gem::Specification instance variables! So there's probably something worth investigating here.It's also worth noting that any Ruby application is going to have a lot of Strings in it, so this isn't all that unusual to see. But it's nice to have a tool that lets you investigate potential inefficiencies (even down to the raw bytes!), and it's nice to know that at least some of that retained data for the Gem module is "real" and not just references back into the class hierarchy.(And I'm not convinced all those Strings really *need* to be alive...but you're welcome to take it from here!)Your TurnEclipse MAT is probably one of the nicest of the free tools. In addition to object browsing, leak detection, GC root analysis, and object query language support, there's a ton of other features, both in the main distribution and available from third parties. If you're hunting for memory leaks, or just want to investigate the memory usage of your (J)Ruby application, MAT is a tool worth playing with (and as always, I hope you will blog and report your experiences!) [Less]
|
|
Posted
over 15 years
ago
by
[email protected] (Charles Oliver Nutter)
After my post on Browsing Memory the JRuby Way, one commenter and several other folks suggested I actually show using Eclipse MAT with JRuby. So without further ado...The Eclipse Memory Analyzer, like many Eclipse-based applications, starts up with a
... [More]
"for dummies" page linking to various actions.The most interesting use of MAT is to analyze a heap dump in a bit more interactive way than with the "jhat" tool. The analysis supports the "jmap" dump format, so we'll proceed to get a jmap dump of a "leaky" Rails application.I've added this controller to a simple application:class LeakyController < ApplicationController class MyData def initialize(params) @params = params end end LEAKING_ARRAY = {} def index LEAKING_ARRAY[Time.now] = MyData.new(params) render :text => "There are #{LEAKING_ARRAY.size} elements now!" endendSome genius has decided to save all recent request parameters into a constant on the LeakyController, keyed by time, wrapped in a custom type, and never cleaned out. Perhaps this was done temporarily for debugging, or perhaps we have a moron on staff. Either way, we need to find this problem and fix it.We'll run this application and crank 10000 requests through the /leaky index, so the final request should output "There are 10000 elements now!"~ ➔ ab -n 10000 http://localhost:3000/leakyThis is ApacheBench, Version 2.3 <$Revision: 655654 $>Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/Licensed to The Apache Software Foundation, http://www.apache.org/Benchmarking localhost (be patient)Completed 1000 requestsCompleted 2000 requests...After 10000 requests have completed, we notice this application seems to grow and grow until it maxes out the heap (JRuby, being on the JVM, automatically limits heap sizes for you). Let's start by using jmap to investigate the problem.~ ➔ jps -l61976 org/jruby/Main61999 sun.tools.jps.Jps61837~ ➔ jmap -histo 61976 | grep " ruby\." | head -5 37: 11685 280440 ruby.TZInfo.TimezoneTransitionInfo 40: 10000 240000 ruby.LeakyController.MyData133: 970 23280 ruby.Gem.Version137: 914 21936 ruby.Gem.Requirement170: 592 14208 ruby.TZInfo.TimezoneOffsetInfoWe can see our old friend TimezoneTransitionInfo in there, but of course we've learned to accept that one. But what's this LeakyController::MyData object we've apparently got 10000 instances of? Where are they coming from? Who's holding on to them?At this point, we can proceed to get a memory dump and move over to MAT, or have MAT acquire and open the dump in one shot, similar to VisualVM. Let's have MAT do it for us.Getting Our Heap Into MAT(Caveat: While preparing this post, I discovered that the jmap tool for the current OS X Java 6 (build 1.6.0_20-b02-279-10M3065) is not properly dumping all information. As a result, many fields and objects don't show up in dump analysis tools like MAT. Fortunately, there's a way out; on OS X, you can grab Soylatte or OpenJDK builds from various sources that work properly. In my case, I'm using a local build of OpenJDK 7.)From the File menu, we select Acquire Heap Dump.The resulting dialog should be familiar, since it lists the same JVM processes the "jps" command listed above. (If you had to specify a specific JDK home, like me, you'll need to click the "Configure" button and set the "jdkhome" flag" for "HPROF jmap dump provider".)We'll pick our Rails instance (pid 61976) and proceed.MAT connects to the process, pulls a heap dump to disk, and immediately proceeds to parse and open it.Once it has completed parsing, we're presented with a few different paths to follow.On other days, we might be interested in doing some component-by-component browsing to look for fat objects or minor leaks, or we might want to revisit the results of previous analyses against this heap. But today, we really need to figure out this MyData leak, so we'll run the Leak Suspects Report.Leak Suspects?Are you kidding? A tool that can search out and report possible leaks in a running system? Yes, Virginia, there is a Santa Claus!This is the good side of the "plague of choices" we have on the JVM. Because there's so many tools for almost every basic purpose (like the dozen – at least – memory inspection tools), tool developers have moved on to more specific needs like leak analysis. MAT is my favorite tool for leak-hunting (and it uses less memory than jhat for heap-browsing, which is great for larger dumps).Once MAT has finished chewing on our heap, it presents a pie chart of possible leak suspects. The logic used essentially seeks out data structures whose accumulated size is large in comparison to the rest of the heap. In this case, MAT has identified three suspects that in total comprise over half of the live heap data.Scrolling down we start to get details about these leak candidates.So there's a Hash, a Module, and 711 Class objects in our list of suspects. The Class objects are probably just loaded classes, since the JRuby core classes and additional classes loaded from Rails and its dependent libraries will easily number in the hundreds. We'll ignore that one for now. There's also an unusually large Module taking up almost 4MB of memory. We'll come back to that.The Hash seems like the most likely candidate. Let's expand that.The first new block of information gives us a list of "shortest paths" to the "accumulation point", or the point at which all this potentially-leaking data is gathering. There's more to this in the actual application, but I'm showing the top of the "path" here.At the top of this list, we see the RubyHash object originally reported as a suspect, and a tree of objects that lead to it. In this case, we go from the Hash itself into a ConcurrentHashMap (note that we're hiding nothing here; you can literally browse anything in memory) which in turn is referenced by the "constants" field of a Class. So already we know that this hash is being referenced in some class's constant table. Pretty cool, eh?Let's make sure we've got the right Hash and not some harmless data structure inside Rails. If we scroll down a bit more, we see a listing of all the objects this Hash has accumulated. Let's see what's in there.Ok, so it's a hashtable structure with a table of entries. Can we get more out of this?Of course like most of these tools, just about everything is clickable. We can dive into one of the hash entries and see what's in there. Clicking on an entry gives us several new ways to display the downstream objects we've managed to aggregate. In this case, we'll just do "List Objects", and the suboption "With Outgoing References" for downstream data.Now finally in the resulting view of this particular RubyHashEntry, we can see that our MyData object is happily tucked away inside.Ok, so we definitely have the right data structure. Not only that, but we can see that the entry's "key" is a Time object (org.jruby.RubyTime). Let's go back to the "Shortest Paths" view and examine the ConcurrentHashMap entry that's holding this Hash object. Each entry in this hash maps a constant name to a value, so we should be able to see which constant is holding the leaking references.(At this point you'll see the side effects of my switch to OpenJDK 7; the memory addresses have changed, but the structure is the same.)We'll do another "List Objects" "with outgoing references" against the the HashEntry object immediately referencing our RubyHash.And there it is! In the "key" field of the HashEntry, we see our constant name "LEAKING_ARRAY".What About That Module?Oh yeah, what about that Module that showed up in the leak suspects? It was responsible for almost 4MB of the heap. Let's go back and check it out.A-ha! Eclipse MAT has flagged the Gem module as being a potential leak suspect. But why? Let's go back to the suspect report and look at the Accumulated Objects by Class table, toward the bottom.Ok, so the Gem module eventually references nearly 6000 Gem::Specification objects, which makes up the bulk of our 3.8MB. I guarantee I don't have 6000 gem versions installed. Perhaps that's something that RubyGems should endeavor to fix? Perhaps we've just used JRuby and Eclipse MAT to discover either a leak or wasteful memory use in RubyGems?Evan Phoenix pointed out that I misread the columns. It's actually 249 Specification objects, their "self" size is almost 6000 bytes, and their "retained" size is 3.8MB. But that gives me an opportunity to show off another feature of MAT: Customized Retained Set calculation.In this case, the retained size seems a bit suspect. Could there really be 3.8MB of data kept alive by Gem::Specification objects? It seems like a bit much, to be sure, but digging through the tree of references from the Gem module down shows there's several references to classes and modules, which in turn reference constant tables, method tables, and so on. How can we filter out that extra noise?First we'll return to the view of the Gem module (two screenshots up) by going back to leak suspect #2, expanding "Shortest Paths". The topmost RubyModule in that list is the Gem module, so we're all set to calculate a Customized Retained Set.The resulting dialog provides a list of options through which you can specify classes or fields to ignore when calculating the retained set from a given starting point. In this case, it's simple enough to filter out org.jruby.RubyClass and org.jruby.RubyModule, so that references from Gem::Specification back into the class/module hierarchy don't get included in calculations.Which results in a similar view to those we've seen, but with objects sorted by retained heap.Well what the heck? It looks like it's all String data?JRuby's String implementation is an org.jruby.RubyString object, aggregating an org.jruby.util.ByteList object, aggregating a byte array, so the top three entries there in total are essentially all String memory. The best way to investigate where they're coming from is to do "List Objects" on RubyString, but instead of "with outgoing references" we'll use "with incoming references" to show where all those Strings are coming from.Finally we have a view that lets us hunt through all these strings and see where they're coming from. Poking at the first few shows they're stored in constant tables of the Gem module (that last RubyModule I haven't expanded in). That's probably not a big deal. But if we sort the the list of RubyString objects by their retained sizes, we get a different picture of the system.If we dig into the *largest* String objects, they appear to be referenced by Gem::Specification instance variables! So there's probably something worth investigating here.It's also worth noting that any Ruby application is going to have a lot of Strings in it, so this isn't all that unusual to see. But it's nice to have a tool that lets you investigate potential inefficiencies (even down to the raw bytes!), and it's nice to know that at least some of that retained data for the Gem module is "real" and not just references back into the class hierarchy.(And I'm not convinced all those Strings really *need* to be alive...but you're welcome to take it from here!)Your TurnEclipse MAT is probably one of the nicest of the free tools. In addition to object browsing, leak detection, GC root analysis, and object query language support, there's a ton of other features, both in the main distribution and available from third parties. If you're hunting for memory leaks, or just want to investigate the memory usage of your (J)Ruby application, MAT is a tool worth playing with (and as always, I hope you will blog and report your experiences!) [Less]
|