Search
RubyConf 2011
Debugging Ruby
Edit
#debugging
#memory-management
#performance
#profiling
#ruby-1-9
#garbage-collection
Summarized using AI

Debugging Ruby

Hemant Kumar • September 29, 2011 • New Orleans, Louisiana • Talk

In the presentation titled Debugging Ruby at RubyConf 2011, speaker Hemant Kumar discusses techniques and tools for identifying and resolving performance and memory issues in Ruby applications, specifically focusing on Ruby 1.9.

The talk starts with an overview of common issues developers face in Ruby applications such as hung processes, memory leaks, and excessive garbage collection time. Hemant emphasizes the importance of leveraging modern profiling tools to enhance Ruby application performance. The session is hands-on, showcasing practical examples and demonstrations to illustrate the usage of various profiling tools.

Key Points Discussed:

  • Introduction to Debugging Ruby: The shift from 1.8 to 1.9 as the primary focus for Ruby applications and debugging.
  • Importance of Profiling: Understanding CPU and memory profiling as vital components for optimizing application performance.
  • Profiling Tools for Ruby 1.9: Hemant introduces different tools available for 1.9, including:
    • puf-tools: A sampling profiler that records where Ruby spends its time, demonstrating its use on both simple programs and Rails applications.
    • Ruby Prof: Discussed as a more traditional profiler that analyzes method calls and tracks time spent.
    • MPR & mov: Tools that help with memory profiling and can identify memory leaks within the application by hooking into Ruby’s allocation methods.
    • gdb.rb: A tool for inspecting live Ruby processes, enabling developers to query objects within the Ruby heap.
  • Demonstrations: Detailed demonstrations on how to implement these tools in Ruby applications were conducted, showing the audience how to track and analyze data effectively, including:
    • Running profiling commands.
    • Interpreting profiler output from puf-tools and Ruby Prof, explaining graphs and method call traces.
    • Identifying hotspots and memory usage patterns.
  • Garbage Collection Profiling: The significance of using Ruby’s GC profiler to evaluate the effects of memory on overall performance. Hemant showed examples of how to detect memory leaks using profiling output, emphasizing the importance of keeping memory usage low to reduce GC times.

Conclusion and Takeaways:

  • Proper tooling and profiling are essential for debugging Ruby applications, especially when migrating from 1.8 to 1.9.
  • Developers must prioritize performance debugging by using the right profiling tools, as understanding where bottlenecks originate can lead to significant improvements in application performance.
  • The discussion encourages Ruby developers to adopt these tools in their workflow to enhance application performance and reliability, ensuring smoother execution and better resource management.

Debugging Ruby
Hemant Kumar • New Orleans, Louisiana • Talk

Date: September 29, 2011
Published: December 12, 2011
Announced: unknown

As Ruby programmers our server side programs throw us in all kind of troubles. Hung processes, memory leaks, process spending too much time in GC, profiling etceteras. As mostly live coding and hands on session, I intend to show - how to use modern tools to find and fix these problems. I will be demonstrating, how to use GDB with live process, using rbtrace, perftools and various ways to detect memory leaks & performance bottle necks in your process.

RubyConf 2011

00:00:17.000 today I'm going to talk about the the title of the talk is a little a bit of misnomer I to say uh it's like it's
00:00:23.760 title debugging Ruby uh but as I started preparing the slides I resulted what I
00:00:28.960 want to talk about is how to debug or how to fix your how to fix various problems with your Ruby applications
00:00:35.719 like performance issues memory issues and I set out to uh prepare my talk with
00:00:42.879 that in mind uh about me uh I go by
00:00:47.920 Nicki on Twitter IRC pretty much everywhere GitHub I work for brib
00:00:54.879 system and uh that's pretty much about it and so there a change of plans and
00:01:01.559 I'm going to talk about CPU and memory profiling of Ruby
00:01:07.600 applications these two topics are pretty much big enough in themselves and I'm going to show how you can do CPU and M
00:01:15.720 profiling of your application so that your applications run faster and better okay uh another thing is like uh
00:01:24.200 if you have been using 1.8 for a while you know pretty much the tools that are there for 1. 8 actually uh the focus of
00:01:33.240 this this talk is going to be 1.9 because uh just show off hands how many
00:01:39.560 of you are writing uh your applications that Target 1.9 today okay pretty much so the focus of
00:01:48.119 this talk is going to be 1.9 non one not 1.8 and we'll take it from
00:01:54.520 there is the funny thing what happened was like I'm using showoff to do this presentation and I just switched to 1.9
00:02:02.640 and then ran this show off serve the Ruby crash actually so this slide was
00:02:07.759 inserted as a last minute gesture and it was like you know like uh R magic was
00:02:13.120 creating problem and then I had to switch to 187 and then that's how the slides are running actually right now so
00:02:20.160 when you're saying debugging Ruby and you you hit a bit of stumbling block
00:02:25.200 that's great so uh all such problems when you
00:02:30.640 see a segmentation fault should be reported to Ruby core it's always handy
00:02:35.720 to have a debug build of Ruby so that uh the the back race that you send to Ruby Cod is Meaningful this is what I use
00:02:42.599 typically to have a debug build of Ruby it works great and yeah it gives great
00:02:48.720 Backes if Ruby crashes somehow now uh this is this is a bike uh
00:02:57.040 Indian bike actually it's sold I think W over as as well it's it's Royal infield bullet actually it's it's called and uh
00:03:04.159 if you look closely uh here you see the there's a BMW logo there I don't know
00:03:09.799 how it came there but that's the Ruby language actually that's the Ruby language which is beautiful but but the
00:03:16.000 way it stands uh if you're not being too
00:03:21.080 careful MRI as it stands today is little rusty around edges and it can throw you
00:03:26.599 in trouble actually what we want is this
00:03:32.200 so without tooling like without proper tooling tools to do performance and
00:03:37.239 memory uh profiling you cannot get this actually no there's no way you're going to get
00:03:43.120 there per so tooling is important and I think that kichi when he
00:03:51.280 talked about in his 1.9.3 and future talk he talked about uh uh the future
00:03:56.519 versions of Ru is going to have more instrumentation to do such things easier to do meor to to uh to make it easier
00:04:03.159 for memory and profiler writers uh for for CPU and profile writers to do certain things and I was yeah so getting
00:04:11.120 back it a little bit of a detour like 1.9 is the future remember and uh yeah
00:04:18.000 this this got like you know RL skill right like just that's that's the way it
00:04:23.560 is and so before you rewrite decide to rewrite your code and language X Scala
00:04:29.560 this this this this joke is on me not on anyone else actually so profiler
00:04:34.960 applications uh that's the key uh we are going to talk about the
00:04:41.160 profiling tools that are available today with for Ruby 1.9 uh first the bad news the tools that
00:04:48.120 have that you have been using for a while for doing uh profiling uh of your Ruby 1.8
00:04:54.160 applications Bleak House doesn't work on 1 uh 1.9 uh me Prof doesn't work on
00:05:01.919 1.9 uh Ruby Prof if you're using it for doing uh uh profiling only CPU profiling
00:05:09.520 works so this is the bad news if you're writing a 1.9 application the good news
00:05:16.080 is uh at least CPU profiling works for Ruby uh when you're using Ruby Prof uh
00:05:23.199 puff D.B which is written by which is written by amen that works great with 1.9 I'm going to show you how to use
00:05:30.039 puff tools to profile your Ruby and rail applications uh MPR uh for for this uh
00:05:36.160 conference I've been hacking for a while and I got I have I have ported uh uh mov
00:05:42.280 to completely work on 1.9 so hopefully I'll be releasing that as a gem and and see how it can be merged Upstream but
00:05:48.720 I'll show you how to use mov with 1.9 and uh gdp. RB which is another
00:05:55.479 project WR by Amon that can be used for memory profiling of 1.9
00:06:01.199 applications okay one step at a time we'll talk CPU profiling uh what does
00:06:06.840 CPU profiling means it means uh when your code is running where are
00:06:12.560 your hotspots where is your code spending most of its time which methods are taking most of time that's basically
00:06:19.840 is all about CPU profiling if you know the the the the the problematic areas you can change the
00:06:27.199 code you can use new you can put right data structures there you have seen like you're all aware how require was so slow
00:06:33.560 in 1.9.2 which was fixed trivially with a patch in 1.9.3 so choice of data SES and all that
00:06:40.720 things can make a difference but you got to know where your bottlenecks are so that that's where CPU profiling comes in
00:06:46.919 and just a bit here that if you are a profile writer CPU profile writer you
00:06:52.759 got to use this function basically which which lets you hook into even call actually whenever a call
00:07:00.080 returns or or a ruby call gets call and it's returns so you can Time Each method how much time Ruby is spending in that
00:07:06.759 particular method uh bunch of profilers that that we going to talk about they use this method for writing
00:07:14.199 profilers so what are the tools that are there for uh CPU profiling puff do tools. RB first uh
00:07:22.560 tool that we going to talk about and then second is Ru Prof third is LL
00:07:27.759 Prof puff tools to uh it's based on Google puf tools
00:07:33.080 project how many of have previously used puf tools here or per tools. RB in one
00:07:38.639 form or another okay perfect few hands great so Google puff
00:07:46.560 tools is a great way to profile your C or C++ applications but auto box it
00:07:53.479 cannot profile Ruby applications uh amen has passed uh puf tools so that it can
00:07:59.840 hook into uh it can get the Ruby stack frame and Records all the data so that it shows you the it can profile Ruby
00:08:08.479 applications uh it's a sampling profiler what does mean by sampling profiler is it's it's not tracking all the method
00:08:15.479 calls it takes like in in one second it takes it collects 100 samples and it gives you data based on that but there
00:08:22.120 are modes when where you can turn on the uh the method based profiling or the object profiling that that's all conf
00:08:28.080 configurable demo time I'm going just of how to use
00:08:38.880 this okay uh is this font not visible definitely
00:08:47.040 okay
00:08:52.399 more it's good yeah perfect so uh we're
00:08:58.160 going to do uh
00:09:06.680 first thing we're going to do is we are going to
00:09:26.000 uh so this is pretty simple program that uh uh just let
00:09:54.399 me this will just be once
00:09:59.720 okay so this is pretty simple program that what it does is basically it wraps
00:10:05.720 uh the actual code in this block puf tools colon col CP profiler Dost start and the location where you want the
00:10:12.279 profile output to be stored is this phone visible
00:10:17.680 no yeah just a second okay yeah okay perfect
00:10:26.480 so that's all it does uh let's see what the more complex code is what that
00:10:33.760 is yeah so it's just uh makes bunch of strings useless stuff basically to
00:10:39.600 demonstrate how this uh this works
00:10:45.959 now no I think now we are set now we are set like oh this is again yeah sucks
00:10:54.800 sorry okay so let's just
00:11:00.800 I ran that program and uh yeah it it wrote the data to this
00:11:08.160 file uh TMP more complex I can generate now a graph with
00:11:14.839 that okay
00:11:31.760 uh so can everyone see this so this is what you get when you ran that uh when
00:11:38.279 you ran your code with MPR sorry pu tools you get where Ruby is spending its time it is spending about uh uh the the
00:11:45.959 way to read this data is like there were 38 samples collected like I said uh perf
00:11:51.120 tools is a sampling profiler and uh out of which four samples it was doing garbage collection and the way to read
00:11:58.240 this like hash this data is uh interpret is like uh this below you see is
00:12:03.959 basically cumulative uh call so how much uh time this
00:12:09.440 procedure how much time was spent totally in this procedure and the before uh that what you see is basically how
00:12:15.760 much time was spent just in that procedure so if this procedure makes calls to another other other methods
00:12:21.639 that that won't be that that won't be shown in the local uh uh sample and
00:12:26.839 cumulative shows all so you can use this data to basically uh do the CPU profiling of your
00:12:33.440 application now uh having done this you will be wondering like how to do like
00:12:39.880 this is pretty simple this is Tri trivial how to how to go about uh doing a big rails application how do I profile
00:12:47.040 a rails application how do I find bottlenecks in a in a big rails application so no problem I'm just going
00:12:52.680 to show you how to do that bar a pretty you know unimaginative name for a rails project so uh it's rails 3.1 project
00:13:01.320 we're going to profile it and see where Ruby is spending all this time okay so
00:13:06.839 to uh it's a standard Ruby uh uh rail 3.1 project all it has is uh uh the one
00:13:13.399 change that I have to two changes you have to do and you can read up internet as well you have to add this gem rack
00:13:20.160 profiles uh profiler and
00:13:26.760 yeah and then you have to
00:13:33.519 yeah and then you have to add this to your uh application. because uh this pu
00:13:39.199 tools profiler is a middleware that traps your request and shows you where it's spending time where you where Ruby
00:13:45.079 spending time after you have done this let's run the rails always run your rails application
00:13:51.880 in production environment when you're are profiling because uh the reloading the when rails reloads code it can cause
00:13:59.120 a lot of noise in your data so ra is running now
00:14:08.720 and and what I'm going to do is uh I'm going to use Curl
00:14:16.680 to can you can you read that yeah so I'm going to hit that uh URL uh and and pass
00:14:22.759 profile equal to true and how many times how many samples I want to collect and and the resultant
00:14:29.160 graph will be saved to this file called barcor
00:14:35.000 R.J you can see the application was head and if I
00:14:40.920 open this
00:14:47.480 file you can start making sense out of it where your real application is spending time it this one is pretty
00:14:54.279 simple application but for a complex application which has like uh doing lot of SQL calls and stuff the the graph
00:15:01.320 will be much more uh meaningful so this is all about puff
00:15:07.959 tools and I hope it's good H
00:15:14.800 yeah next tool we are going to talk about is Ruby Prof okay and how you can
00:15:20.480 do CPU profiling with Ruby Prof a profile written in C uses RB ad
00:15:28.360 event hook again uh uh perf tools does not only when you using you're using
00:15:34.800 method profiler of perf tools perf tools use makes use of this method but but Ru
00:15:39.880 Prof as such uses this method to track all the calls when a ruby call is made when a when the call returns when a c
00:15:46.440 call is made when that call returns and how much time was spend in that method it it tracks all the data keeps it keeps
00:15:52.079 into into into a hashmap and basically you you and gives you various outputs
00:15:57.880 you can uh get FL output you can get uh uh graph output you can get graph HTML and it can potentially do uh memory
00:16:05.920 profiling but unfortunately that's not working at the moment for 1.9 yeah demo time for Ruby Prof
00:16:25.199 so again this is the program that uh
00:16:33.079 is there is same it's this is a sample program and I'll just increase the font
00:16:39.759 uh which basically loads the earlier more complex oo file and uh uh it starts
00:16:46.120 that in that uh you can start your application in the block Ruby profit. profile whatever key thing you want to
00:16:52.319 do and then you can print the output so sorry so we do
00:17:02.880 that yep and if I open
00:17:08.600 this so how many of you here have used uh Ruby
00:17:14.839 Prof okay so Ruby Prof is it's is much older than uh than puf tool so that's
00:17:22.079 that's cool uh you can see uh if you use Ruby Prof this output is
00:17:29.280 pretty much familiar it again shows how much is the total how much uh Ruby is spending uh time in that particular
00:17:36.559 method similar to what the way you read the output of MPR sorry per tools and it
00:17:42.280 it basically gives you like which how it doesn't give you a graph like the way
00:17:47.440 perf tools does but it tells you how the call chain happened actually like like more complex start it called hash each
00:17:54.520 and it it went down like that so this is this is the output of uh Ruby
00:18:00.200 Prof again I just have a quick sample here that that shows you how to do if
00:18:05.679 you have a rails application how to do Ruby uh how to use Ruby Prof with that pretty straightforward again and all you
00:18:12.360 got to do
00:18:23.280 is yeah add this as a gem and then run your rails application with
00:18:30.919 like this okay uh where the output should be saved and uh start the uh
00:18:37.320 scrip rails and it should be you should be pretty good to go sorry there's
00:18:47.400 already yeah so
00:18:55.039 again one thing to keep in mind is uh uh for a large application when you
00:19:01.200 hitting like and you're hitting with five to 6,000 requests the profile data
00:19:06.280 that that Ruby Prof gathers I've have seen it crashing with huge amount of data actually it's uh it's it's really
00:19:12.880 not yeah
00:19:44.240 okay you really don't yeah you can you can do that yeah and and there's a file
00:19:50.640 that come that there's a helper that comes with uh with Ruby Prof you can use to uh like uh Focus particular
00:19:56.919 controller and profile you can do that as well or you can profile it like this and hit your Elsa application and when
00:20:02.679 you press contrl C the output is saved to this file the output is again pretty much similar to you see the dumping the
00:20:09.760 data takes a while and for real large application it can it can it can be a drag actually this Pro this is not the
00:20:16.320 right format HTML to to to see this data uh it's really not so you can see it's
00:20:22.679 like pretty huge uh browser cannot even scroll
00:20:28.360 actually so there
00:20:35.559 that okay so we uh profile a ra application we profile a ruby
00:20:40.600 application we saw what the output is uh another tool that I'm briefly going to
00:20:45.679 talk about is LL Prof uh which is a CPU profiler which was presented at Ruby kagi 2011 this year uh I I I it's there
00:20:56.760 there a bunch of problems with it one is it's not portable at this point in time so you cannot run it in Mac OSX it uses
00:21:03.600 some non portable non-portable functions uh another problem is like uh it it basically has a client server
00:21:09.720 architecture of doing profiling the the the the application with which you
00:21:14.960 running LL Prof it starts a server and certain port and uh the it uses a
00:21:20.400 protocol that it sends the profile data that can be used from a browser or from uh from a Java outlet and and you can
00:21:28.159 see the profile output actually it comes with a with its application but unfortunately it's it's it's very rough
00:21:34.960 it doesn't work on Mac and it did not even work for me on Linux actually so that was the problem and I cannot really
00:21:42.600 demo this one at this point in time maybe it will get improve and it will get fixed and if
00:21:49.279 not okay so next thing we're going to talk about
00:21:55.600 is memory profiling why is memory profiling important for Ruby applications or rails applications
00:22:02.400 Ruby and ra 4 because the the Ruby spends if your
00:22:09.640 application is taking huge amount of memory Ruby is spending more time doing garbage collection rather than actually
00:22:15.440 processing your request so you want to keep your processes low in memory that's the reason you you you you definitely
00:22:22.000 want if your application is huge in size and memory you definitely want to do memory profiling these days with pass
00:22:28.480 passenger and unicorn when the applications can get killed when they hit a certain memory threshold it gets
00:22:34.720 easier when unicorn for example has a has has has a way to configure that the GC can be triggered on each request
00:22:41.200 actually so that that helps with things but that's not good enough that's not really solution and we're going to talk
00:22:48.279 about tools that are available for memory profiling of uh of Ruby
00:22:54.200 applications uh first thing we're going to talk about is what can Ruby 1. n do for me to profile my applications out of
00:23:01.799 box can it tell where the leak is can it tell we're going to talk about that then we going to talk about MPR how to use
00:23:09.080 MPR to detect Le leaks or or memory problems in your
00:23:14.120 application uh and the last tool that we going to talk about is gb. RB how I can connect GDB to a live running
00:23:20.320 application and see what objects it has and whatnot we're going to do this okay and the last is uh Google puff
00:23:29.600 tools comes with a uh with a heap profiler so if you compile Ruby with TCM a lock you can potentially do that but
00:23:36.159 that means that that uh your Ruby dat data structures like your hash or or
00:23:41.400 classes cannot really be shown cannot really be seen in the
00:23:46.480 output okay so what does Ruby 1.9 provide out of box one of the one of the
00:23:52.320 coolest thing is GC profiler uh GC col profile. report that you can use to uh
00:23:58.440 see how much uh how much time ru is spending in GC if you see a incremental
00:24:04.720 time it's always increasing Time ruby spending in in GC and the number of objects is increasing there's definitely
00:24:11.240 a leak in your application that you need to fix demo
00:24:16.760 time okay so
00:24:41.360 this is a very simple application uh this simple application a simple program what it does is it leaks
00:24:51.600 memory really so you see here it's just when you call start allocating it stores
00:24:58.399 all those random data in the hashmap and it just leaks memory that's all it does and uh we have to before we can uh get
00:25:05.640 the report we must enable the profiler and then you can call report and that's it let's run it see what
00:25:22.760 happens okay the output is like uh let me show uh it doesn't fit really on the
00:25:29.679 screen side that we have uh we are constrained with you can see there was
00:25:35.240 in when the program quit before that there was 53 invokes of GC and an index gives
00:25:42.039 you how much time Ruby spent in the first in work of GC so you can see the first time uh first in work ruby spent 0
00:25:50.240 uh millisecond in the in the doing the GC and the uh object size was 16 167
00:25:56.880 kilobytes and the total number of object was 9,816 the second GC when it was invoked
00:26:02.480 Ruby spent much more time 8 and the number of objects was 10,225 as it goes you can see that when
00:26:09.960 it reaches the 54th or 53rd GC then
00:26:15.720 the yeah you can see the number of objects is like 2 million and the number
00:26:20.840 and the time spent is 3.5 537 milliseconds Ruby is spending
00:26:26.200 significant amount of time doing uh these the GC and the number of objects is exponentially increasing there's
00:26:32.880 definitely a leak in your application so this will not tell you where the leak is coming from so you need to use other
00:26:40.240 tools to do that I'm going to show show how to use mov to do that but this definitely can tell you if there's a
00:26:45.279 leak and this is pretty lightweight that you can use uh before this came people used to uh count uh uh people used to
00:26:51.640 what they used to they used to travel the object space and count what each object that is there and their type and
00:26:57.799 how many strings how many uh how many you know uh like user controller how many user model and they ised to count
00:27:03.880 it and see okay how many how how much objects are getting created on the each
00:27:09.320 each request but the problem with that was the profile data is basically polluting your uh a profile data that
00:27:16.279 you're Gathering is basically being shown as well when you are doing when you're walking the object space in Ruby
00:27:23.279 you got to be careful about that and and this is pretty lightweight and can show you that so use it
00:27:29.919 for doing the lightweight uh GC
00:27:35.600 profiling Ruby also comes with extension with a library call that you you have to
00:27:41.200 require require of space and then it gives you these methods like count object size count t count nodes count T
00:27:48.120 data objects nodes is basically Ruby stores your code as well as objects like
00:27:53.840 your if else everything is stored as node objects then T data objects is the internal data stres that Ruby uses to
00:27:59.919 store data so you can you can get that information with Ruby 1.9 it's pretty simple uh probably not
00:28:12.120 even yeah you can see the output here let me show you the
00:28:19.840 code yeah so you can just do some allocations and then you can count
00:28:25.440 object size count notes count T data objects and it gives you this data like yeah the TCL class T module this many
00:28:31.679 objects T string this many objects yeah again this may not be useful for
00:28:37.440 exactly pinpointing where leak is in your application so yeah with with 1.9 it
00:28:44.720 was things can get tricky the last tool that we're going to talk about is uh not
00:28:49.919 last sorry the second last MPR what is MPR uh how many of you have
00:28:57.559 used profia before and a follower of Jo damato and
00:29:02.840 his blogs time to bleed okay so it's a trampoline it uses
00:29:09.320 trampoline to hook into RB uh new OB and
00:29:14.480 RB and add free list method RB new OBG method gets called whenever you allocate
00:29:20.919 object any single objects when it gets allocated in Ruby that method gets called whenever object get free that
00:29:26.360 method gets called and it basically it it not only these two method but it it basically hooks into a bunch of other
00:29:32.240 methods as well to get that profiling data uh and the traces traces these
00:29:38.600 called traces traces can be added to pretty much any c function call problem
00:29:43.799 with that is this is not cross crossplatform and uh official version does not work with 1.9 it is and uh
00:29:52.279 mostly no new development for for a while now and it needs a hosted uh web
00:29:58.080 base visualizer so these are the bunch of problems that are there with MPR uh good stuff is that it it uh dumps
00:30:06.240 Heap and stack at Json so you can use uh pretty much other tools as well to visualize your HEAP and stack and I
00:30:13.480 fixed up MPR for working with 1.9 I had to yeah next next we'll talk what it
00:30:18.640 took to run MPR on 1.9 uh I totally ripped out trampolines
00:30:23.760 basically because it's like the the binary uh uh when the code that is doing
00:30:29.240 the modifying the Ruby binary in memory it's like it's non Port portable and I
00:30:34.679 did not really understand it TR truth be told so I I just uh removed the trampolines and and I had to patch a
00:30:40.760 ruby a bit to to get the data and another thing is that between 1.8 and
00:30:46.960 1.9 the inter internal data stres have changed significantly like R array or R
00:30:52.840 string they have all changed significantly so I had to modify all of that stuff
00:30:58.480 and there's a new C API to walk the object space which is even based event
00:31:03.840 based uh okay so we're going to talk just demo time for MPR I'm so how you
00:31:11.440 can use MPR to track your
00:31:18.679 leaks Okay so
00:31:32.360 this is same application everybody remembers the Leaky code right all it it did was leak code uh leak memory
00:31:38.840 actually so yeah that's all it does so what you need to do we we require MPR and we
00:31:45.799 require leaky code and then sorry we are loading that library and we are starting MPR you have to start MPR so that those
00:31:53.240 instrumentations that that I had to put in Ruby to collect the data are in place
00:31:58.760 by default no no no uh profiling data is gathered by a member of actually you have to enable it and so that's done by
00:32:06.519 this line and then you start allocating then you collect stats then you do gc.
00:32:12.120 start and see how many objects got freed and then you do member of stats again and then start collecting and then you
00:32:17.519 print the stats again so let's run it uh okay so this is the this is the
00:32:25.320 program I'm going to run it oh sorry I'll have to okay so this is a a modified Ruby
00:32:34.120 it's it's not the standard 1.9.2 which has those instrumentations in place I'm going to use that rather than standard
00:32:40.639 uh Ruby
00:32:47.039 and yeah so it's telling you let's let's go back
00:32:54.639 to code a bit and see what stats does what stats does is uh it tells you the
00:33:02.200 allocations that has happened after start was called and the line number and the file number where the most of the
00:33:09.080 memory was allocated after you call GC the me member of the start so you can see that it's telling you that on line
00:33:15.720 number 10 uh 10 there were 22,000 uh objects created actually string objects
00:33:20.960 basically so if you go to Leaky code. ABB and you can just say yeah so this is
00:33:26.320 where the leak is happening so it can can tell you where the leak is happening exactly and it's in a way much more
00:33:32.080 useful than than other tools then after GC some uh objects
00:33:40.279 collected and then before before GC after GCS we did it bunch of time but you can see that it's there's a leak on
00:33:46.559 line number 10 so this is about using uh stats API
00:33:53.399 then that there's another way to use uh get the that data is using mov track
00:33:59.120 it's again uh what it does is is like it it it's basically a short
00:34:05.200 form of doing m. start and then print the stats it's it's a way to wrap that
00:34:10.639 in a block so that when the block exits uh when the block starts it starts the M stats tracking and then when it exits it
00:34:17.079 prints the stats so if I run this uh it's pretty simple
00:34:24.119 again yeah so you can see that 100 uh mod objects were created on that line
00:34:29.399 number 100 floats were created 100 strings were created line numbers are important as well when you are doing me
00:34:36.040 memory profiling to know where exactly the leak is coming from
00:34:42.599 so yeah and uh I'm not going to show how to do uh like uh memory profiling of a
00:34:49.359 large res application because MPR as it stand for 1.9 is still I'm still haging on it I'm still working on it I hope to
00:34:57.079 release a Jam soon and then I'll see how it works last thing we're going to talk about is m. dump all which basically uh
00:35:05.280 dumps the entire Heap to a Json file and uh and that is what
00:35:18.680 sorry let's get rid of folder object
00:35:37.000 creates some object this object holds references to some other another object and then then stores this in a in a in a
00:35:42.760 class variable if you run this with Ruby sample uses it printed that
00:35:58.240 the Json file is a little big H come
00:36:05.319 on it's not that
00:36:14.640 big
00:36:20.119 wow emx come on
00:36:32.200 yeah okay so I had J JS to mod on Json documents that's why it was taking a
00:36:38.720 while to load uh you can see here if you uh right now it's like pretty raw cannot
00:36:45.040 use it for for for doing the entire for figuring out where exactly the leap uh
00:36:50.160 the leak is but the the web based visualizer fortunately was open sourc uh
00:36:56.040 uh two days back I've been talking to am and uh and and this you can take this Json dump it there and you can get you
00:37:03.160 can make sense start making sense out of it where the objects are where the leak is coming from here you can see I can
00:37:09.960 show you like uh what kind the object ID is and who is holding reference to what object all that is recorded in this Json
00:37:16.960 that can be used and you can pretty much figure out where the leak is coming from
00:37:22.640 uh this work we'll have to wait so that we can use it on a website and you can she see it in a more user friendly
00:37:31.800 fashion future of these changes will be releasing folk version I don't know how it's going to be after Rubicon will be
00:37:37.720 compatible with opsource mov.com and uh last thing uh we are going to
00:37:43.839 talk about is uh gdp. RB which is which
00:37:49.079 using which you can poke uh uh into a life process and see what object it
00:37:54.960 holds right so it's nothing but GDB hooks for 1.8 and
00:38:02.040 some for 1.9 it's written in U uh GDB 17
00:38:07.280 comes with uh you can script GDB using python so it uses that for doing this
00:38:13.040 and then uh thread uh thread inspection for example does not work with 1.9 it works only for 1.8 and it does not work
00:38:20.960 at all on Mac OSX actually so yeah I'm going to demo gdp. RB how to use it and
00:38:28.400 how to poke live processes with
00:38:34.319 it I have to SS to a oh I'm already SS great
00:39:05.240 it we have seen this program make leak what it does it leaks strings that's all it does same as we saw it earlier here
00:39:14.079 so there's nothing new there uh what we are going to do is we are going to connect to this process so we'll have to
00:39:20.839 use rvm pseudo because uh you need pseudo access to connect to a live
00:39:26.000 process and I'm I'm using rvm so I have to do this and then yeah I'm connected to this process now I have bunch of uh
00:39:33.839 commands here that I can execute and see how many objects and what objects are there Ruby objects yeah it's telling us
00:39:42.400 there are 47,000 strings and complex struct blah blah blah you can see
00:39:54.560 uh how many class objects are there Bunch sorry how many uh the objects by
00:40:00.440 class then uh then you can see uh like nodes I
00:40:07.880 think so yeah and uh if you're using R Ruby 1.8 it you it can also show uh back
00:40:15.839 trace of uh uh each thread that's that's live and you can do all that but with
00:40:21.040 1.9 that's that's not possible so that's pretty much about
00:40:27.839 it and uh yeah we have done that and yeah before I wrap up uh if you are
00:40:35.680 using rubinus rubinus has pretty much pretty excellent CPU and profile uh CPU
00:40:41.280 and memory profiling API the CPU profiling is excellent memory profiling again it uses client server architecture
00:40:46.760 so that you can connect to processes and get the data it's beautiful with J Ruby you can use the your Java visualizer I
00:40:53.880 didn't had great great success with it but I'm not talking about that them because I wouldn't do justice to them
00:40:59.640 they take their own time to do proper research and and report so I encourage you to check out rubinus profiling API
00:41:06.920 these are the resources the one that I want to point out is like if you are writing a profiler is this one this hepp
00:41:13.280 profiler which basically is a it's a python profiler it talks about how to go about doing a client architecture or or
00:41:19.920 how to ensure that profile data does not poison the the the application that
00:41:26.800 you're profiling in and uh there's another uh memory
00:41:32.119 profile which was presented last year which Ki provided me a link for it and and and it's
00:41:38.240 here and that's it thank you
Hemant Kumar
@gnufied
Explore all talks recorded at RubyConf 2011
+55