jQuery in Action, 2nd edition*
The moose likes Performance and the fly likes High CPU utilization for Java Web App Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login


Win a copy of The Java EE 7 Tutorial Volume 1 or Volume 2 this week in the Java EE forum
or jQuery UI in Action in the JavaScript forum!
JavaRanch » Java Forums » Java » Performance
Bookmark "High CPU utilization for Java Web App" Watch "High CPU utilization for Java Web App" New topic
Author

High CPU utilization for Java Web App

Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52
- We are running our Webapp on tomcat 6 .

- Its developed on Spring MVC, hibernate, (c3po db pool)

- Its running on Java 1.5.

- The machine is Linux OS with 4GB RAM and 4 CPUs.

- We are running the app with max 1.5GB heap size.

Our application is not doing lot of processing its just a simple webapp accessing oracle db and has almost 150users/per hour load.

But as soon as we start the app and check the top processes, its taking almost 100% of 2 out of 4 CPUs.

and after few days of use it reached almost 100% on all CPUs.

I could see 250 threads running at that time,

We are trying to investigate, with different options.

Any suggestions or pointers to investigate would help.

I would like to know you approach and ideas to go about this investigation.


Priya - Mockup Tool | Java | Struts2 | Lucene
Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52
Also not more info.

When we check the memory utilization its not using full heap memory and the machine is not doing lots of swapping also. So I assume its not GC which may be eating CPU.

Can this be Connection pool here are the settings I have

<bean id="myDataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource" destroy-method="close">
<property name="user" value="${hibernate.username}" />
<property name="password" value="${hibernate.password}" />
<property name="driverClass" value="${hibernate.driver}" />
<property name="jdbcUrl" value="${hibernate.url}" />
<property name="initialPoolSize" value="20" />
<property name="maxPoolSize" value="250" />
<property name="minPoolSize" value="20" />
<property name="acquireIncrement" value="20" />
<property name="acquireRetryAttempts" value="5" />
<property name="maxConnectionAge" value="7200" />
</bean>
Ernest Friedman-Hill
author and iconoclast
Marshal

Joined: Jul 08, 2003
Posts: 24183
    
  34

Well, do the threads have names? Do you have any stack traces? What are the threads doing?


[Jess in Action][AskingGoodQuestions]
Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52
Here are the top 5 threads from stack...Most of them look like waiting on something....

=====================================

Thread 213 (Thread 1697876896 (LWP 32471)):
#0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0xb7fd3cf6 in pthread_cond_wait@@GLIBC_2.3.2 ()
#2 0xb7fd436e in pthread_cond_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0
#3 0xb78ee7b9 in os::Linux::safe_cond_wait ()
#4 0xb78d5d91 in Monitor::wait ()
#5 0xb76c2c77 in GCTaskManager::get_task ()
#6 0xb76c3eb5 in GCTaskThread::run ()
#7 0xb78ef6f8 in _start ()
#8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
#9 0xb7f6396e in clone () from /lib/tls/libc.so.6
Thread 212 (Thread 1697348512 (LWP 32472)):
#0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0xb7fd3cf6 in pthread_cond_wait@@GLIBC_2.3.2 ()
#2 0xb7fd436e in pthread_cond_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0
#3 0xb78ee7b9 in os::Linux::safe_cond_wait ()
#4 0xb78d5d91 in Monitor::wait ()
#5 0xb76c2c77 in GCTaskManager::get_task ()
#6 0xb76c3eb5 in GCTaskThread::run ()
#7 0xb78ef6f8 in _start ()
#8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
#9 0xb7f6396e in clone () from /lib/tls/libc.so.6
Thread 211 (Thread 1696820128 (LWP 32473)):
#0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0xb7fd3cf6 in pthread_cond_wait@@GLIBC_2.3.2 ()
#2 0xb7fd436e in pthread_cond_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0
#3 0xb78ee7b9 in os::Linux::safe_cond_wait ()
#4 0xb78d5d91 in Monitor::wait ()
#5 0xb76c2c77 in GCTaskManager::get_task ()
#6 0xb76c3eb5 in GCTaskThread::run ()
#7 0xb78ef6f8 in _start ()
#8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
#9 0xb7f6396e in clone () from /lib/tls/libc.so.6
Thread 210 (Thread 1696291744 (LWP 32474)):
#0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0xb7fd3cf6 in pthread_cond_wait@@GLIBC_2.3.2 ()
#2 0xb7fd436e in pthread_cond_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0
#3 0xb78ee7b9 in os::Linux::safe_cond_wait ()
#4 0xb78d5d91 in Monitor::wait ()
#5 0xb76c2c77 in GCTaskManager::get_task ()
#6 0xb76c3eb5 in GCTaskThread::run ()
#7 0xb78ef6f8 in _start ()
#8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
#9 0xb7f6396e in clone () from /lib/tls/libc.so.6
Thread 209 (Thread 1695763360 (LWP 32475)):
#0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0xb7fd3f7c in pthread_cond_timedwait@@GLIBC_2.3.2 ()
#2 0xb7fd43f5 in pthread_cond_timedwait@GLIBC_2.0 ()
#3 0xb78ee95c in os::Linux::safe_cond_timedwait ()
#4 0xb78d5e41 in Monitor::wait ()
#5 0xb79d1e8b in VMThread::loop ()
#6 0xb79d1af0 in VMThread::run ()
#7 0xb78ef6f8 in _start ()
#8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
#9 0xb7f6396e in clone () from /lib/tls/libc.so.6
Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52
This thread looks a little different then others .... but not sure what it is doing?

=============================

Thread 7 (Thread 1471003552 (LWP 397)):
#0 0xb15ac662 in ?? ()
#1 0x00000020 in ?? ()
#2 0x00000040 in ?? ()
#3 0x8a415d70 in ?? ()
#4 0x6585eb68 in ?? ()
#5 0x6585eb68 in ?? ()
#6 0x8a415e00 in ?? ()
#7 0x0000003f in ?? ()
#8 0x00000040 in ?? ()
#9 0x8a412780 in ?? ()
#10 0x8a415e00 in ?? ()
#11 0x00000003 in ?? ()
#12 0xb1641358 in ?? ()
#13 0xfffd323c in ?? ()
#14 0x0000001c in ?? ()
#15 0x0000001c in ?? ()
#16 0xffc2c28c in ?? ()
#17 0x08482988 in ?? ()
#18 0xfffd323c in ?? ()
#19 0x57ada1f0 in ?? ()
#20 0xb1e84c48 in ?? ()
#21 0xad736b38 in ?? ()
#22 0xad722a10 in ?? ()
#23 0xad737f88 in ?? ()
#24 0xad722a10 in ?? ()
#25 0x85fe23d0 in ?? ()
#26 0x08482988 in ?? ()
#27 0xad736b38 in ?? ()
#28 0xad737f88 in ?? ()
#29 0x57ada22c in ?? ()
#30 0x00000000 in ?? ()
Ernest Friedman-Hill
author and iconoclast
Marshal

Joined: Jul 08, 2003
Posts: 24183
    
  34

Generally it's the Java stack traces that are going to be more useful in diagnosing Java server operation.
Tim Holloway
Saloon Keeper

Joined: Jun 25, 2001
Posts: 16019
    
  20

Actually, they appear to be Garbage Collector threads, with the rather odd attribute that they're invoking tls (secure socket) thread services.

Which may or may not mean anything. If these are waiting threads, they might have no bearing on the problem.

The first thing to determine is where the CPU is being burned up. Is it in kernel services or app code? If it's in kernel services, you may need to tune some kernel parameters or change how the app requests those services. Application code is under your control, so you have a lot more options there.

As Ernest said, you need to collect some Java profiling information. I believe you can switch that on by setting JAVA_OPTS before starting Tomcat. It's possible to take snapshots by sending the appropriate signal to Tomcat's JVM when the problem occurs. The profiler will drag down performance, but if it tells you what you need to know, it will be worth it.

There are some commercial tools that can analyze the profile dumps, although if your employer is cheap, like mine was, you can sort through the raw profile info yourself at the cost of some extra time and detective work.

250 system threads is probably not unreasonable. 250 Java threads may or may not be.

Database access is pretty much I/O bound, so performance problems there are usually lots of wait time, not lots of CPU time. I've heard it stated that excessive use of encryption can be a CPU drag on network I/O, but the source was someone with a lot of odd notions, and I'd buy better hardware before turning off essential security. A lot of encryption can be done in hardware these days, anyway.


Customer surveys are for companies who didn't pay proper attention to begin with.
Carey Evans
Ranch Hand

Joined: May 27, 2008
Posts: 225

In the context of Linux, TLS often means Thread-Local Storage, not Transport Layer Security. There's a different version of the GNU C Library for new enough versions of the Linux kernel, which is why /lib/tls/ is showing in the stack trace.

You can use JConsole, JVisualVM or kill -QUIT to get the Java stack traces corresponding to the Linux threads.
Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52
Thanks everyone, I am still trying to figure out things.

I am not able to reproduce the same on my local setup and other env. so have tough time understanding why this is happening.

When I see the linux light weight processes the Thread 7 is taking lots of CPU cycles as compared to others. Almost 90% of 2 CPUs is used by this thread.

Thread 7 (Thread 1471003552 (LWP 397)):
#0 0xb15ac662 in ?? ()
Carey Evans
Ranch Hand

Joined: May 27, 2008
Posts: 225

You should be able to use the jstack tool to get a Java thread dump on the running machine which, as Ernest has said, is much more useful. The "nid" value in the jstack thread dump is the hexadecimal version of the "LWP" value in the Linux thread dump, so you can match the stack traces in each thread dump.
Tim Holloway
Saloon Keeper

Joined: Jun 25, 2001
Posts: 16019
    
  20

Originally posted by Carey Evans:
In the context of Linux, TLS often means Thread-Local Storage, not Transport Layer Security.


I love recycled acronyms. :roll:

Jstack hooks into the Java profiler, so my earlier advice still applies - just with some extra options on how to take advantage of it.

You really need to find out what your Java stack is before worrying about the binary stack!
William Brogden
Author and all-around good cowpoke
Rancher

Joined: Mar 22, 2000
Posts: 12769
    
    5
Perhaps if you give each Java Thread a distinct name as it is created it will be easier to figure out what is going on.

Bill
Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52
jstack is cool, I am able to match the java stack for the linux lwp ....
looks like there is a property editor used in our code which is killing us...
will update the exact findings soon.

Thanks a lot everyone...
[ December 23, 2008: Message edited by: Priyanka Dandekar ]
Priyanka Dandekar
Ranch Hand

Joined: Aug 06, 2008
Posts: 52

For others benefit.....Just replying to this thread cause I created a blog post about several set of commands which can help you in similar situation

I have tried to include all commands that helped during this issue debugging - Most Powerful Unix Commands for Java Performance Debugging


Hope this helps a struggling java developer on google

njoy
rakesh kadulkar
Ranch Hand

Joined: Jul 24, 2008
Posts: 115
Hi Priyanka,

Good Job. It was really helpful.

Regards,
Rakesh k


Rakesh Kadulkar
 
I agree. Here's the link: http://aspose.com/file-tools
 
subject: High CPU utilization for Java Web App