Java Memory Leaks

From MineOS
Jump to: navigation, search

Detecting and diagnosing Java memory leaks is not a particularly straightforward task. There are many factors that can lead to Java OutOfMemoryErrors, and there are even more causes for that error that are not memory leaks. This page is to help provide instructions for the first line of defense, Garbage Collection (GC) logging. While there are a number of ways to detect leaks, many approaches such as employing Java profilers and visualizers are far beyond the scope of this wiki page.

It is it important to note, though, that all the tutorials and guides you might see for profiling memory on Linux are still pertinent--remember, MineOS Turnkey is simply Debian--and therefore any other approach you are familiar and comfortable with is perfectly valid.

I recommend this good read: an official Oracle tutorial on GC tuning.

Contents

GC Logging

Garbage collection logging can be enabled at the command-line, when starting the Minecraft servers. These arguments are passed to Java, rather than the jar itself, and therefore should come before the -jar flag. You have a few ways to implement any desired Java flags.

java_tweaks

java_tweaks is a MineOS convention that inserts your own custom java tweaks into the Java startup command (in mineos.py as command_start), after the memory flags:

root@core games/minecraft# ./mineos_console.py -s a command_start
'/usr/bin/screen -dmS mc-a /usr/bin/java -server  
-Xmx256M -Xms256M <JAVA_TWEAKS_GO_HERE> -jar /var/games/minecraft/servers/a/minecraft_server.1.7.4.jar '

java_debug

If you update your MineOS scripts, a number of pre-determined GC logging features can be enabled more easily. Using them, the startup command is automatically updated like this:

root@core games/minecraft# ./mineos_console.py -s a command_start
'/usr/bin/screen -dmS mc-a /usr/bin/java -server 
-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/var/games/minecraft/servers/a/java_gc.log 
-Xmx256M -Xms256M  -jar /var/games/minecraft/servers/a/minecraft_server.1.7.4.jar '

These commands will output verbose logging to a file /var/games/minecraft/servers/a/java_gc.log. To enable GC logging via the web-ui, go to your server.config file in the web-ui. Create a new attribute, with the section java, property name java_debug, and value true, on, or 1. Upon the next starting up of the server, you can start diagnosing your Java memory!

Looking at the GC logs

This section is a work-in-progress and will be filled out more to help understand GC logging output:

xms == xmx

6.477: [GC 6.477: [DefNew: 69952K->8704K(78656K), 0.0221260 secs] 69952K->12940K(253440K), 0.0221690 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
9.033: [GC 9.033: [DefNew: 78656K->8259K(78656K), 0.0226230 secs] 82892K->18887K(253440K), 0.0226740 secs] [Times: user=0.02 sys=0.01, real=0.02 secs]
10.398: [GC 10.398: [DefNew: 78211K->8704K(78656K), 0.0205370 secs] 88839K->26999K(253440K), 0.0205810 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
11.581: [GC 11.581: [DefNew: 78656K->8704K(78656K), 0.0218930 secs] 96951K->35745K(253440K), 0.0219470 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
13.099: [GC 13.099: [DefNew: 78656K->8401K(78656K), 0.0200320 secs] 105697K->44004K(253440K), 0.0200900 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
14.313: [GC 14.313: [DefNew: 78353K->8704K(78656K), 0.0238270 secs] 113956K->53604K(253440K), 0.0238710 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
15.430: [GC 15.430: [DefNew: 78656K->8703K(78656K), 0.0186190 secs] 123556K->62670K(253440K), 0.0186690 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
16.413: [GC 16.413: [DefNew: 78655K->8704K(78656K), 0.0343260 secs] 132622K->70764K(253440K), 0.0343850 secs] [Times: user=0.02 sys=0.00, real=0.03 secs]
48.099: [GC 48.099: [DefNew: 78656K->1194K(78656K), 0.0120090 secs] 140716K->69153K(253440K), 0.0120600 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
78.007: [GC 78.007: [DefNew: 71146K->1321K(78656K), 0.0037680 secs] 139105K->69280K(253440K), 0.0038090 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
556.817: [GC 556.817: [DefNew: 71273K->2192K(78656K), 0.0054430 secs] 139232K->70151K(253440K), 0.0054850 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
1020.758: [GC 1020.758: [DefNew: 72144K->1199K(78656K), 0.0032820 secs] 140103K->69158K(253440K), 0.0033240 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Heap
 def new generation   total 78656K, used 28668K [0x79750000, 0x7eca0000, 0x7eca0000)
  eden space 69952K,  39% used [0x79750000, 0x7b2231e8, 0x7dba0000)
  from space 8704K,  13% used [0x7dba0000, 0x7dccbfa8, 0x7e420000)
  to   space 8704K,   0% used [0x7e420000, 0x7e420000, 0x7eca0000)
 tenured generation   total 174784K, used 67958K [0x7eca0000, 0x89750000, 0x89750000)
   the space 174784K,  38% used [0x7eca0000, 0x82efdaa8, 0x82efdc00, 0x89750000)
 compacting perm gen  total 16384K, used 9944K [0x89750000, 0x8a750000, 0x91750000)
   the space 16384K,  60% used [0x89750000, 0x8a1060c0, 0x8a106200, 0x8a750000)
    ro space 10240K,  60% used [0x91750000, 0x91d5c958, 0x91d5ca00, 0x92150000)
    rw space 12288K,  63% used [0x92150000, 0x928f4db0, 0x928f4e00, 0x92d50000)

xms < xmx

3.097: [GC 3.097: [DefNew: 34944K->4352K(39296K), 0.0176670 secs] 34944K->5625K(126720K), 0.0177090 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
4.699: [GC 4.699: [DefNew: 39296K->4352K(39296K), 0.0163840 secs] 40569K->10752K(126720K), 0.0164680 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
6.491: [GC 6.491: [DefNew: 39296K->4352K(39296K), 0.0111080 secs] 45696K->14384K(126720K), 0.0111560 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
7.567: [GC 7.567: [DefNew: 39296K->4352K(39296K), 0.0088370 secs] 49328K->18908K(126720K), 0.0088800 secs] [Times: user=0.00 sys=0.00, real=0.02 secs]
8.261: [GC 8.261: [DefNew: 39296K->4352K(39296K), 0.0094500 secs] 53852K->23806K(126720K), 0.0094930 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
8.935: [GC 8.935: [DefNew: 39296K->4352K(39296K), 0.0080400 secs] 58750K->27715K(126720K), 0.0080830 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
9.417: [GC 9.417: [DefNew: 39115K->4352K(39296K), 0.0093750 secs] 62479K->32450K(126720K), 0.0094160 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
9.925: [GC 9.925: [DefNew: 39296K->4351K(39296K), 0.0100230 secs] 67394K->36673K(126720K), 0.0100660 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
10.510: [GC 10.510: [DefNew: 39238K->4352K(39296K), 0.0075800 secs] 71559K->40578K(126720K), 0.0076350 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
11.054: [GC 11.054: [DefNew: 39296K->4352K(39296K), 0.0098840 secs] 75522K->44777K(126720K), 0.0099350 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
11.526: [GC 11.526: [DefNew: 39280K->4352K(39296K), 0.0118080 secs] 79706K->49446K(126720K), 0.0118510 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
12.121: [GC 12.121: [DefNew: 39296K->4351K(39296K), 0.0098320 secs] 84390K->53054K(126720K), 0.0098750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
12.618: [GC 12.618: [DefNew: 39295K->4352K(39296K), 0.0094510 secs] 87998K->57070K(126720K), 0.0095260 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
13.105: [GC 13.105: [DefNew: 39296K->4351K(39296K), 0.0098200 secs] 92014K->61017K(126720K), 0.0098680 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
13.662: [GC 13.662: [DefNew: 39126K->4352K(39296K), 0.0098270 secs] 95791K->65376K(126720K), 0.0098720 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
14.379: [GC 14.379: [DefNew: 39296K->4233K(39296K), 0.0091510 secs] 100320K->69467K(126720K), 0.0091960 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
21.400: [GC 21.400: [DefNew: 39177K->3276K(39296K), 0.0136820 secs] 104411K->72423K(126720K), 0.0137380 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
40.264: [GC 40.264: [DefNew: 38220K->420K(39296K), 0.0056630 secs] 107367K->71625K(126720K), 0.0057060 secs] [Times: user=0.00 sys=0.01, real=0.00 secs]
59.743: [GC 59.743: [DefNew: 35364K->3148K(39296K), 0.0078840 secs] 106569K->74354K(126720K), 0.0079410 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
69.796: [GC 69.797: [DefNew: 38092K->64K(39296K), 0.0022700 secs] 109298K->71593K(126720K), 0.0023000 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
240.669: [GC 240.669: [DefNew: 35008K->285K(39296K), 0.0019250 secs] 106537K->71814K(126720K), 0.0019530 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
465.782: [GC 465.782: [DefNew: 35229K->168K(39296K), 0.0013880 secs] 106758K->71698K(126720K), 0.0014190 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
693.205: [GC 693.205: [DefNew: 35112K->107K(39296K), 0.0014850 secs] 106642K->71636K(126720K), 0.0015130 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
919.467: [GC 919.467: [DefNew: 35051K->107K(39296K), 0.0015240 secs] 106580K->71636K(126720K), 0.0015500 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 39296K, used 15674K [0x79750000, 0x7c1f0000, 0x7eca0000)
  eden space 34944K,  44% used [0x79750000, 0x7a683c80, 0x7b970000)
  from space 4352K,   2% used [0x7b970000, 0x7b98ac98, 0x7bdb0000)
  to   space 4352K,   0% used [0x7bdb0000, 0x7bdb0000, 0x7c1f0000)
 tenured generation   total 87424K, used 71529K [0x7eca0000, 0x84200000, 0x89750000)
   the space 87424K,  81% used [0x7eca0000, 0x8327a528, 0x8327a600, 0x84200000)
 compacting perm gen  total 16384K, used 10012K [0x89750000, 0x8a750000, 0x91750000)
   the space 16384K,  61% used [0x89750000, 0x8a117260, 0x8a117400, 0x8a750000)
    ro space 10240K,  60% used [0x91750000, 0x91d5c958, 0x91d5ca00, 0x92150000)
    rw space 12288K,  63% used [0x92150000, 0x928f4db0, 0x928f4e00, 0x92d50000)