Java Tutorial - JVM verbose GC analysis

hello everyone my name is pH Charbonneau I'm a senior IT consultant and also the author on Java I support patterns at blogspot.com so today's video will be about Java verbal GC tutorial this will be basically a presentation on how you can enable verbal GC from your Eclipse ID and also I'll be focusing on how you can perform the analysis what keep in mind this tutorial is not intended to provide you with a deep dive on the Java heap and everything but I'll still be covering some of the basics future tutorial will include also a deeper analysis techniques like keep Dom analysis as well so welcome to this tutorial I hope you will appreciate the quality now let's start with a quick overview what is verbal GC and why is it useful well did their verbal GC from our perspective it's very crucial and it's one in case you saw a pass article from my blog this is one of the things basically that Java developers should know so not only support individual will also Java developers because verbo GC basically provides you with out-of-the-box detail on your java heat me memory footprint so basically lower level of detail on each of your memory space when a Java heap that is dumped to the actual log it also provided detail on a gel garbage collection process so you can basically read the logs and determine the frequency of the garbage collection the interval especially regarding the major collection which can be quite intrusive for your app application and can degrade the performance quite significantly so now let's move on to the simple program using the Eclipse ID so here the snapshot of the screen for a simple java program well in order to understand the java verb OGC i always recommend to learn this process using a very simple java program instead of jumping right away to very complex Java EE program with the Gigabyte the memory footprint it's always easier to understand via a simple example that you can write yourself run quickly and then learn these techniques via this program before you jump into more complex tasks right so what you see here is a very simple program that I created which I call JVM I'll remember simulator basically what this program does is quite straightforward it's basically just trying to initialize and populate what I call a leaking hash map with string data ultimately triggering an ottoman tree condition so as you know when you allocate object like this in a hash map these object will accumulate in the Java heap and eventually depending on your capacity you will run out of memory so that that's what basically this problem is trying to simulate here so let me show you has a starting point the argument so in Eclipse IDE you can basically just inspect write in your arguments of your program as you can see I did configure the program with a hex MX of 1 gigabyte meaning that the Java heap total capacity is up to one gig line in order to enable verbal GC verbally it's very simple if you just need basically to add - verbal GC parameter and then you have some extra parameters you can enable as well those are optional but I highly recommend that you do that basically to add some additional detail the time stamp on top of it and more importantly to redirect the output to a separate log otherwise if you don't do that verbal GC output will be redirected to the standard output which is not to user french friendly there in turn my GRE as you can see I'm using GDK 1.7 which and I'm using the hotspot JVM on Windows OS so this is basically my specification future videos and article I'll be showing you some example on Linux OS or UNIX based OS as well but for the verbal GC analysis it doesn't really matter if you're enabling that on windows OS linux AIX and others the dat verbal GC is basically unique or cross-platform so back to our program let me run one iteration so I'm going to run the program right now so this is the output that you see here and my expectation is you can see given the number of iteration my expectation is that I'll be generating an all-american dition so you can see promisee running and it there go you see you have a heap space out of memory ever drive a heap space simulator is done so this is what one end to generate because when you enable verbal GC it'll probably do some statistic on your Java heap but it's it's definitely more interesting if you see my a lemon on top of it because we will be able to analyze the garbage collection process so i am i read about heat space for people and from here with this basically just mean you're running out of Java heap and by Java heap it means basically if you're using the default concurrent collector it means both your young gent space and old gen space is depleted right a quick a quick refresher on the JVM right you're on the JVM you have the Java yung-jan all giant space you have also the perm gen States used for the class metadata and obviously you have the native heap some memory allocated for the threads from the internal JVM native computing times now in order our program fail other memory error our footprint or capacity was up to a gig so obviously this program attempted to allocate more than one gig of memory and ran out of memory with Joe a space as I just explained now let's go back to the original meeting and understand now the verbal GC now let's go back to our program what I did is a quick addition of XM s to 1k just to simplify the analysis or bold you see what it means is that I'm allowing still one gig of memory but the minimum is also set to one gig so you'll be able to see that footprint allocation a little bit easier there so lets me open the verb of GC okay so that's basically the output for a hotspot 1.7 VM as as you remember we enable the time step in the first column so you have the time stamp basically in second at the time you start GBM and then you can see the incremental value in seconds right so this were you able to see the elapsed time in between your interval the garbage collection especially for you're dealing with excessive garbage collection you will see a for example a lot of major collection you will be able to see that from the row GC lot DLE you should not have too many major collection because these are more intrusive to the GBM from a past time perspective cpu and so on in the verbal you see will always be you basically will see a split of minor collection which are identify as capital GC right a major collection which are identify as full GC you should see much more frequency of minor collection ET le right because minor collection if you remember the jvm as I explained the money collection stand more for the young gent space so the yeah the short clip object your program is created or initially allocated right in the young gent space and if these objects survives collection then they will get promoted to the old gent space which is why we call it short of object basically if you create local variables or temporary data structure these object will get cleared out by a JVM very quickly via the minor collection minor collection are much faster to clean up because typically the footprint is smaller right the Java heap space for the young is always typically smaller than the old gent space so if we're back to a program at a time zero to two when we just fired the program we can see a few minor collection which happen remember our program was very quickly allocating a lot of memory right so which is why you see some allocation happening on the young gen right and eventually you'll see some some major collection happening here so let's see how this whole thing is working so when you look at these line yet always to read from left to right so what it means is this on the left side of the arrow it means this this was the memory footprint for the young gent space before the collection meaning at that time right before them on a collection you had about 260 to 262 out of memory allocated in the young gent space after the minor collection now that footprint got reduced to 43 Meg's which is good news meaning you're that GM was able to clean up some of the memory and a total capacity is Treon hundred Meg's why is it 300 makes for the young-jun well that keep in mind that's a typical ratio okay when you don't specify anything and tuning on downside the JVM will automatically break down your Java heap capacity into silos young-shin and all jam with typically a 130 percent rate ratio right so for example in our case with a 1 gig if you remember right with a 1 gig of heap footprint the Java heap or the JVM created a young gent space of about 305 mix the rest of the memory around 700 megabyte was allocated for the old gen space or if or if you prefer you along the object so this is totally expected behavior so that's the first portion of the miner collection the second portion will give you a total heat footprint that's the total combined young and old gen right and again I'm not even talking about the permission at this point I did not as you remember from the Woody not specify anything so we're using the default perm generators this is not really in scope for this topic permission is more the class metadata we're not simulating any problem here at the perm general so no need to worry about this one for now so what it's telling us at this point with the model collection is that well footprint was 262 and then you're you're back to 144 after so 43 for the young Channel and 144 total meaning we already have some more allocated to the origin as we can see here right and then this is giving you the elapsed time for the mana collection as you can see the molecular sheen or extremely fast zero that 0.4 second and then you have the user time as well system in real user time in second here now let's look because remember I'll program the generator and recondition so we're expecting a lot of my major collection at some point right this is exactly what's happening look at this full GC full GC full GC totally expected like almost every half second for GC over and over and over which is normal since this is what we're trying to demonstrate with this program so what it means that very quickly because our program shred was still working in progress very quickly that memory was still retain by that trend so that memory footprint got or these object were promoted very quickly to the old gen space which is why you will see a lot of major collection and I will be able to see the origin as you can see the minor collection will not give you footprint of the old gen right this is more focus on the young gem but the major collection will take care of the old gen space not the minor collection which is why the minor collection is more efficient right the money collection as I just explained by design it has a smaller footprint right 30% of your total capacity by default so by default it's much faster to clean up right the old gen is always your biggest java heat space so obviously it's always - or to clean up the old gen is not cleaned up with the mana collection that's the whole purpose of splitting a memory space right because you don't want to Joanne to spend too much time going against all the audience space for nothing right the major collection will take care of both of the entire JVM which is why when you do your analysis from a footprint perspective let's you want to detect memory leak the more we leak by their nature will be leaking in the old gen space along with objects let's see a - man which acumulate memory over time every hour you also growing patterns from your old gents pace so in order to do that analysis the best way is always to analyze your footprint after a major collection so let's see an example of this - this one so at time 3.9 second we had a major collection same pattern here first let's start with a young gen that was the memory footprint before the major collection - 62 after we're down to 266 so pretty much when we want unable to clean up much here Oh gem what we care about this is where it's get interesting as you can see the old gem capacity is 700 mix as I just explained now the troubling part is this before the major collection we were about seven hundred Meg's which makes sense right because UVM always at some point grew up to its Mac capacity before a major collection the troubling part is this after the major collection were still around seven hundred Meg's so very very very close to depletion which is normal as the extremes because that's all Primus trying to demonstrate so that's what you may see let's see if you're supporting a production environment or you're facing issue at your application this is what you have to understand look at your old gen make sure you see how much memory was cleaned up after right before after if the after is going down just to about a few person it means you are really struggling right JVM is struggling is not cleaning up much this and what's the side effect well problem is that GM is unable to clean up much so it has to fire again the full GC again and again and again you see that here it's all the same pattern you see the old gen after it's always always close to max right and at some point as you saw from the Eclipse we run out of memory completely okay so that's the old gent space now for the major collection you'll also get the detail on your perm Jones base I said this is a total heat that you see so young gen Energon the perm gen is here again you get the elapsed time as you can see much more choosy right for the major collection minor collection where the beginning 0.05 extremely fast and then the major collection or taking in mind women about half a second so it's not that big a deal but the real problem is is a complete depletion right so you can see it's it's fairly straightforward right once you understand the pattern of analysis before after capacity once you understand that the short a blip short live object and long live object or split between these two the prime gen again is separate space as you probably heard soon to be the Commission with probably Java 8 so don't worry about this one for now it's quite straightforward so that's a bottom line it allows you to track down major collection most important and the frequency of such major collection so you can correlate with slowdown condition of your application now let's close this video with an explanation of this one the good thing also the verbal do you see it provide you full breakdown it's in a more friendly manner right similar like like we just I giving you a quick view also of the of the heap right at that point when it was basically close to the mirror condition we can see the young Jen was at 99% that was just before the other memory right 99% of young Chan all Jen 99% used and the perm gem which as I said we don't care too much because we ran out of Java heat nut porridge in space when we're running out of perm gents pay the separate error that GM is is throwing not in this case so as you can see problem is confirmed Java EE depletion plus we confirm that by looking at each of the individual line so I hope you did appreciate that tutorial on verbal GC as you can see don't get any fancy tool or anything there are some very good monitoring tool out there either commercial or line G visual VM which can visualize that with nice graph and everything so I always recommend that you use these tool but I also highly recommend that you learn how to analyze the raw data because there are sons and I use that you will need that because the verbal GC the real benefit is that it's persisting the data to a log so if you don't have any monitoring tool that your client is using I highly recommend that you turn on verbal GC for your production environment it's not intrusive it doesn't cause any impact performance plus will give you a story called data from a Java heap footprint perspective and garbage collection to figure out the root cause of your production or your development problems so thank you for your attention on the video and you can expect other video pretty soon again thanks for visiting my blog and also watching this video have a good day

Channel: Pierre-Hugues Charbonneau

Views: 19,877

Keywords: Java (programming Language), JVM, Eclipse, Java Tutorial, Hosting, Software, Technology, Computer, Tutorial, Web Application Monitoring, Network Monitoring, Java Monitoring

Id: 7CJCMKNoICE

Length: 20min 48sec (1248 seconds)

Published: Fri Jan 11 2013