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]
Debug
Analyzing Garbage Collection Log
High CPU Utilization Finding Cause?
Hi All,
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
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.
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
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
"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
Multicast Errors in The Server Logs
1). IP Multicasting (One to Many):
2). IP Socketing (One to One):
Multicast Errors:
<Error> <Cluster> <BEA-000110> <Multicast socket receive error: java.io.OptionalDataException java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1285) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:322) at weblogic.cluster.MulticastManager.execute(MulticastManager.java:411) at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:224) at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:183)
<Error> <Cluster> <testWeb> <MS1> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <1264189488263> <BEA-000110> <Multicast socket receive error: java.lang.OutOfMemoryError: PermGen space java.lang.OutOfMemoryError: PermGen space at sun.misc.Unsafe.defineClass(Native Method) at sun.reflect.ClassDefiner.defineClass(ClassDefiner.java:45) at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:381) at java.security.AccessController.doPrivileged(Native Method) at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:377) at sun.reflect.MethodAccessorGenerator.generateSerializationConstructor(MethodAccessorGenerator.java:95) at sun.reflect.ReflectionFactory.newConstructorForSerialization(ReflectionFactory.java:313) at java.io.ObjectStreamClass.getSerializableConstructor(ObjectStreamClass.java:1299) at java.io.ObjectStreamClass.access$1500(ObjectStreamClass.java:52)
<Error> <Cluster> <testDomain> <testServer> <ExecuteThread: '14' for queue: 'weblogic.kernel.Default'> <<WLS Kernel>> <BEA-000110> <Multicast socket receive error: java.io.StreamCorruptedException java.io.StreamCorruptedException at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(ObjectInputStream.java:2347) at java.io.ObjectInputStream$BlockDataInputStream.refill(ObjectInputStream.java:2380) at java.io.ObjectInputStream$BlockDataInputStream.read(ObjectInputStream.java:2452) at java.io.DataInputStream.readInt(DataInputStream.java:443) at java.io.ObjectInputStream$BlockDataInputStream.readInt(ObjectInputStream.java:2657) at java.io.ObjectInputStream.readInt(ObjectInputStream.java:900) at weblogic.cluster.MulticastManager.execute(MulticastManager.java:387)
<Error> <Cluster> <BEA-000110> <Multicast socket receive error: java.io.EOFException java.io.EOFException at java.io.DataInputStream.readFully(DataInputStream.java:178) at java.io.DataInputStream.readLong(DataInputStream.java:380) at java.io.ObjectInputStream$BlockDataInputStream.readLong()J(Unknown Source) at java.io.ObjectInputStream.readLong()J(Unknown Source) at weblogic.cluster.HeartbeatMessage.readExternal(HeartbeatMessage.java:55) at java.io.ObjectInputStream.readExternalData(Ljava.io.Externalizable;Ljava.io.ObjectStreamClass;)V(Unknown Source) at java.io.ObjectInputStream.readOrdinaryObject(Z)Ljava.lang.Object;(Unknown Source)
<Error> <Cluster> <Multicast socket receive error : java.io.InterruptedIOException: Receive timed out java.io.InterruptedIOException: Receive timed out at java.net.PlainDatagramSocketImpl.receive(Native Method) at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:90) at java.net.DatagramSocket.receive(DatagramSocket.java:404) at weblogic.cluster.FragmentSocket.receive(FragmentSocket.java:145) at weblogic.cluster.MulticastManager.execute(MulticastManager.java:298) at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:139) at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
Most Possible Causes of the Multicast Errors ?
What All Things Need to Debug ?
It is Always recommended to first of all go through the following link: http://download.oracle.com/docs/cd/E12840_01/wls/docs103/cluster/multicast_configuration.html
[jaytest@jaytest bin]$ lsof -p 4020 | wc -l 666 [jaytest@jaytest bin]$ lsof -p 4020 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME java 4020 jaytest cwd DIR 253,4 4096 8657973 /NotBackedUp/WLS103/user_projects/domains/base_domain java 4020 jaytest rtd DIR 253,1 4096 2 / java 4020 jaytest txt REG 253,3 50810 133154 /home/jaytest/MyJdks/jdk1.6.0_21/bin/java java 4020 jaytest mem REG 253,1 150672 542805 /lib64/ld-2.12.so java 4020 jaytest mem REG 253,1 1838296 542806 /lib64/libc-2.12.so java 4020 jaytest mem REG 253,1 145672 542818 /lib64/libpthread-2.12.so java 4020 jaytest mem REG 253,1 22536 542808 /lib64/libdl-2.12.so java 4020 jaytest mem REG 253,1 598816 542807 /lib64/libm-2.12.so java 4020 jaytest mem REG 253,1 47072 542819 /lib64/librt-2.12.so java 4020 jaytest mem REG 253,1 113904 542814 /lib64/libresolv-2.12.so java 4020 jaytest mem REG 253,1 116136 542840 /lib64/libnsl-2.12.so java 4020 jaytest mem REG 253,3 6676 133795 /home/jaytest/MyJdks/jdk1.6.0_21/jre/lib/amd64/librmi.so java 4020 jaytest mem REG 253,3 1163700 133902 /home/jaytest/MyJdks/jdk1.6.0_21/jre/lib/resources.jar java 4020 jaytest mem REG 253,3 842216 134434 /home/jaytest/MyJdks/jdk1.6.0_21/jre/lib/ext/localedata.jar java 4020 jaytest mem REG 253,4 282279 8653766 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/console.jar java 4020 jaytest mem REG 253,4 293750 8653774 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/standard.jar java 4020 jaytest mem REG 253,4 779658 8653764 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/beehive-netui-core.jar java 4020 jaytest mem REG 253,4 57299 8653775 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/struts-adapter.jar java 4020 jaytest mem REG 253,4 531676 8653767 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/jh.jar java 4020 jaytest mem REG 253,4 1490143 8653770 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/netuix_servlet.jar java 4020 jaytest mem REG 253,4 54683 8653769 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/netuix_common_web.jar java 4020 jaytest mem REG 253,4 46008 8653772 /NotBackedUp/WLS103/wlserver_10.3/server/lib/consoleapp/consolehelp/WEB-INF/lib/render_taglib.jar
java weblogic.Admin -url t3://localhost:7001 - username weblogic -password weblogic SET -type ServerDebug -property DebugCluster true