Troubleshoot high CPU usage java process

This is a real troubleshooting example that I just did yesterday for a high CPU usage java application. The application uses tomcat and runs on AWS EC2.

1. Login into the box, and change to root user so you can see all users’ process.

   sudo su -

2. Install htop if you have not installed it before, the run it.

   yum -y install htop
   htop

3. Press F6 then choose sort by CPU (or use keyboard shortcut P)

   

4. Press F4 to filter by keyword tomcat

   

5. Press H to turn on/off threads.

   

6. Send thread dump info to log. For tomcat, the log is /var/log/tomcat7/catalina.out. Here I dump the info of thread ID 7328

   kill -3 7328

7. Get the hex value of 7328.

   echo "obase=16; 7328" | bc
   1CA0

8. Search 1ca0 in /var/log/tomcat7/catalina.out. Then I get the info of the java thread 7328. By a quick glance, it should have something to do with the AWS S3 bucket operations. Send the info to developers to look into that pieces of codes to find out why it takes so much CPU time.

"http-bio-8080-exec-425" daemon prio=10 tid=0x00007fa8e046e000 nid=0x1ca0 runnable [0x00007fa8c94cf000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:442)
at sun.security.ssl.InputRecord.read(InputRecord.java:480)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:934)
- locked <0x00000000d62bcaf0> (a java.lang.Object)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:891)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:102)
- locked <0x00000000d62bc6d0> (a sun.security.ssl.AppInputStream)
at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:160)
at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:84)
at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:273)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:260)
at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:283)
at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:251)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:197)
at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:271)
at com.amazonaws.http.protocol.SdkHttpRequestExecutor.doReceiveResponse(SdkHttpRequestExecutor.java:66)
at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:682)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:486)
at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:464)
at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:273)
at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3645)
at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3597)
at com.amazonaws.services.s3.AmazonS3Client.listObjects(AmazonS3Client.java:621)
at newsapi.provider.aws.S3BlobStorageProvider.deleteByIdPrefix(S3BlobStorageProvider.java:173)
at newsapi.service.image.ImageUpdateServiceImpl.removeFromBlobRepository(ImageUpdateServiceImpl.java:84)
at newsapi.service.image.ImageUpdateServiceImpl.updateImages(ImageUpdateServiceImpl.java:53)
at newsapi.service.ContentIngestionServiceImpl.storeContent(ContentIngestionServiceImpl.java:711)
at newsapi.service.ContentIngestionServiceImpl.storeRelatedContent(ContentIngestionServiceImpl.java:844)
at newsapi.service.ContentIngestionServiceImpl.processContent(ContentIngestionServiceImpl.java:390)
at newsapi.service.ContentIngestionServiceImpl.addContentForDocument(ContentIngestionServiceImpl.java:318)
at newsapi.service.ContentIngestionServiceImpl.processDocument(ContentIngestionServiceImpl.java:174)
at newsapi.controller.DocumentController.processDocument(DocumentController.java:406)
at newsapi.controller.DocumentController.post(DocumentController.java:162)
at sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.threewks.thundr.action.method.MethodAction.invoke(MethodAction.java:60)
at com.threewks.thundr.action.method.MethodActionResolver.invokeAction(MethodActionResolver.java:121)
at com.threewks.thundr.action.method.MethodActionResolver.resolve(MethodActionResolver.java:101)
at com.threewks.thundr.action.method.MethodActionResolver.resolve(MethodActionResolver.java:47)
at com.threewks.thundr.route.Routes.resolveAction(Routes.java:117)
at com.threewks.thundr.route.Routes.invoke(Routes.java:97)
at com.threewks.thundr.ThundrServlet.applyRoute(ThundrServlet.java:122)
at com.threewks.thundr.ThundrServlet.service(ThundrServlet.java:161)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at newsapi.util.filter.CacheFilter.doFilter(CacheFilter.java:93)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:683)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)
- locked <0x00000000d144da00> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)