Garbage collector

Introduction

Garbage Collector is a process that identifies and deletes objects no longer in use from the JVM Heap memory.
Garbage Collector also frees up space after removing unreferenced objects.

Indexima allows you to log your 'garbage collections' so you can easily see which files and how much space garbage collector has cleared.

1 - First, stop your Indexima cluster with the command stop.sh

Run this command multiple times until you receive the message Unable to connect...

2 - Edit the file conf/galactica-env.sh and add the following lines :

conf/galactica-env.sh

BASH

#set GC_VERBOSE to ON to have gc logs
GC_VERBOSE=OFF
GC_OPTIONS="-XX:+UseConcMarkSweepGC"


if [ "${GC_VERBOSE}" == "ON" ] ; then
        LOG_DIR=`grep "^log.dir" ./conf/galactica.conf 2>/dev/null | cut -d"=" -f2 | sed 's/ //g'`
        if [ -z "${LOG_DIR}"  ]; then
                LOG_DIR="."
        fi

        echo "Using directory (${LOG_DIR}) for gc log"
        GC_OPTIONS="${GC_OPTIONS} -Xloggc:${LOG_DIR}/jvm_gc.%p.%t.log -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M"
fi

3 - Make sure also to add`${GC_OPTIONS}` argument in the start-node.sh, start_yarn.sh or start_node.bat scripts such as:

${GC_OPTIONS}

BASH

$JAVA_HOME/bin/java -Xms$GALACTICA_MEM -Xmx$GALACTICA_MEM -Xss512k ${GC_OPTIONS} $JMX_OPTIONS -cp $ORDER_LIBS:lib/*:conf:web:$GALACTICA_LIB:$HADOOP_JARS io.galactica.server.NodeServer $@

4 - Turn the Garbage Collector On or Off with the option GC_VERBOSE.

5 - By default, GC log files are written in the INDEXIMA log directory. This directory is defined in the conf/galactica.conf configuration file.

6 - Snippet of a GC log file :

GC log file

BASH

cat jvm_gc.pid661.18-21-21.log.0.current
Java HotSpot(TM) 64-Bit Server VM (25.121-b13) for linux-amd64 JRE (1.8.0_121-b13), built on Dec 12 2016 16:36:53 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 3863568k(3447428k free), swap 4079612k(3849980k free)
CommandLine flags: -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=4194304000 -XX:MaxHeapSize=4194304000 -XX:MaxNewSize=348966912 -XX:MaxTenuringThreshold=6 -XX:NewSize=348966912 -XX:NumberOfGCLogFiles=10 -XX:OldPLABSize=16 -XX:OldSize=697933824 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ThreadStackSize=512 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation -XX:+UseParNewGC

18:21:23.285+0000: 2.221: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(3755264K)] 256616K(4061952K), 0.0458122 secs] [Times: user=0.04 sys=0.01, real=0.05 secs]
18:21:23.331+0000: 2.267: [CMS-concurrent-mark-start]
18:21:23.377+0000: 2.313: [CMS-concurrent-mark: 0.046/0.046 secs] [Times: user=0.07 sys=0.03, real=0.04 secs]
18:21:23.378+0000: 2.314: [CMS-concurrent-preclean-start]
18:21:23.384+0000: 2.320: [CMS-concurrent-preclean: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
18:21:23.384+0000: 2.320: [CMS-concurrent-abortable-preclean-start]
18:21:23.646+0000: 2.582: [GC (Allocation Failure) 2018-10-17T18:21:23.646+0000: 2.582: [ParNew: 272640K->21738K(306688K), 0.0264161 secs] 272640K->21738K(4061952K), 0.0265128 secs] [Times: user=0.06 sys=0.01, real=0.03 secs]
18:21:25.195+0000: 4.131: [CMS-concurrent-abortable-preclean: 1.063/1.811 secs] [Times: user=4.16 sys=0.47, real=1.81 secs]
18:21:25.196+0000: 4.131: [GC (CMS Final Remark) [YG occupancy: 192111 K (306688 K)]18:21:25.196+0000: 4.131: [Rescan (parallel) , 0.0158156 secs]18:21:25.212+0000: 4.147: [weak refs processing, 0.0000197 secs]18:21:25.212+0000: 4.147: [class unloading, 0.0044254 secs]18:21:25.216+0000: 4.152: [scrub symbol table, 0.0040644 secs]18:21:25.220+0000: 4.156: [scrub string table, 0.0004283 secs][1 CMS-remark: 0K(3755264K)] 192111K(4061952K), 0.0255949 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]

18:21:25.222+0000: 4.158: [CMS-concurrent-sweep-start]
18:21:25.222+0000: 4.158: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
18:21:25.222+0000: 4.158: [CMS-concurrent-reset-start]
18:21:25.559+0000: 4.495: [CMS-concurrent-reset: 0.336/0.337 secs] [Times: user=0.35 sys=0.37, real=0.34 secs]
18:21:26.845+0000: 5.781: [GC (Allocation Failure) 18:21:26.845+0000: 5.781: [ParNew: 294378K->19926K(306688K), 0.0701429 secs] 294378K->29589K(4061952K), 0.0702231 secs] [Times: user=0.14 sys=0.05, real=0.07 secs]
18:21:28.250+0000: 7.186: [GC (Allocation Failure) 18:21:28.250+0000: 7.186: [ParNew: 292566K->34048K(306688K), 0.0494936 secs] 302229K->95118K(4061952K), 0.0495713 secs] [Times: user=0.12 sys=0.04, real=0.05 secs]

18:23:17.885+0000: 116.820: [GC (GCLocker Initiated GC) 18:23:17.885+0000: 116.820: [ParNew: 15011K->12221K(306688K), 0.0147037 secs] 997295K->994505K(4061952K), 0.0147992 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
18:23:19.286+0000: 118.222: [GC (Allocation Failure) 18:23:19.286+0000: 118.222: [ParNew: 284861K->11147K(306688K), 0.0150668 secs] 1267145K->993431K(4061952K), 0.0151769 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

18:25:01.564+0000: 220.500: [CMS-concurrent-abortable-preclean: 0.201/0.301 secs] [Times: user=0.88 sys=0.00, real=0.30 secs]
18:25:01.566+0000: 220.502: [GC (CMS Final Remark) [YG occupancy: 199910 K (306688 K)]18:25:01.567+0000: 220.502: [Rescan (parallel) , 0.0320234 secs]18:25:01.599+0000: 220.534: [weak refs processing, 0.0017425 secs]18:25:01.600+0000: 220.536: [class unloading, 0.7077892 secs]18:25:02.319+0000: 221.254: [scrub symbol table, 0.1399324 secs]18:25:02.459+0000: 221.394: [scrub string table, 0.0006582 secs][1 CMS-remark: 3505891K(3755264K)] 3705801K(4061952K), 0.9063105 secs] [Times: user=0.26 sys=0.14, real=0.91 secs]
18:25:02.478+0000: 221.414: [CMS-concurrent-sweep-start]
18:25:02.650+0000: 221.585: [GC (Allocation Failure) 18:25:02.650+0000: 221.586: [ParNew: 279170K->7227K(306688K), 0.2336017 secs] 3583714K->3312515K(4061952K), 0.2342538 secs] [Times: user=0.61 sys=0.00, real=0.23 secs]

18:25:04.550+0000: 223.485: [CMS-concurrent-sweep: 1.431/2.072 secs] [Times: user=4.70 sys=0.34, real=2.08 secs]
18:25:04.550+0000: 223.486: [CMS-concurrent-reset-start]
18:25:04.581+0000: 223.517: [CMS-concurrent-reset: 0.031/0.031 secs] [Times: user=0.06 sys=0.02, real=0.03 secs]
18:25:04.938+0000: 223.874: [GC (Allocation Failure) 18:25:04.938+0000: 223.874: [ParNew: 279517K->8765K(306688K), 0.0948165 secs] 1061185K->791039K(4061952K), 0.0949692 secs] [Times: user=0.34 sys=0.00, real=0.10 secs]
18:25:05.256+0000: 224.191: [GC (Allocation Failure) 18:25:05.256+0000: 224.191: [ParNew: 281405K->4278K(306688K), 0.0846136 secs] 1063679K->789546K(4061952K), 0.0847287 secs] [Times: user=0.31 sys=0.00, real=0.09 secs]

Garbage Collector Traps

When there is insufficient memory for the Java Runtime Environment to continue, the Linux OS displays an out of memory error message. A GC trap log file is then written in the galactica directory which contains information you can use to troubleshoot the memory issue.

Snippet of a trap log file :

Garbage collector traps

BASH

cat hs_err_pid552.log
#  Out of Memory Error (os_linux.cpp:2627), pid=552, tid=0x00007f42a0082700
#
# JRE version:  (8.0_121-b13) (build )
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode linux-amd64 compressed oops)
# Core dump written. Default location: /indexima/galactica/core or core.552
#
---------------  T H R E A D  ---------------
Current thread (0x00007f429800d800):  JavaThread "Unknown thread" [_thread_in_vm, id=553, stack(0x00007f42a0003000,0x00007f42a0083000)]
Stack: [0x00007f42a0003000,0x00007f42a0083000],  sp=0x00007f42a0081330,  free space=504k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xac703a]  VMError::report_and_die()+0x2ba
V  [libjvm.so+0x4fc7eb]  report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
...
V  [libjvm.so+0x5fbaf2]  GenerationSpec::init(ReservedSpace, int, GenRemSet*)+0xf2
V  [libjvm.so+0x5ea92e]  GenCollectedHeap::initialize()+0x1de
V  [libjvm.so+0xa8eff3]  Universe::initialize_heap()+0xf3
V  [libjvm.so+0xa8f55e]  universe_init()+0x3e
V  [libjvm.so+0x63d4f5]  init_globals()+0x65
V  [libjvm.so+0xa72c4e]  Threads::create_vm(JavaVMInitArgs*, bool*)+0x23e
V  [libjvm.so+0x6d1d94]  JNI_CreateJavaVM+0x74
C  [libjli.so+0x745e]  JavaMain+0x9e
C  [libpthread.so.0+0x7e25]  start_thread+0xc5

---------------  P R O C E S S  ---------------
Java Threads: ( => current thread )
Other Threads:
=>0x00007f429800d800 (exited) JavaThread "Unknown thread" [_thread_in_vm, id=553, stack(0x00007f42a0003000,0x00007f42a0083000)]
VM state:not at safepoint (not fully initialized)
VM Mutex/Monitor currently owned by a thread: None
Dynamic libraries:
00400000-00401000 r-xp 00000000 fd:01 137545428                          /usr/java/jre1.8.0_121/bin/java
00600000-00601000 rw-p 00000000 fd:01 137545428                          /usr/java/jre1.8.0_121/bin/java
021e6000-02207000 rw-p 00000000 00:00 0                                  [heap]
6c6000000-6dacc0000 rw-p 00000000 00:00 0
7f4274000000-7f4274021000 rw-p 00000000 00:00 0
7f4274021000-7f4278000000 ---p 00000000 00:00 0
...
/usr/java/jre1.8.0_121/lib/amd64/libjava.so
7f429db5c000-7f429dd5b000 ---p 0002b000 fd:01 10990690                   /usr/java/jre1.8.0_121/lib/amd64/libjava.so
7f429dd5b000-7f429dd5d000 rw-p 0002a000 fd:01 10990690                   
Launcher Type: SUN_STANDARD

Environment Variables:
JAVA_HOME=/usr/java/jre1.8.0_121
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/hadoop-2.8.3/bin:/hadoop-2.8.3/sbin

Signal Handlers:
SIGSEGV: [libjvm.so+0xac78c0], sa_mask[0]=11111111011111111101111111111110, sa_flags=SA_RESTART|SA_SIGINFO
SIGBUS: [libjvm.so+0xac78c0], sa_mask[0]=11111111011111111101111111111110, sa_flags=SA_RESTART|SA_SIGINFO
SIGFPE: [libjvm.so+0x920ac0], sa_mask[0]=11111111011111111101111111111110, sa_flags=SA_RESTART|SA_SIGINFO
SIGPIPE: [libjvm.so+0x920ac0], sa_mask[0]=11111111011111111101111111111110, sa_flags=SA_RESTART|SA_SIGINFO
SIGXFSZ: [libjvm.so+0x920ac0], sa_mask[0]=11111111011111111101111111111110, sa_flags=SA_RESTART|SA_SIGINFO
SIGILL: [libjvm.so+0x920ac0], sa_mask[0]=11111111011111111101111111111110, sa_flags=SA_RESTART|SA_SIGINFO
SIGUSR1: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none
SIGUSR2: [libjvm.so+0x922300], sa_mask[0]=00000000000000000000000000000000, sa_flags=SA_RESTART|SA_SIGINFO
SIGHUP: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none
SIGINT: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none
SIGTERM: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none
SIGQUIT: SIG_DFL, sa_mask[0]=00000000000000000000000000000000, sa_flags=none

---------------  S Y S T E M  ---------------
OS:CentOS Linux release 7.5.1804 (Core)
uname:Linux 3.10.0-862.9.1.el7.x86_64 #1 SMP Mon Jul 16 16:29:36 UTC 2018 x86_64
libc:glibc 2.17 NPTL 2.17
rlimit: STACK 8192k, CORE infinity, NPROC infinity, NOFILE 65536, AS infinity
load average:0.05 0.51 1.22

1 - First, stop your Indexima cluster with the command stop.sh

2 - Edit the file conf/galactica-env.sh and add the following lines :

3 - Make sure also to add${GC_OPTIONS} argument in the start-node.sh, start_yarn.sh or start_node.bat scripts such as:

4 - Turn the Garbage Collector On or Off with the option GC_VERBOSE.

5 - By default, GC log files are written in the INDEXIMA log directory. This directory is defined in the conf/galactica.conf configuration file.

6 - Snippet of a GC log file :

Garbage Collector Traps

3 - Make sure also to add`${GC_OPTIONS}` argument in the start-node.sh, start_yarn.sh or start_node.bat scripts such as: