Analyzing Slow Response – Case 2 (a High CPU Usage)

Recently we observed a strange issue with one of our Tomcat server in Production. The monitors that we configured on these always showed degraded performance. The HTTP Ping monitor that we configured has a Success status when it responds in less than 2 seconds. But from the last couple of days we were seeing alerts as the HTTP Ping Monitor is taking more than 6 Seconds and to respond causing the alert to fail.

1) We started to analyze the performance of the server by using the basic top command which gave us the highest CPU and Memory Used process like,

localHost $ top -n1 | grep -m1 java

5944  root   20   0 7057m 4.3g 7444 S 312.1 55.9  13871:55 java

We obtained the Process that was actually using the High CPU and amount of the Memory being used. In this case the CPU being used is 312.1

2) Next step is we started to find out the Thread ID that is causing the HIGH CPU usage in this process which gave us this

localHost $ top -n1 -H | grep -m1 java | perl -pe 's/\e\[?.*?[\@-~] ?//g' | cut -f1 -d' '

5958

3) In the next process we took the thread dump of the PID 5944 (running Tomcat Process ID ) and obtained the NativeID for the Thread ID using

localHost $ printf "%x" 5958

1746

4) From the Thread Dump we observed that this thread belongs to Garbage Collection

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f306c025800 nid=0x1746 runnable

And some times it pointed us to

"VM Thread" prio=10 tid=0x00007f306c134800 nid=0x1749 runnable

The VM thread is a special thread in the HotSpot VM. It performs special tasks in the VM such as garbage collection. If the VM_Operation suggests that the operation is a garbage collection then it is possible that you have encountered as issue such as heap corruption.

The High CPU usage might be  a Garbage collector issue but it can be some thing else that leave object references in the heap in in-correct state.

The main important thing at this point is to collect as much information as possible about the environment and try out possible workarounds.

Now upon checking the GC status we observed that the memory is totally exhausted and the GC is performing high number of Full GC’s

localHost $ jstat -gcutil  5944

  S0      S1     E      O        P        YGC     YGCT       FGC    FGCT          GCT

  0.00   0.00  70.12 100.00  99.66  57691 4817.991 30178 107006.562 111824.553

In the above case , the FGC element tells us the number of Full GC Caused during the life time.

Since the JVM is busy handling the Full GC of this process, it is actually pausing the other threads to perform the GC events hence causing the slow response to the EMS monitor.

More to come, Hope this helps J

Read More

All You Need to Know about Class-loaders

Class-loaders in java play an important role in Java. They are the pieces that every java developer should be aware of. In this article we will see the working of a Class-loader in java.

So what exactly is a Class-loader?

Every class-loader is an Object. An Instance of the class that extends the abstract Class java.lang.ClassLoader. So every class in java is loaded by one of these instances.

So what does this class-loader do?

The class-loader is the means by which Java Classes and resources are loaded in the JRE (Java Runtime Environment).

What does it load?

As we know a Class file contains the binary representation of a Java Class, which has the executable byte-codes and references to other classes used by this class. This includes references to classes to the java API and other references. The Class-loader locates the byte-codes for the java class that needs to be loaded, read the byte-codes and creates a instance of java.lang.Class class. Then this class is made available to the JVM for execution.

Even statements as simple as String greeting = "hello" or int maxValue = Integer.MAX_VALUE make use of a class loader. They require the String class and the Integer class to be loaded.

Initially only class that needs to be executed as loaded into the class ,once the execution moves forward the Classes being referenced are loaded are loaded thus using the lazy loading.

If classes are loaded by the instances of the class that extends ClassLoader class, then there should be something that makes the started before this that make the instances of the Class-loader class. How does this work?

Class-Loader principles

Every ClassLoader in java Works on 3 Principles,

Delegation: Whenever a Class is to be loaded, the request is forward to the Parent ClassLoader for loading. The Child ClassLoader loads the class if Parent ClassLoader cannot find or load Class.

Visibility: This allows child ClassLoader to see all classes loaded by the parent ClassLoader but the Parent ClassLoader cannot view classes loaded by the Child ClassLoader.

Uniqueness: This allows loading a Class exactly once by taking help of delegation and ensures that the ClassLoader does not re-load the class that is already re-loaded by the Parent.

How Classes are loaded?

Here is an excerpt from the java.lang.ClassLoader

package java.lang;

public abstract class ClassLoader {

  public Class loadClass(String name);

  protected Class defineClass(byte[] b);

  public URL getResource(String name);

  public Enumeration getResources(String name);

  public ClassLoader getParent()

}

The loadClass(String name) is the most important method above, which takes the fully qualified name of the class to be loaded as String and returns an object of class Class.

The next important method is the defineClass(byte b[]) which actually materialize the Class. The byte array parameter is the byte code of the Class which is loaded from Disk.

The getParent() method returns the Parent Class-loader.

getResource and getResources return URLs to actually existing resources when given a name or a path to an expected resource.

So consider if I we check the code,

Public class A {

   Public void createB() {

          B b=new B();

  }

}

In the above snippet, when we say B b=new B(),a couple of things happen here. The creation of B instance is B b = A.class.getClassLoader().loadClass(“B”).newInstance().

So every Object created is associated with its own class (A.Class in this case) and every Class is associated with its own ClassLoader.

Class-Loader Hierarchy

Whenever a JVM starts a bootstrap ClassLoader is started first. This is the parent Class-loader for all Classes. Its responsibility is to load Core Classes from java.lang package and other use full runtime Classes to the memory first. We can say that the bootstrap ClassLoader is the one which does not have a parent Class Loader.

The next one of the extension class-loader which is responsible for loading classes from all the jar file available in the java.ext.dirs path and files available in JRE/lib/ext location.

The next is the Application Class loader which is very important for a developer. This ClassLoader is responsible for loading classes from directories and jar files specified by the CLASSPATH environment variable, java.class.path system property or –classpath command line. This is the child of the extension Class-loader.

Contest Class Loader: In the newer versions of java, there is something called as Context Class Loader which is used with threads. A thread's context class loader is, by default, set to the context class loader of the thread's parent. The Context class loader of a thread is set to the Class-loader that loaded the application. The context class loader can load the classes that the application can load. This is normally used by the java Runtime such as RMI to load classes and resources on behalf of the application.

Endorsed Standard Override Mechanism: The Endorsed Standard Override Mechanism says that if we have a newer version of JAXP class which we want to load but Since this class is already being loaded by the bootstrap ClassLoader from the rt.jar, in order to overcome we can place this new version in a location and access that location by passing an argument as –Djava.endorsed.dir=<Path to Location of Jar>

Here is the Class-Loader hierarchy,

Request for a Class by Client

Lets see how the class-loader thing works when a Client requests to load a Class.

1. A check is performed to see if the requested class is already loaded by the Current Class Loader. If that is loaded it is returned back and used. The JVM will cache all the classes that are loaded by the Class-loaded so a Class which was loaded once will not be loaded again.

2. If the class is not already loaded, the request is delegated to the Parent Class-Loader before the check to the Current Class-loader fails. The delegation can move to the top level (bootstrap Class loader) until no further delegation can be done.

3. So if the parent Class-loader also cannot load the class, the Current Class-loader will then try to search for the requested class in some defined locations such as the bootstrap searches in the location specified in the sun.boot.class.path system property. And Application class-loader will search in the classpath location.

4. If the class is still not found, a java.lang.ClassNotFouncException is thrown.

Does Classes in Class-Loader see?

Classes loaded by a Class-loader can see other Classes loaded by the same Class-loader. Classes inside a Class-loader cannot see Classes loaded by other Classes.

JMV keepts track of the classes loaded by a Class-loader. This is achieved by name-space technique by which every Class-loader in a Java application will have its own Name-space( java.lang.*) and classes loaded in one name –space cannot see classes loaded by other Name-spaces.

There are certain restrictions where we can load multiple class-loaders in the java application and load the same class from multiple class-loaders. At this point , the class will know that there is another version available.

What If I create a custom class in a name-space?

Since we said that classes are loaded by the name-space and classes loaded in one class-loader cannot view classes loaded by other Class-loader. What if I create a class in java.util Package?

Even if we create a custom class with a same package, java only grants access to a Class in the same package which gets loaded by the same Class-loader. In the above case even if we create a Custom class with a same package name, the class will be loaded by the user-class loader.

Container Class-Loader

This class loader hierarchy happens when a JVM starts but the hierarchy may differ when we use J2EE containers. In containers, every ear application deployed will be having its own Class-loader and more over ever war file inside the ear will have its class-loader. The web class-loader will load the classes in the local class-loader and the task is delegated to the Parent Class loader only when Classes cannot be loaded (as Specified in Servlet Specification).

Some containers allows to web modules to load classes from the location specified instead of loading classes from the Parent Class Loader. In Weblogic, we can use <Prefer-web-inf-class> element in the weblogic.xml file which allows jar to be loaded from the WEB-INF location even though a version of the jar is loaded by the parent Class-Loader. These cases arise with the logging libraries where the container holds a version and application ships with a different version.

This is normally done by overriding the loadClass() method of the java.lang.ClassLoader Class. 

We will see some Class Loader case Studies like Tomcat, Weblogic and JBoss in next articles.

Read More

Garbage Collection

As we said earlier objects are stored in the Young generation as well as Old generation and there should be a way to clean the objects. The Garbage Collector comes at this point.

How a JVM does the Memory allocation?

Memory allocations in JVM are done using 2 techniques

Bump-the-pointer: bump-the-pointer creates objects on the top of the EDEN space. This keeps track of the last object created. Whenever a request for creating a new object comes it will check the old object created and make sure the new object size is suitable enough to be created in Eden space. It creates the object and the new object will be the first one on the top.

This can be considered as a Pointer increment method where the first object allocated will have an 'address' (actually an offset into the segment) of zero. When you allocate object then the memory manager will know how big the object is, allocate that much space within the segment (16 bytes say) and then increment it's "offset address" by that amount.

But this becomes complicated during the multi-threaded case, to save objects used by multiple threads in the Eden space for Thread-Safe, an inevitable lock will occur and the performance will drop due to the lock-contention. The TLAB method helps in this case

TLABs (Thread-Local Allocation Buffers): This allows each thread created in JVM to have its own small portion of the EDEN space. As each thread created can only access to their own TLAB, the memory allocations can be done without a lock

Garbage Collector

The Garbage Collector algorithm is another important place to tune the performance. These determine how the garbage collection process is executed.

A GC can be considered good when it meets certain criteria

When a high throughput is achieved &

When a Small Pause time is achieved

JVM always executes GC in a dedicated Thread called "GC threads”. So when ever GC threads are active, they have to compete with the application threads for Processor and CPU time.

Throughput, the throughput can be the amount of work done by an application as a ratio of time spent in GC

For example, a throughput of 99/100 means that on average the application threads are running 99 out of 100 seconds of program execution time, while the GC threads are only running for one second during the same time span.

This can be managed by ‑XX:GCTimeRatio=99 ; 99 is the default equating to 1% GC time.

The term “pause time” refers to a time span in which the application threads are paused completely in favor of the GC threads. For example, a pause time of 100 milliseconds during a GC means that no application thread was active during that 100 millisecond interval

This can be managed by  ‑XX:MaxGCPauseMillis=<n>.

  

Garbage collection uses a term "stop-the-world”. This means that when a JVM is doing a Garbage collection, every thread except for the threads needed for the GC will stop their tasks. The interrupted tasks will resume only after the GC task has completed. So when ever a GC is going being performed, all application related threads are kept on hold until the Gc is completed.

The JVM uses a form of garbage collector called a tracing collector, which operates by pausing the world around it, marking all root objects (objects referenced directly by running threads), and following their references, marking each object it sees along the way.

Java implements something called a generational garbage collector based upon the generational hypothesis assumption, which states that the majority of objects that are created are quickly discarded, and objects that are not quickly collected are likely to be around for a while.

Why application Threads need to be stopped?

 A GC requires certain preconditions in order to run safely. For example, it must be guaranteed that application threads do not modify the state of objects while the GC threads try to decide which objects are still referenced and which ones are not. For this reason, the application threads must be stopped during a GC 

Even though GC is good but it causes additional costs for thread scheduling: direct costs through context switches and indirect costs because of cache effects

So a GC comes with negligible cost efforts

Minor and Major GC

This is divided into 2 parts,

Minor GC (Young generation): Most of the objects created in the Young Generation.  These objects are created and then will be disappeared. When objects disappear from this area, we say a "minor GC" has occurred. 

Major GC (Old generation): When Objects that are survived from young generation, they are copied to the Old Generation. As its size gets bigger and bigger a GC Occurs which is called a Major GC that cleans up objects that can be garbage collected.

Gc happened in Perm Space can also be considered as a Major GC.

How can the GC find objects that are eligible to Garbage?

An Object will be considered to garbage when the object is no longer referenced by any pointers from inside the application. Normally a GC iterates over every reachable object and if any objects are left over they are Garbage Collected.

When the Young Generation is full (smaller Pause + more Frequent), a minor collection GC is trigged. This has the small performance impact since it cleans only the smaller memory area.

When the Old generation is full (Bigger Pause + Less Frequent), a major collection GC is trigged. This can lead to a performance impact since it is targeted to the Entire Heap area.

If the major GC fails to free required memory, the JVM increases the current memory to allocate memory for the Object allocation. The whole cycle moves until memory reaches Max Memory Set for the JVM and then we see the Out Of Memory.

What if an object in the old generation needs to reference an object in the young generation?

To handle this case, the Old generation maintains something called ‘Card Table’ which is a 512 byte chunk. So If an object in old Generation refers an object in young generation, this information is recorded in this table. When a GC is started in the young generation, only this card table is searched to determine whether an object is being referenced by something from the Old generation. This eliminated the need to check the object references for all the objects in the old generation to check whether they are accessing something from Young generation. This card table is managed with write barrier. This write barrier is a device that allows a faster performance for minor GC. Though a bit of overhead occurs because of this, the overall GC time is reduced.

GC alogirthms 

There are 5 algorithms

1. Serial GC
2. Parallel GC
3. Parallel Old GC (Parallel Compacting GC)
4. Concurrent Mark & Sweep GC  (or "CMS")
5. Garbage First (G1) GC

And these can be further divided into

Collectors operating on young generation

-XX:+UseSerialGC

-XX:+UseParNewGC

-XX:+UseParallelGC

Collectors operating on old generation

-XX:+UseParallelOldGC

-XX:+UseConcMarkSweepGC

Serial Collector (-XX:+useSerialGC)

This is a default copying collector. This collector performs the Garbage collection in a single thread. During this process it stops all other threads. Serial GC may drop the application performance gradually.

This can be used with single processor systems. Since there is no communication overhead between various threads, it cant advantage from the multi processor systems. This GC type was created when there was only one CPU core on desktop computers.

Parallel GC (-XX:+UseParNewGC)

This is similar to the serial collector which is a stop-the-world collector. But this collector parallelizes the copying collection over multiple threads, which is more efficient than the original single-thread copying collector for multi-CPU machines.

Parallel GC (-XX:+UseParallelGC) &  Parallel Old GC  (‑XX:+UseParallelOldGC)

Parallel GC uses multiple Threads for performing the GC and hence it is faster. This GC is useful when there is enough memory and a large number of cores. It is also called the "throughput GC." 

The parallel collector comes in 2 forms, Parallel collector which uses multiple threads to perform minor GC on the young generation and a single thread for performing the major GC on the old generation.

The other one Parallel Old Collector which is a default on from jdk7 uses multiple threads for both minor GC as well as major GC.

This algorithm is considered as the best on a multi processor systems which will give the greatest throughput. For example, batch processing like printing reports or bills or performing a large number of database queries .The below image tells the differences between Serial and Parallel GC

Concurrent Mark & Sweep GC (-XX:+UseConcMarkSweepGC)

This GC method is one of the complex method available now. As we have learned earlier the Throughput Collector always pauses the application threads for some time during the GC process. In Contrast the CMS collector runs along with the application threads and only cause few pause times. This is sometimes called as Concurrent Low Pause Collector.

A GC cycle of the CMS Collector consists of six phases. Four of the phases are run concurrently to the actual application while the other two phases need to stop the application threads.

·         Initial Mark: The application threads are paused and marks all objects that are reachable as live from root objects (GC roots).

·         Concurrent Mark: in this phase all the application threads are restarted again. Objects that are reachable by the objects identified in the first phase are also marked as live

·         Concurrent Pre-clean: in the 3 phase, it checks the objects which has been updated or promoted during the second phase. It also checks for any new objects allocated. This phase runs multiple times and make sure certain amount of memory space is available in Eden. It also checks whether objects are alive or dead.

·         Remark: in the next stage , the application threads are stopped one more time so that a check can be done on objects to find any reference changes happened in the 3 phase. The application threads are stopped ensure a correct view of referenced objects before the actual cleaning takes place

·         Concurrent Sweep: All objects that are not referenced are removed from heap

·         Concurrent Reset: The GC collector does some house keeping jobs to make sure that there is clean state for the next Gc run.

Concurrent Mode Failure

At some points, the CMS collector can’t fill the needs of the application and a Full Gc is needed. This is called Concurrent Mode Failure. This failure occurs when there is not enough space in tenured to promote a Objects

CMS doesn't collect permgen spaces by default, and requires the XX:+CMSClassUnloadingEnabled flag enabled in order to do for the perm space to be gc

Most cases a Full GC is trigged if the flag is not enabled. permgen space can hold references into normal heap via things like class loaders, which means that until you collect Permgen you may be leaking memory in regular heap

A separate article will be available on Garbage G1 collector.

More to Come ,Happy Learning J

Read More

Analyzing a JVM Crash

A crash can cause the JVM to terminate. A Crash or even a fatal error can cause a Crash. A bug in the API, a bug in third party library that we use or bug in a native api can cause these JVM crashes. JVM can crash due to the external factors like resource exhaustion etc.

In this article we will see how we can analyze a JVM crash. Whenever a JVM is crashed a fatal error log file is generated. The file is named as hs_err_pid<pid>.log (where <pid> is the process id of the process). Most cases this file is created in the same working directory and in some other cases the file may be created in the temporary location. The file is created in the /tmp location in Linux and in directory specified by TEMP environment variable in windows.

The format of the error log file will change accordingly.

Header

The header in the log file tells us about the problem. This is printed to standard output. An example log file looks as

#

# An unexpected error has been detected by Java Runtime Environment:

#

#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x074639a3, pid=1232, tid=9240

#

# Java VM: Java HotSpot(TM) Client VM (11.0-b16 mixed mode, sharing windows-x86)

# Problematic frame:

# C [jp2iexp.dll+0x39a3]

#

# If you would like to submit a bug report, please visit:

#   http://java.sun.com/webapps/bugreport/crash.jsp

# The crash happened outside the Java Virtual Machine in native code.

# See problematic frame for where to report the bug.

#

The first line tells that the JVM crashed due to an Unexpected signal. The second line gives some more details like,

EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x074639a3, pid=1232, tid=9240

EXCEPTION_ACCESS_VIOLATION: This was crashed with an Access violation exception and this is the signal name.

(0xc0000005): Signal Number

0x074639a3: Instruction pointer

pid=1232: Process ID

tid=9240: Thread ID

The next line tells us about the JVM

# Java VM: Java HotSpot(TM) Client VM (11.0-b16 mixed mode, sharing windows-x86)

This says that the JVM is running in Client mode, mixed and sharing mode.

The Problematic frame is the function frame where the error occurred. The next line gives us like

C [jp2iexp.dll+0x39a3]

This is represented as a Library name and offset. It's possible to inspect the instructions that caused the crash without a debugger or core file.  Just use a disassembler to dump instructions near the offset.

In the above line, the “C” is called a Native C Frame. We do have some other frames as

C -Native C frame

J –Other frame types including compiled Java frames

j -Interpreted Java frames

V -VM frames

v –VM generated stub frame

Thread

The fatal error log will also give us the Thread details. The thread section in the log file gives us information about the thread that crashed. There may be cases where multiple threads crash, at this point only one thread is printed.

The first part in the thread section tell us

Current thread (0x0d0eb000):  JavaThread "main" [_thread_in_native, id=9240, stack (0x044e0000, 0x046e0000)]

Current thread (0x0d0eb000): The Thread pointer is a pointer to the internal representation to the JVM internal thread structure.

JavaThread "main": The Java Thread that is currently running. This can change accordingly.

_thread_in_native: The Thread State.

Some other thread states include,

_thread_uninitialized: Thread is not created. This should never happen unless there's

memory corruption

_thread_new: Thread has been created but it has not yet started.

_thread_in_native: Thread is running native code. Probably a bug in native code.

_thread_in_vm: Thread is running VM code.

_thread_in_Java: Thread is running (either interpreted or compiled) Java code.

_thread_blocked: Thread is blocked.

..._trans: If you see any of the above states but followed by "_trans", it means

the thread is changing to a different state.

id=9240: The thread ID is the native Thread ID also seen as nid in Thread dumps.

The next line is the signal information like

siginfo: ExceptionCode=0xc0000005, reading address 0x00000000

This indicates that the exception code is 0xc0000005 (ACCESS_VIOLATION), and it occurred when the thread attempted to read address 0x00000000.

The next line after this will be the register information like,

Registers:

EAX=0x00000000, EBX=0x28108828, ECX=0x004583a8, EDX=0x046dc46c

ESP=0x046dc448, EBP=0x046dc458, ESI=0x00000000, EDI=0x0d0eb000

EIP=0x074639a3, EFLAGS=0x00010246

These register gives us the context of the register at the time of the fatal error and these will change depending on the underlying architecture.

After the register values, you will see the top of stack and the instructions/opcodes near the crashing pc. The error log prints 32 bytes which can be decoded using a disassembler to see the instructions around the location of the crash. These can be seen as

Top of Stack: (sp=0x046dc448)

0x046dc448:   046dc46c 046dc454 28108828 00000000

0x046dc458:   046dc498 0e869d11 0d0eb114 046dc4a0

0x046dc468:   09eaabf8 00000000 0d0eb9ac 0d0eb9a4

0x046dc478:   046dc478 28108828 046dc4ac 28110a90

0x046dc488:   00000000 28108828 00000000 046dc4a8

0x046dc498:   046dc4d4 0e862f07 281104e0 0e8681a6

0x046dc4a8:   09eaabf8 00000000 2718dd98 046dc4b4

0x046dc4b8:   28108797 046dc4dc 28110a90 00000000

Instructions: (pc=0x074639a3)

0x07463993:   33 f6 85 c0 7c 3a 8b 45 fc 8d 55 14 52 89 75 14

0x074639a3:   8b 08 50 ff 91 a0 00 00 00 85 c0 7c 1a 8b 75 14

The next line of information will be the thread stack trace. This includes the addresses of the base and the top of the stack, the current stack pointer, and the amount of unused stack available to the thread. This is followed by the stack frames and up to 100 frames are printed. For C/C++ frames the library name may also be printed.

Stack: [0x044e0000, 0x046e0000], sp=0x046dc448, free space=2033k

Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)

C [jp2iexp.dll+0x39a3]

j  sun.plugin2.main.server.IExplorerPlugin.getDocumentBase0(J)Ljava/lang/String;+0

j  sun.plugin2.main.server.IExplorerPlugin.getDocumentBase()Ljava/lang/String;+31

……..

……..

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)

j  sun.plugin2.main.server.IExplorerPlugin.getDocumentBase0(J)Ljava/lang/String;+0

j  sun.plugin2.main.server.IExplorerPlugin.getDocumentBase()Ljava/lang/String;+31

…….

If we see we have 2 stack traces one was a Native Stack trace and other was a Java Stack Trace.

The Native Stack trace gives us the native thread information showing all function calls leaving the Java calls. The second stack is Java frames which prints the java frames including the in-lined methods. It skips the native frames. Sometimes according to the crash it will not print the native thread details but can print the java details.

Process

Some of the fatal error log file will generate the Process Information too. The process section gives us information about the process which includes the thread details and memory usage. We can see the information as,

Java Threads: ( => current thread )

Other Threads:

=>0x00007faa08008800 (exited) JavaThread "Unknown thread" [_thread_in_vm, id=12588, stack(0x00007faa0c9d5000,0x00007faa0cad6000)]

Java Threads: ( => current thread )

  0x11726c00 JavaThread "JRE 1.6.0.11 Worker Thread" [_thread_blocked, id=10764, stack(0x123d0000,0x124d0000)]

  0x11726800 JavaThread "JRE 1.6.0.11 Output Reader Thread" [_thread_in_native,

……

Other Threads:

  0x0d14b800 VMThread [stack: 0x109b0000,0x10ab0000] [id=9664]

  0x0d171c00 WatcherThread [stack: 0x114e0000,0x115e0000] [id=8004]

In the above line we can see, The thread list includes the threads that the VM is aware of. This includes all Java threads and some VM internal threads, but does not include any native threads created by the user application that have not attached to the VM

VM state:not at safepoint (normal execution)

The next line gives us the VM state. This normally tells us the state of the VM. Some normal VM states include

1.    not at a safepoint – normal execution

2.    at safepoint – indicates that all threads are blocked in the VM waiting for a special vm operation to complete

3.    synchronizing – indicates that a special vm operation is required and the VM is waiting for all threads in the vm to block.

VM Mutex/Monitor currently owned by a thread: None

The next line gives us the Mutex/Monitor Information. These are not java Object locks but JVM internal locks. For each lock it prints the name of the lock, its owner, and the addresses of a VM internal mutex structure and its OS lock. In this case the lock is owned by None.

Heap

 def new generation   total 960K, used 773K [0x27100000, 0x27200000, 0x27230000)

  eden space 896K,  86% used [0x27100000, 0x271c15f8, 0x271e0000)

  from space 64K,   0% used [0x271e0000, 0x271e0000, 0x271f0000)

  to   space 64K,   0% used [0x271f0000, 0x271f0000, 0x27200000)

 tenured generation   total 4096K, used 0K [0x27230000, 0x27630000, 0x28100000)

   the space 4096K,   0% used [0x27230000, 0x27230000, 0x27230200, 0x27630000)

 compacting perm gen  total 12288K, used 749K [0x28100000, 0x28d00000, 0x2c100000)

   the space 12288K,   6% used [0x28100000, 0x281bb598, 0x281bb600, 0x28d00000)

    ro space 8192K,  63% used [0x2c100000, 0x2c613ae8, 0x2c613c00, 0x2c900000)

    rw space 12288K,  53% used [0x2c900000, 0x2cf683f8, 0x2cf68400, 0x2d500000)

The next section prints about the heap details and they depend upon the GC and memory used.

After the heap details, the next section tells us about the memory regions at the time of crash. A Memory map is also generated which is use-full when debugging some crashes, as it can tell you what libraries are actually being used, their location in memory, as well as the location of heap, stack and guard pages. This memory map section will be different depending on the Operating Systems. On Linux the process memory map (/proc/<pid>/maps) is printed. On Windows, the base and end addresses of each library are printed.

Dynamic libraries:

0x01220000 - 0x012dc000   C:\Program Files (x86)\Internet Explorer\IEXPLORE.EXE

0x777a0000 - 0x77920000   C:\Windows\SysWOW64\ntdll.dll

0x76d70000 - 0x76e80000   C:\Windows\syswow64\kernel32.dll

……..

Or in some cases

Dynamic libraries:

00400000-00401000 r-xp 00000000 fd 04 263750    /software/bin/java

0238e000-023af000 rw-p 00000000 00:00 0                            [heap]

3fae00000-800000000 rw-p 00000000 00:00 0

3be8802000-3be8a02000 ---p 00002000 fd:00 321        /lib64/libdl-2.12.so

…..

The reading of memory map is as follows                      

00400000-00401000: memory region

r-xp: Permission on the region , we have Read,Write,eXecute,Private and Share.

Fd: File Off set number

04:Major ID and minor ID of the device from where the file is located or accessed.

263750: Inode number   

/software/bin/java: File Name

Every library has two virtual memory regions. One for code and one for data. The code

segment is marked with r-xp (readable, executable, private); data segment is rw-p

(readable, writable, private).

The Java heap details can be obtained with the map listed as heap. This gives us the the actual memory regions reserved for heap with attributes rwxp.

Thread stacks usually show up in the memory map as two back-to-back regions, one with

attribute ---p (guard page) and one with rwxp (actual stack space). Of course, knowing the

guard page size or stack size would make the job a bit easier. For example, in this memory

map, 3be8802000-3be8a02000 is stack.

After the memory map details, we can see VM arguments passed,

VM Arguments:

jvm_args: -XX:+AggressiveOpts -XX:+UseLargePages -Xmn10g -Xms26g -Xmx26g

java_command: <unknown>

Launcher Type: SUN_STANDARD

The next section tells us about the Environment variables passed

Environment Variables:

JAVA_HOME=/software/java64/current

PATH=/usr/local/bin:/bin:/usr/bin:/usr/local/.............

LD_LIBRARY_PATH=/software/jboss/ews/current/lib:

SHELL=/bin/bash

System

The last section is about the System which gives us the information about the system statistics when the crash occurred like

OS:Red Hat Enterprise Linux Server release 6.4 (Santiago)

uname:Linux 2.6.32-358.23.2.el6.x86_64 #1 SMP Sat Sep 14 05:32:37 EDT 2013 x86_64

libc:glibc 2.12 NPTL 2.12

rlimit: STACK 10240k, CORE 0k, NPROC 32768, NOFILE 8192, AS infinity

load average:0.00 0.01 0.00

/proc/meminfo:

MemTotal:        1922716 kB

MemFree:          177136 kB

Buffers:           67908 kB

Cached:           226672 kB

SwapCached:        11612 kB

Active:          1093288 kB

Inactive:         472848 kB

Active(anon):     950380 kB

Inactive(anon):   324624 kB

Active(file):     142908 kB

Inactive(file):   148224 kB

Unevictable:        4208 kB

Mlocked:            4208 kB

SwapTotal:       4194296 kB

SwapFree:        4131324 kB

Dirty:               112 kB

Writeback:             0 kB

AnonPages:       1267744 kB

Mapped:            21132 kB

Shmem:                 0 kB

Slab:             139492 kB

SReclaimable:     111720 kB

SUnreclaim:        27772 kB

KernelStack:        2768 kB

PageTables:         7384 kB

NFS_Unstable:          0 kB

Bounce:                0 kB

WritebackTmp:          0 kB

CommitLimit:     5155652 kB

Committed_AS:    2018712 kB

VmallocTotal:   34359738367 kB

VmallocUsed:       12060 kB

VmallocChunk:   34359712480 kB

HardwareCorrupted:     0 kB

AnonHugePages:     75776 kB

HugePages_Total:       0

HugePages_Free:        0

HugePages_Rsvd:        0

HugePages_Surp:        0

Hugepagesize:       2048 kB

DirectMap4k:        8180 kB

DirectMap2M:     2088960 kB

CPU:total 1 (1 cores per cpu, 1 threads per core) family 6 model 13 stepping 3, cmov, cx8, fxsr, mmx, sse, sse2, sse3, lzcnt, tsc

/proc/cpuinfo:

processor      : 0

vendor_id      : AuthenticAMD

cpu family     : 6

model           : 13

model name   : QEMU Virtual CPU version (cpu64-rhel6)

stepping        : 3

cpu MHz                  : 2394.026

cache size      : 512 KB

fpu               : yes

fpu_exception : yes

cpuid level     : 4

wp               : yes

flags             : fpu de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 syscall nx lm up unfair_spinlock pni cx16 hypervisor lahf_lm abm sse4a

bogomips       : 4788.05

TLB size        : 1024 4K pages

clflush size     : 64

cache_alignment       : 64

address sizes : 48 bits physical, 48 bits virtual

power management:

Memory: 4k page, physical 1922716k(177136k free), swap 4194296k(4131324k free)

The output is operating system specific but in general includes the operating system version, CPU information, and summary information about the memory configuration.

In Linux or solaris , the the operating system information obtained by reading /etc/*release.

The uname In linux is called to get information about the kernel and the Thread library

uname:Linux 2.6.32-358.23.2.el6.x86_64 #1 SMP Sat Sep 14 05:32:37 EDT 2013 x86_64

libc:glibc 2.12 NPTL 2.12

On linux there are 3 types of threading libraries which areinuxthreads (fixed stack), linuxthreads (floating stack) and NPTL. In our case it’s the NTPL. Knowing this type is use-full when we see crashes that come due to the threading library.

The rlimit is actually a wrapper for the ulimit command in linux

rlimit: STACK 10240k, CORE 0k, NPROC 32768, NOFILE 8192, AS infinity

load average:0.00 0.01 0.00

The ulimit gives us the information about the limits that are set for various elements. In the above line

Stack: Stack Size (ulimit –s)

CORE: Core dump size(ulimit –c)

NPROC: Maximum user process (Ulimit –u)

NOFILE: Maximum Open files (ulimit –n)

CPU:total 1 (1 cores per cpu, 1 threads per core) family 6 model 13 stepping 3, cmov, cx8, fxsr, mmx, sse, sse2, sse3, lzcnt, tsc

The CPU information is also provided with the fatal error log and last the memory information is provided as

Memory: 4k page, physical 1922716k(177136k free), swap 4194296k(4131324k free)

4K: Page Size

1922716k: Physical memory

177136k: un-used Physical Memory

4194296k: Total Swap memory

4131324k: Un-used Swap Memory

If both physical memory and swap space are almost full, there's good reason to suspect the crash was due to running out of memory.

vm_info: Java HotSpot(TM) Client VM (11.0-b16) for windows-x86 JRE (1.6.0_11-b03), built on Nov 10 2008 02:15:12 by "java_re" with MS VC++ 7.1

The Final Section is the Vm_info.This is a version string embedded in libjvm.so/jvm.dll. Every JVM has its own unique vm_info string. When you are in doubt about whether the hs_err*.log was generated by a particular JVM, check the version string.

I will be updating this doc with more details on analyzing the error log file.

More to Come, Happy Learning J

Read More