Tag: JVM Tuning

How to Generate HeapDump in case of Windows Service ?

Hi,

Jay SenSharma

Jay SenSharma

Based on the query of Magic Subscriber “fipnova51we are writing this article.  This article is very very important in case of Windows Service.  Because if we run any Server like JBoss or WebLogic like a Windows Service then NONE of the JVM utilities like “jmap”, “jconsole” , “jps” …etc will work. So it becomes very difficult to collect the Thread Dump or Heap Dump of the Running Service.

We wrote an article using JMX to collect all the JVM details using JMX code “Remote JVM Analysis (Mini JConsole)“. Here we are extending the same program to make the JMX program to even collect the HeapDump whenever we want.

Step1). Make a Windows Service for example you can use the following Script to make your WebLogic Server as Windows Service…

echo off
SETLOCAL
set DOMAIN_NAME=Test_Domain
set USERDOMAIN_HOME=C:bea103user_projectsdomainsTest_Domain
set SERVER_NAME=AdminServer
set WLS_USER=weblogic
set WLS_PW=weblogic
set PRODUCTION_MODE=true
set JAVA_VENDOR=Sun
set JAVA_HOME=C:bea103jdk160_05
set MEM_ARGS=-Xms1024m -Xmx1024m  -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=127.0.0.1

set JAVA_OPTIONS=-Dweblogic.Stdout=C:bea103user_projectsdomainsTest_DomainASstdout.txt -Dweblogic.Stderr=C:bea103user_projectsdomainsTest_DomainASstderr.txt %MEM_ARGS%
call "C:bea103wlserver_10.3serverbininstallSvc.cmd"
ENDLOCAL

NOTE: Make sure that the -Dcom.sun.management.* flags are added properly in the JAVA_OPTIONS of the script.

Step2). Now You can also use the following Script to Uninstall your WebLogic Server Windows Service …

SETLOCAL
set WL_HOME=C:bea103wlserver_10.3
rem *** Uninstall the service
"%WL_HOME%serverbinbeasvc" -remove -svcname:"beasvc Test_Domain_AdminServer"
ENDLOCAL

Step3). Now Write the following JMX code “GenerateHeapDump.java”  inside some directory.

import java.util.Hashtable;
import java.io.*;
import javax.management.MBeanServerConnection;
import javax.management.remote.JMXConnector;
import javax.management.remote.JMXConnectorFactory;
import javax.management.remote.JMXServiceURL;
import javax.naming.Context;
import java.lang.management.MemoryMXBean;
import java.lang.management.ManagementFactory;
import java.lang.reflect.Method;
import java.lang.reflect.Modifier;
import javax.management.*;
import javax.management.openmbean.CompositeDataSupport;

public class GenerateHeapDump
{
private static MBeanServerConnection connection;
private static JMXConnector connector;
public static void Connection(String hostname, String port) throws IOException
{
Integer portInteger = Integer.valueOf(port);
Hashtable h = new Hashtable();
JMXServiceURL address = new JMXServiceURL("service:jmx:rmi:///jndi/rmi://"+hostname+":"+port+"/jmxrmi");
connector = JMXConnectorFactory.connect(address,null);
connection = connector.getMBeanServerConnection();
System.out.println("GOT THE MBeanServerConnection---SUCCESSFULLY");
}

private static void doGarbageCollection() throws Exception
{
ObjectName memoryMXBean=new ObjectName("java.lang:type=Memory");
connection.invoke(memoryMXBean,"gc", null, null);
System.out.println("nnt------Garbage Collection Done Successfully-----");
}

private static void getHeapDump(String fileName) throws Exception
   {
      ObjectName memoryMXBean=new ObjectName("com.sun.management:type=HotSpotDiagnostic");
      Object[] params = new Object[] { "C:/WindowsService_Script/"+fileName, Boolean.TRUE };
      String[] signature = new String[] { String.class.getName(), boolean.class.getName() };
      Object result = connection.invoke(memoryMXBean, "dumpHeap" , params, signature);
      System.out.println("nt Heap Dump Generated to " +fileName);
}

public static void main(String[] args) throws Exception
{
String hostname = args[0];
String port = args[1];
Connection(hostname, port);
System.out.println("nt----------Generating Heap Dump---------");
getHeapDump("HeapDump.hprof");
connector.close();
}
}

Step4). Run your Windows Service and then compile and run your Program to generate the HeapDump.

C:WindowsService_Script>set PATH=c:bea103jdk160_05bin;%PATH%;

C:WindowsService_Script>javac GenerateHeapDump.java

C:WindowsService_Script>java GenerateHeapDump localhost 9999
GOT THE MBeanServerConnection---SUCCESSFULLY

        ----------Generating Heap Dump---------

         Heap Dump Generated to HeapDump.hprof

Step5). Now you can see that the Heap Dump is generated as desired … 🙂

.

.

Thanks

Jay SenSharma


Analyzing Garbage Collection Log

Hi,
Jay SenSharma

Jay SenSharma

It’s always best to enable the Garbage collection Logging in our production environment as well because it does not cause any resource overhead or any side effect on weblogic server or an other application server’s performance.  GC log helps us in investigating man issues. Apart from issues it helps us to find out if some tuning is required based on the statistics of the Garbage collection.
.
Garbage collection logging can be enable and collected in a separate log file by using the following JAVA_OPTIONS:
-Xloggc:D:/gcLogs/GCLogs.log         -XX:+PrintGCDetails        -XX:+PrintGCTimeStamps
As soon as you add these JAVA_OPTIONS which are JVM specific (above will work for Sun and Open JDKs fine) the JVM will start generating the garbage collection logging in the GCLog.log file. Now if you will open this file then you can
see something like following:
4.636: [GC [PSYoungGen: 230400K->19135K(268800K)] 230400K->19135K(2058752K), 0.0635710 secs] [Times: user=0.08 sys=0.01, real=0.06 secs]
7.302: [GC [PSYoungGen: 249535K->38396K(268800K)] 249535K->51158K(2058752K), 0.0777300 secs] [Times: user=0.21 sys=0.04, real=0.07 secs]
7.521: [GC [PSYoungGen: 49735K->38388K(268800K)] 62496K->51933K(2058752K), 0.0741680 secs] [Times: user=0.15 sys=0.04, real=0.07 secs]
7.595: [Full GC (System) [PSYoungGen: 38388K->0K(268800K)] [PSOldGen: 13545K->51794K(1789952K)] 51933K->51794K(2058752K) [PSPermGen: 19868K->19868K(39936K)], 0.3066610 secs] [Times: user=0.28 sys=0.02, real=0.31 secs]
9.752: [GC [PSYoungGen: 230400K->26206K(268800K)] 282194K->78000K(2058752K), 0.0728380 secs] [Times: user=0.15 sys=0.00, real=0.08 secs]
11.906: [GC [PSYoungGen: 256606K->38393K(268800K)] 308400K->94759K(2058752K), 0.1058920 secs] [Times: user=0.19 sys=0.00, real=0.10 secs]
13.480: [GC [PSYoungGen: 268793K->38394K(268800K)] 325159K->109054K(2058752K), 0.0762360 secs] [Times: user=0.20 sys=0.03, real=0.08 secs]
18.115: [GC [PSYoungGen: 268794K->38384K(268800K)] 339454K->179238K(2058752K), 0.1351350 secs] [Times: user=0.42 sys=0.10, real=0.14 secs]
20.860: [GC [PSYoungGen: 268784K->38394K(268800K)] 409638K->200343K(2058752K), 0.1063430 secs] [Times: user=0.29 sys=0.03, real=0.11 secs]
22.148: [GC [PSYoungGen: 268794K->38399K(268800K)] 430743K->221395K(2058752K), 0.1173980 secs] [Times: user=0.24 sys=0.02, real=0.12 secs]
23.357: [GC [PSYoungGen: 268799K->26775K(268800K)] 451795K->231618K(2058752K), 0.0714130 secs] [Times: user=0.15 sys=0.03, real=0.08 secs]
24.449: [GC [PSYoungGen: 257175K->29170K(268800K)] 462018K->239909K(2058752K), 0.0312400 secs] [Times: user=0.06 sys=0.01, real=0.04 secs]
You can notice something in the above output:
Point-1). [Full GC (System) [PSYoungGen: 38388K->0K(268800K)]    It means a Full GC is happening on the complete Heap Area including all the Areas of the Java Heap Space.
.
Point-2). [GC [PSYoungGen: 230400K->19135K(268800K)]   Indicates some small GCs which keep on happening in the young generation very frequently,This garbage collection cleans the Young Generation short living Objects.
.
Point-3). Meaning of the [GC [PSYoungGen: 230400K->19135K(268800K)]   line is around 256MB (268800K) is the Young Generation Size, Before Garbage Collection in young generation the heap utilization in Young Generation area was around  255MB (230400K)  and after garbage collection it reduced up to 18MB (19135K)
.
Point-4). Same thing we can see for Full Garbage collection as well….How effective the Garbage collection was…[Full GC (System) [PSYoungGen: 38388K->0K(268800K)] [PSOldGen: 13545K->51794K(1789952K)]  Here it says that around
[(old)1789952K +  young (268800K) ]  memory space means  OldGeneration is consuming 1.75GB space and Young Generation is consuming around 255 MB space  So it means total Heap size is around 2GB.
.
But analyzing the Garbage collection log like above technique Line by Line is very bad…so here we have an alternative was to analyze the Garbage Collection log in few Seconds to see how much time the Full Garbage collection is taking as an average and other reports…etc.
.
Step1). Download the “garbagecat-1.0.0.jar   (881 KB) ”  tool from the follwing link: http://garbagecat.eclipselabs.org.codespot.com/files/garbagecat-1.0.0.jar
.
Step2). Open a command prompt and then make sure that JAVA is set in the Path so that we can use “jar” utility of JDK to run the “garbagecat-1.0.0.jar”  tool.
.
Step3). Put the “garbagecat-1.0.0.jar”  file and the “GCLog.log” file in the same directory. then run the following command:
java      -jar      garbagecat-1.0.0.jar      GCLog.log
.
Step4). As soon as ou run the above command you will see that in your current directory following files are created:
garbagecat-1.0.0.jar
GCLog.log
gcdb.lck
gcdb.log
gcdb.properties
report.txt
.
Step5). Now open the “report.txt” file to see the Over all report of the Garbage Collection something like following:
========================================
SUMMARY:
========================================
# GC Events: 12
GC Event Types: PARALLEL_SCAVENGE, PARALLEL_SERIAL_OLD
Max Heap Space: 2058752K
Max Heap Occupancy: 462018K
Max Perm Space: 39936K
Max Perm Occupancy: 19868K
Throughput: 95%
Max Pause: 306 ms
Total Pause: 1233 ms
First Timestamp: 4636 ms
Last Timestamp: 24449 ms
========================================
.
If you see that the Garbage Collection Max Pause time is very high like  more than 5-7 Seconds for a 2 GB heap then you need to worry about it. 😉
NOTE: Garbagecat  is a best utility to generate the Garbage Collection Report for Sun JDK and Open JDK for other JDKs you should use other tools for accurate results.
.
.
Thanks
Jay SenSharma

High CPU Utilization Finding Cause?

Hi All,

Jay SenSharma

Jay SenSharma

High CPU utilization is a very very common thing for an Application Server Administrator. Almost every week or quarter or may be every day we can see some High CPU utilization by the Application Server. It is very important for an Administrator or System Admin or a Application Server Support Person to find out what is causing the High CPU.

.
High CPU may cause System Crash or Server Crash or Slow Responsiveness of Server. So we need to find out which Thread is actually consuming more CPU cycles this will help us to find out whether the Thread is processing some application code ….there may be a code bug or it may be Application Framework bug as well…etc

.
So here we are going to see a very simple demonstration of generating High CPU and then we will see How to Analyze High CPU utilization. For this purpose we are going to use 2 very basic utilities

.
1). jps: to know How to use JPS utility please refer to : http://middlewaremagic.com/weblogic/?p=2291
2). top: This is an Operating System Utility .. Please refer to “man” (Manual of your OS like Linux/Solaris)
3). jstack: to know how to use jstack please refer to : http://middlewaremagic.com/weblogic/?p=2281

Generating High CPU

Step1). Create a Simple Web Application with the following JSP code:
“HighCpuGenerator.jsp”


<%
for (int i=0; i < 3; i++)
    {
       Thread x=new Thread(new Runnable(){

                  public void run()
                    {
                       System.out.println("Thread " +Thread.currentThread().getName() + " started");
                       double val=10;
                       for (;;)
                         {
                            Math.atan(Math.sqrt(Math.pow(val, 10)));
                         }
                     }
              });
 
        x.start();
    }
%>

<h3>High CPU generation ....Please collect the 4-5 times "Top" command Output and the 4-5 ThreadDumps.</h3>

Step2). Now Deploy your Application which is having this JSP.
Step3). Hit the Application using “http://localhost:7001/HighCpuWebApp/HighCpuGenerator.jsp

Analyzing High CPU:

Step4). Open a shell prompt and then get the Servers Process ID using “jps” utility which comes with Jdk1.5 and Higher inside the bin directory.

[jsenshar@jsenshar ~]$ export PATH=/home/jsenshar/MyJdks/jdk1.6.0_21/bin:$PATH
[jsenshar@jsenshar ~]$ jps -v

HighCpu_Collect5ing Process ID using JPS

HighCpu_Collect5ing Process ID using JPS

Step5). Now In the same command prompt run the “JStack” utility to collect some Thread Dumps in a File… Suppose if the Application Servers Process ID is “5398” which we got in previous step.

[jsenshar@jsenshar ~]$ jstack -l 5398 > ThreadDumps.log
[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log
[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log
[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log
[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log
HighCpu_ThreadDumps_JStack

HighCpu_ThreadDumps_JStack

Step6). Now In Parallel to collecting the Thread Dumps please collect the “top” commands output as well….like
(NOTE: Make sure that u collect the Thread Dumps and the Top commands results in Parallel whenever u observe any kind of High CPU utilization or Server Slow response)

[jsenshar@jsenshar HighCpu]$ top -H -b -p 5398

HighCPU_Top_Report

HighCPU_Top_Report

You will see some results like this :

top - 02:52:09 up 18:08,  4 users,  load average: 3.49, 3.25, 8.02
Tasks:  51 total,   6 running,  45 sleeping,   0 stopped,   0 zombie
Cpu(s): 96.6%us,  0.7%sy,  0.0%ni,  2.6%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:   3848964k total,  3352224k used,   496740k free,    50940k buffers
Swap:  4194296k total,   400804k used,  3793492k free,  1116028k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 5522 jsenshar  20   0 2884m 412m  19m R 77.8 11.0  40:00.46 java
 5521 jsenshar  20   0 2884m 412m  19m R 66.9 11.0  39:57.34 java
 6900 jsenshar  20   0 2884m 412m  19m R 65.2 11.0   0:07.82 java
 5520 jsenshar  20   0 2884m 412m  19m R 54.2 11.0  39:57.70 java

Step7). Now U will observe that there are some Thread IDs which are consuming more CPU Cycles like Child Thread PID=5522 is consuming 77.8% of CPU similarly Child Thread PID 5521 is consuming 66.9 % of CPU Cycles. These are very Hign CPU utilization Threads inside the Main Parent Process ID 5398.

Step8). Now convert those PIDs into Hexadecimal values…..Example     the Hex Decimal Value for     5522 will be      1592. So now please open the Thread Dump and then find out the word 1592

Decimal Value of the Thread ID provided by OS

Decimal Value of the Thread ID provided by OS

Converted the Decimal Thread ID Value to Hexa Decimal Code

Converted the Decimal Thread ID Value to Hexa Decimal Code

"Thread-17" daemon prio=10 tid=0x00007fe824439800 nid=0x1592 runnable [0x00007fe7fa9e2000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.StrictMath.atan(Native Method)
        at java.lang.Math.atan(Math.java:187)
        at jsp_servlet.__highcpugenerator$1.run(__highcpugenerator.java:83)
        at java.lang.Thread.run(Thread.java:619)

Here you will see that The Thread with id=0x1592 is actually causing the High CPU …Now u can tell your Developers to check the Stack Trace of this Thread so that they can correct their Application Code or If you see any API Code or Framework code there then you know what u need to do and where the problem is.

Like in above case u can see that  My JSPs code is actually causing High CPU    “at jsp_servlet.__highcpugenerator$1.run(__highcpugenerator.java:83)

.

.

Thanks

Jay SenSharma


Copyright © 2010-2012 Middleware Magic. All rights reserved. |