Finding the Bad Apple in JVM

If you run into situation where you have to troubleshoot a JVM that consumes high CPU and you have absolutely no idea whats causing it, here are some very useful tricks that saved my life countless time.

top:
Most of us use Top often but there are some handy params that can be even more helpful.

First Do a top to get the Cpu Hungry process id.

#top
top - 14:33:22 up 42 days, 7:11, 2 users, load average: 1.60, 1.62, 1.56
Tasks: 154 total, 1 running, 153 sleeping, 0 stopped, 0 zombie
Cpu(s): 77.8%us, 0.8%sy, 0.0%ni, 21.5%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 8061328k total, 7545548k used, 515780k free, 134776k buffers
Swap: 2097148k total, 162800k used, 1934348k free, 798096k cached</code>

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
12058 root 20 0 13.3g 4.7g 21m S 302.0 61.5 41219:31 java
18205 root 20 0 4273m 948m 6244 S 11.3 12.0 1704:03 java
12056 root 20 0 22032 1080 920 S 0.7 0.0 62:33.48 wrapper-linux-x
1 root 20 0 19356 1244 1052 S 0.0 0.0 0:03.22 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd

Ok, clearly, the process with PID 12058 isn’t behaving properly.

Lets ask ‘top’ to list the child-process (one to one binding with each thread in JVM) for PID 12058

-H Flags turns on the Threads Toggle
-H : Threads toggle
Starts top with the last remembered ’H’ state reversed. When this toggle is On, all individual threads will be displayed. Other-
wise, top displays a summation of all threads in a process.

## top -p 12058 -H (-p only lists child process for 12058 )

&nbsp;

[mule@FSASYDESBPROD02 ~]# top -p $PID -H
top - 15:09:49 up 42 days, 7:48, 2 users, load average: 1.34, 1.50, 1.54
Tasks: 5359 total, 3 running, 5356 sleeping, 0 stopped, 0 zombie
Cpu(s): 77.8%us, 1.2%sy, 0.0%ni, 20.9%id, 0.0%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 8061328k total, 7740576k used, 320752k free, 135436k buffers
Swap: 2097148k total, 162652k used, 1934496k free, 833864k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
28255 root 20 0 13.3g 4.9g 21m R 98.3 63.3 10163:33 java
14064 root 20 0 13.3g 4.9g 21m R 97.7 63.3 14089:00 java
14062 root 20 0 13.3g 4.9g 21m R 97.4 63.3 14073:55 java
925 root 20 0 13.3g 4.9g 21m S 1.9 63.3 279:22.62 java
12060 root 20 0 13.3g 4.9g 21m S 0.6 63.3 108:39.51 java

Ok, so Thread $28255 & $14064 is doing a lot of stuff. How do we know what they are doing??

jstack in rescue !

"AsyncLoggerConfig-1" daemon prio=10 tid=0x00007f45ec2ab000 nid=0x2f27 waiting on condition [0x00007f45e1e22000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:123)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

In the jstack trace, the nid=0x2f27 is the hex of the pid we received before. So lets awk it!

bash# PID=12058
bash# NID=28255
bash# jstack $PID | awk '/ nid='"$(printf '%#x' $NID)"' /,/^$/'</code>

"pool-1140-thread-1" prio=10 tid=0x00007f45706b4000 nid=0x6e5f runnable [0x00007f453247a000]
java.lang.Thread.State: RUNNABLE
at sun.reflect.Reflection.getCallerClass0(Native Method)
at sun.reflect.Reflection.getCallerClass(Reflection.java:69)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.logging.log4j.util.ReflectionUtil.getCallerClass(ReflectionUtil.java:123)
at org.apache.logging.log4j.util.ReflectionUtil.getCallerClass(ReflectionUtil.java:230)
at org.apache.logging.log4j.jul.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:34)
at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42)
at org.apache.logging.log4j.jul.LogManager.getLogger(LogManager.java:89)
at java.util.logging.LogManager.demandLogger(LogManager.java:430)
at java.util.logging.Logger.demandLogger(Logger.java:346)
at java.util.logging.Logger.getLogger(Logger.java:393)
at com.orientechnologies.common.log.OLogManager.log(OLogManager.java:103)
at com.orientechnologies.common.log.OLogManager.debug(OLogManager.java:128)
at com.orientechnologies.orient.client.remote.OStorageRemote.useNewServerURL(OStorageRemote.java:1703)
- locked (a java.util.ArrayList)
at com.orientechnologies.orient.client.remote.OStorageRemote.getAvailableNetwork(OStorageRemote.java:1866)
at com.orientechnologies.orient.client.remote.OStorageRemote.openRemoteDatabase(OStorageRemote.java:1608)
at com.orientechnologies.orient.client.remote.OStorageRemote.open(OStorageRemote.java:216)
at com.orientechnologies.orient.client.remote.OStorageRemoteThread.open(OStorageRemoteThread.java:87)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.open(ODatabaseDocumentTx.java:244)
at com.orientechnologies.orient.core.db.OPartitionedDatabasePool$DatabaseDocumentTxPolled.internalOpen(OPartitionedDatabasePool.java:137)
at com.orientechnologies.orient.core.db.OPartitionedDatabasePool.openDatabase(OPartitionedDatabasePool.java:331)
at com.orientechnologies.orient.core.db.OPartitionedDatabasePool.acquire(OPartitionedDatabasePool.java:304)
at com.tinkerpop.blueprints.impls.orient.OrientBaseGraph.(OrientBaseGraph.java:166)
at com.tinkerpop.blueprints.impls.orient.OrientGraphNoTx.(OrientGraphNoTx.java:54)
at com.tinkerpop.blueprints.impls.orient.OrientGraphFactory.getNoTx(OrientGraphFactory.java:93)
at au.com.foxsports.subscription.service.SubscriptionServiceImpl.getSubscribersWithRetry(SubscriptionServiceImpl.java:760)
at au.com.foxsports.subscription.service.SubscriptionServiceImpl.getSubscribers(SubscriptionServiceImpl.java:739)
at au.com.foxsports.subscription.service.SubscriptionServiceImpl$1.call(SubscriptionServiceImpl.java:945)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)

There you go! You can see the 3rd party system eating up the CPU ! In my case its Orientdb. Yes, we faced a lot of issue trying to implement a graph model in orientdb, but thats a story for another day.

Advertisements

Troubleshooting Tomcat deployment problem for jaxws-2.2 application : The Sherlock Holmes way

I just spent my last 3 hour trying to deploy my perfect JAXWS-2.2 application in tomcat 6.0.26. Again I felt so great and thanked God that I took programming as a profession. Sure you don’t get to solve mysterious murder cases like Sherlock Homes, but the things we do are not much different! Where else can you go to work, get a problem with a set of clues, judge / discard / follow each and every clue, follow the trails to come to identify the problem and fix it and get paid for it!

Background:

The application was running happily in Jetty ever since I wrote it three months ago but my client wants to run it in tomcat. It was a standard web application so I thought it will be a child’s play to deploy it in tomcat. Ah! As if I have learned nothing from history! Nothing is child’s play when it comes to deploy an application in a new container, no matter how standard it is! I have learned this lesson hard way from deploying application in tomcat, jetty, jboss, weblogic, glassfish (yeah..i’v been fortunate/unfortunate enough to play with them all) , yet I tend to forget.

Problem 1:
First time I tried to run the app, I ran into the ClassNotFoundException:


SEVERE: WSSERVLET11: failed to parse runtime descriptor: java.lang.NoClassDefFoundError: javax/xml/ws/soap/AddressingFeature$Responses
java.lang.NoClassDefFoundError: javax/xml/ws/soap/AddressingFeature$Responses
	at com.sun.xml.ws.policy.PolicyWSDLGeneratorExtension.loadConfigurators(PolicyWSDLGeneratorExtension.java:459)
	at com.sun.xml.ws.policy.PolicyWSDLGeneratorExtension.start(PolicyWSDLGeneratorExtension.java:111)

..........................

I remember this! This was due to the jaxws-2.2 libraries conflicting with jaxws-2.1 libraries shipped with jdk-1.6! But I had it fixed by placing the latest jaxb-api.jar & jaxws-api.jar into the JDK_HOME/jre/lib/endorsed folder!

Hmm…here is a clue…the library is setup properly in JDK , app is running fine with Jetty with the same JDK, but wouldn’t load in tomcat!! Who is the ‘Usual Suspect’ ? Of course the tomcat classloading framework! Its ignoring the ‘endorsed’ jars configured in JDK ! Ah, at this point I begin to miss my old complex Tomcat 5.5, there was this ‘endorsed’ directory in the ‘common/endorsed’ folder. Where is it in tomcat 6? Luckily I had some old trick under my belt…Quickly Added a ServletContextListener like this:

public class WebappLoadListener implements ServletContextListener {
	private static final Log log = LogFactory.getLog(WebappLoadListener.class);
	public void contextDestroyed(ServletContextEvent arg0) {
	}

	public void contextInitialized(ServletContextEvent arg0) {
		log.info("\n\n\n ENDORSED DIR: " +System.getProperty("java.endorsed.dirs"));		
	}
}

And the output was:

ENDORSED DIR:  /usr/local/development/servers/apache-tomcat-6.0.26/endorsed

How the hack am I supposed to know that, the directory is not even there! Come on tomcat guys, I understand you want to make things simple for the new tomcat adopters, but why screw us – the old 5.5 users!!! Created folder “/usr/local/development/servers/apache-tomcat-6.0.26/endorsed” and copied the latest jars (jaxb-api.jar jaxws-api.jar) in there, got rid of the ClassNotFoundException.

Problem 2:
As soon as I got rid of problem 1, I ran into this:

SEVERE: WSSERVLET11: failed to parse runtime descriptor: java.lang.NoSuchMethodError: com.sun.istack.logging.Logger.getLogger(Ljava/lang/Class;)Lcom/sun/istack/logging/Logger;
java.lang.NoSuchMethodError: com.sun.istack.logging.Logger.getLogger(Ljava/lang/Class;)Lcom/sun/istack/logging/Logger;
	at com.sun.xml.ws.api.config.management.policy.ManagementAssertion.<clinit>(ManagementAssertion.java:87)
	at com.sun.xml.ws.server.MonitorBase.createManagedObjectManager(MonitorBase.java:121)
	at com.sun.xml.ws.server.WSEndpointImpl.<init>(WSEndpointImpl.java:143)
	at com.sun.xml.ws.server.EndpointFactory.createEndpoint(EndpointFactory.java:232)
	at com.sun.xml.ws.api.server.WSEndpoint.create(WSEndpoint.java:505)
	at com.sun.xml.ws.transport.http.DeploymentDescriptorParser.parseAdapters(DeploymentDescriptorParser.java:253)
	at com.sun.xml.ws.transport.http.DeploymentDescriptorParser.parse(DeploymentDescriptorParser.java:147)

Now this got my head spinning! All the clue I got from Google was pointing to ‘Problem 1’…I was also a little confused and headed that way, placed the ‘jaxb-api.jar jaxws-api.jar’ in various locations, with no luck ! Ok, time to give up that trail and think clear. So, it was not a ClassNotFoundException, the class is there, but the Method is not. Why do this sounds familier? Because I have seen it countless times! Its because of two version of same class staying in the classpath and the faulty one getting preference by Tomcat ClassLoader! If you know about tomcat classloading, you know that it creates a ClassLoader for each webapp and the jars in “WEB-INF/lib” are loaded first (by the child classloader). So I must have some jar in my dependency which should not be there…Hmm..how do I know which jar? Wait, I know a way, infact I even blogged about it HERE.

So quickly added this method in my WebappLoadListener:

public static String getClassLocation(Class clazz) {
		if(clazz == null) {
			return null;
		}

		try {
			ProtectionDomain protectionDomain = clazz.getProtectionDomain();
			CodeSource codeSource = protectionDomain.getCodeSource();
			URL location = codeSource.getLocation();
			return location.toString();
		} catch (Throwable e) {
			e.printStackTrace();
			return "Not found";
		}
	}

	public void contextInitialized(ServletContextEvent arg0) {		
		log.error("jar file: " + getClassLocation(com.sun.istack.logging.Logger.class));		
	}

OUTPUT:

ERROR WebappLoadListener:21 - jar file: file:/home/sajid/workspace_test/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/jaxws-sample/WEB-INF/lib/istack-commons-runtime-1.1-SNAPSHOT.jar

I got you “Professor Moriarty” (in case you are not familiar with Sherlock Holmes, Professor Moriarty is the common villain)! How did you got in my LIB folder ! The very name “istack-commons-runtime-1.1-SNAPSHOT.jar” suggests that I should not bundle it in my app! I deleted the jar manually and ran the code. Ah! Sweet. At last my code deployed in tomcat and all my SOAP-UI tests(only Three to be honest) are passed! And where is the class loaded from now?

ERROR WebappLoadListener:21 - jar file: file:/home/sajid/workspace_test/.metadata/.plugins/org.eclipse.wst.server.core/tmp0/wtpwebapps/jaxws-sample/WEB-INF/lib/jaxb-impl-2.2.jar

See! The right class is supplied with the jaxb-impl Jar.

Now, back to the old question, how did istack-commons-runtime-1.1-SNAPSHOT.jar ended up in my library? Did a quick ‘Dependency Graph’ in eclipse

So I added an exclusion rule in the dependency of jaxws-rt:


		<dependency>
			<groupId>com.sun.xml.ws</groupId>
			<artifactId>jaxws-rt</artifactId>
			<version>2.2</version>
			<exclusions>
				<exclusion>
					<groupId>com.sun.istack</groupId>
					<artifactId>istack-commons-runtime</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

Ran all the tests and everything seemed to be OK. I feel so lucky that I spent time writing those SOAP-UI test cases (at the time it felt like complete waste of time)! Otherwise, I’d have to test the application manually to see if anything was broken by this.

Conclusion:
I see now why newbies like to adopt those exotic Ruby framework instead of Java. Imagine someone trying to build a webservice using JAX-WS. As if the api specs are not confusing enough, he has to go through all these pain to run the app! I feel sorry for the poor guy if he starts with tomcat, he would have no clue that its not his code’s fault that the app is not running. Luckily I started with Jetty, not because I was wise but because the client wanted it in Jetty.

But did I have fun going through all these pain? I sure did 🙂 . Good to know that I still get a kick out of fixing these weird problems, no matter how many times I did it before.

Exporting Spring Beans as JMX Mbeans

If you always want to stay on top of your production system and always want to know whats going on in your APP, you would want to configure JMX for your application.

First you need to start your JVM with the following parameters to enable any JMX client to connect to your system.

-Dcom.sun.management.jmxremote.port=8888 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false

This is just done without any security but in production, you would want to add authentication.

Now, add these configuration for your spring APP to automatically expose your Spring Beans as MBeans if they have the right annotations.

	<bean id="exporter" class="org.springframework.jmx.export.MBeanExporter"
		lazy-init="false">
		<property name="autodetect" value="true"></property>
		<property name="namingStrategy" ref="namingStrategy"></property>
		<property name="assembler" ref="assembler"></property>		
		<property name="server" ref="mbeanServer"></property>		
	</bean>

	<bean id="assembler"
		class="org.springframework.jmx.export.assembler.MetadataMBeanInfoAssembler">
		<property name="attributeSource" ref="attributeSource" />
	</bean>

	<bean id="namingStrategy"
		class="org.springframework.jmx.export.naming.MetadataNamingStrategy">
		<property name="attributeSource" ref="attributeSource" />
	</bean>

	<bean id="mbeanServer" class="java.lang.management.ManagementFactory" factory-method="getPlatformMBeanServer"/>	

The ‘exporter’ will inspect all your defined Spring Beans in your configuration and see if the have Spring JMX annotations. Now you need to define your beans with Annotations.

@ManagedResource(objectName = "yourapp:name=log4jLevelChanger", description = "LOG4j Level Changer")
public class Log4jLevelChanger  {
	private static final Log log = LogFactory.getLog(Log4jLevelChanger.class);
	
	public void init() throws AttributeNotFoundException, InstanceNotFoundException, MBeanException, ReflectionException {
		ArrayList<MBeanServer> servers = MBeanServerFactory.findMBeanServer(null);
		for(MBeanServer server : servers) {
			String name = (String) server.getAttribute(MBeanServerDelegate.DELEGATE_NAME,
            "MBeanServerId");	
			
			log.info("found  server: " + name);
		}
	}
	
	/*
	 * (non-Javadoc)
	 * 
	 * @see
	 * com.vantage.callcenter.web.utils.Log4jLevelChanger#setLogLevel(java.lang
	 * .String, java.lang.String)
	 */
	@ManagedOperation
	@ManagedOperationParameters({
	@ManagedOperationParameter(description="Name of the Logger to configure", name="loggerName"),
	@ManagedOperationParameter(description="Level ofthe Logger to set", name="level")
	})
	public void setLogLevel(
			
			String loggerName, 
			
			String level) {
		if ("debug".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.DEBUG);
		} else if ("info".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.INFO);
		} else if ("error".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.ERROR);
		} else if ("fatal".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.FATAL);
		} else if ("warn".equalsIgnoreCase(level)) {
			Logger.getLogger(loggerName).setLevel(Level.WARN);
		}
	}

        //Read the log4j.properties to reconfigure the logging levels.
	@ManagedOperation
	public boolean refreshLogging() {
		try {
			Log4jConfigurer.initLogging("classpath:log4j.properties");			
			return true;
		} catch (FileNotFoundException e) {
			return false;
		}
	}
	
	
	@ManagedOperation
	@ManagedOperationParameters ({
		@ManagedOperationParameter(description="Name of the Logger to get the Level", name="loggerName")	
	})
	public String getLogLevel(
			
			String loggerName) {
		log.debug("getLogLevel -> loggerName: " + loggerName);
		Logger logger = Logger.getLogger(loggerName);
		
		if(logger != null) {
			if(logger.getLevel() != null) {
				return logger.getLevel().toString();
			}
		}
		
		return Logger.getRootLogger().getLevel().toString();
	}
}

and define it in your application-context.xml as a regular bean

<bean id="log4jLevelChanger"  class="com.test.Log4jLevelChanger"></bean>

Thats it! Now you can open any Standard JMX client (JConsole / VisualVM / JManage) to inspect the bean and changing log levels!

You can also add Mbean Annotations to any regular Bean that you wish to inspect at runtime. For example, you can add it to the bean that manages your threadpool to see its utilization at runtime, you can add it to any in memory cache to find out memory leaks. If you think closely, the possibilities can be endless!

How to get the jar file location of a loaded class?

When there are two versions of the same class (same class & package name) in the classpath (may be from two different jars), there is no way to tell the JVM which one to load at runtime (JVM loads the one which it finds first). And there is no direct way of knowing from which jar the class was loaded! This causes enormous difficulties for a j2ee developer when working with different containers.

You can use the following code to find which jar was used to load the class

	public static String getClassLocation(Class clazz) {
		if(clazz == null) {
			return null;
		}
		
		try {
			ProtectionDomain protectionDomain = clazz.getProtectionDomain();
			CodeSource codeSource = protectionDomain.getCodeSource();
			URL location = codeSource.getLocation();
			return location.toString();
		} catch (Throwable e) {
			e.printStackTrace();
			return "Not found";
		}
	}

For example, The if you run the following code,

	public static void main(String[] args) {
		System.out.println("class location of Log: " + getClassLocation(org.apache.commons.logging.Log.class));
	}

It will give you :

class location of Log: file:/C:/dev/tools/maven2/repository/commons-logging/commons-logging/1.1.1/commons-logging-1.1.1.jar

This simple code helped me a lot to resolve a lot of deployment problem in different containers specially when working with third party libs.