Logging Java Garbage Collection
If you are working on a medium to large Java project then one of the aspects of application performance you’re probably (should be!) monitoring is garbage collection.
I am working on a custom made multi-threaded server application running usually 6000 child threads, serving 3000 connected users, simultaneously getting server responses (like a topic). After releasing a new build with some new functionality allowing more users to interact, we got complaints from our users that sometimes they get delay in responses. Usually these delays sometimes take up to 15-16 seconds. And this was only happening at very high peak load time. I browsed the logs and found out the application (server) was paused for 15-16 seconds, the whole world on one server with 3000 users was paused. Check the memory logs and find out this is our old pal Garbage collector freezing the server.
Before taking any further steps (tunning garbage collector) the first step is to turn on the Java garbage collector logging. This helps us in many ways like
- Java heap size
- Young Vs Tenured Generations
- GC pause times
- Memory freed
- Memory usuage
- GC behavior etc etc
To turn on Logging for Java garbage collection, use
1 | –verbose:gc –Xloggc:filename |
along with your JVM arguments.
Usually on a server class machine you would like to use
1 | java -server -Xms2g -Xmx2g -Xmn512m -verbose:gc -Xloggc:gc.log |
but there are many other usefull options too like
1 | java -server -Xms2g -Xmx2g -Xmn512m -verbose:path -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -Xloggc:gc.log |
1 | Below is a sample of the out put, you will get. |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 | Total time for which application threads were stopped: 0.0003530 seconds 137.487: [GC [PSYoungGen: 393216K->15181K(458752K)] 393216K->15181K(2031616K), 0.0405356 secs] Total time for which application threads were stopped: 0.0414858 seconds Total time for which application threads were stopped: 0.0002701 seconds Total time for which application threads were stopped: 0.0002514 seconds Total time for which application threads were stopped: 0.0003790 seconds Total time for which application threads were stopped: 0.0008238 seconds Total time for which application threads were stopped: 0.0002532 seconds Total time for which application threads were stopped: 0.0002798 seconds Total time for which application threads were stopped: 0.0003979 seconds Total time for which application threads were stopped: 0.0012853 seconds Total time for which application threads were stopped: 0.0002747 seconds Total time for which application threads were stopped: 0.0002880 seconds Total time for which application threads were stopped: 0.0004205 seconds Total time for which application threads were stopped: 0.0014724 seconds Total time for which application threads were stopped: 0.0003462 seconds Total time for which application threads were stopped: 0.0002705 seconds Total time for which application threads were stopped: 0.0003936 seconds Total time for which application threads were stopped: 0.0016568 seconds Total time for which application threads were stopped: 0.0002672 seconds Total time for which application threads were stopped: 0.0003065 seconds Total time for which application threads were stopped: 0.0004013 seconds Total time for which application threads were stopped: 0.0016449 seconds Total time for which application threads were stopped: 0.0002005 seconds Total time for which application threads were stopped: 0.0002170 seconds Total time for which application threads were stopped: 0.0005666 seconds Total time for which application threads were stopped: 0.0004817 seconds Total time for which application threads were stopped: 0.0006606 seconds Total time for which application threads were stopped: 0.0018527 seconds Total time for which application threads were stopped: 0.0003502 seconds Total time for which application threads were stopped: 0.0004479 seconds 358.392: [GC [PSYoungGen: 408397K->33277K(458752K)] 408397K->33277K(2031616K), 0.0696625 secs] Total time for which application threads were stopped: 0.0705119 seconds Total time for which application threads were stopped: 0.0004636 seconds |
In the next post, I will let you know how to efficiently read these logs and what they mean.
