High System CPU Time

[hamilrk1]

On our production app servers I'm seeing high system cpu time as compared with user cpu time. The ration is 1:1 which I feel can be improved upon ... Yes?/No?

We're running apache and JBoss on the same server with mod_jk connector and have narrowed the high system cpu time down to the JBoss process (JVM). I'm just starting to take a look inside JBoss and the JVM to see what's up and figured I'd drop a quick line in the forums too...

The System/User load increases evenly @ 1:1 directly related to load. The server is pushing around 4 Mbps. Apache is snoozing...

Looking for suggestions on where/how to look at what is going on.

Server is dual proc with 2 Gig
OS is REL4.5 with latest patches
JVM is:

java version "1.5.0_11"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_11-b03)
Java HotSpot(TM) Server VM (build 1.5.0_11-b03, mixed mode)
JBoss version 4.0.4GA(build: CVSTag=JBoss_4_0_4_GA date=200605151000)

Snapshot of the heap from one of the app servers below:

[root@app3 ~]# jmap -heap 20166
Attaching to process ID 20166, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_11-b03

using thread-local object allocation.
Parallel GC with 4 thread(s)

Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 536870912 (512.0MB)
NewSize = 655360 (0.625MB)
MaxNewSize = 4294901760 (4095.9375MB)
OldSize = 1441792 (1.375MB)
NewRatio = 8
SurvivorRatio = 8
PermSize = 16777216 (16.0MB)
MaxPermSize = 67108864 (64.0MB)

Heap Usage:
PS Young Generation
Eden Space:
capacity = 58458112 (55.75MB)
used = 6423064 (6.125511169433594MB)
free = 52035048 (49.624488830566406MB)
10.987463981046805% used
From Space:
capacity = 524288 (0.5MB)
used = 98304 (0.09375MB)
free = 425984 (0.40625MB)
18.75% used
To Space:
capacity = 524288 (0.5MB)
used = 0 (0.0MB)
free = 524288 (0.5MB)
0.0% used
PS Old Generation
capacity = 313262080 (298.75MB)
used = 118485440 (112.99652099609375MB)
free = 194776640 (185.75347900390625MB)
37.82310326229079% used
PS Perm Generation
capacity = 40894464 (39.0MB)
used = 29614816 (28.242889404296875MB)
free = 11279648 (10.757110595703125MB)
72.41766513922276% used
[root@app3 ~]#


From JMX Console - listThreadCpuUtilization() shows TP-Processorxxx at the top of the list.


TP-Processor26 86810
TP-Processor71 86160
TP-Processor15 85450
TP-Processor9 85390
TP-Processor49 85370
TP-Processor78 85230
TP-Processor158 85000
TP-Processor14 84670
TP-Processor27 84590
TP-Processor53 84440
TP-Processor93 84310
TP-Processor58 84290
TP-Processor47 83700
TP-Processor75 83670
TP-Processor126 83410
TP-Processor135 83380
TP-Processor149 83020
TP-Processor122 82960
TP-Processor89 82920
TP-Processor163 82670
TP-Processor175 82440
TP-Processor63 82240
TP-Processor164 82000
TP-Processor37 81750
TP-Processor150 81700
TP-Processor100 81680
TP-Processor96 81640
TP-Processor174 81630
TP-Processor86 81520
...
about 200 or so threads total

These threads all have the same makeup:

Thread: TP-Processor26 : priority:5, demon:true, threadId:75, threadState:RUNNABLE, threadLockName:null

java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
java.io.BufferedInputStream.read(BufferedInputStream.java:313)
org.apache.jk.common.ChannelSocket.read(ChannelSocket.java:607)
org.apache.jk.common.ChannelSocket.receive(ChannelSocket.java:545)
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:672)
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
java.lang.Thread.run(Thread.java:595)


Thanks,

-Rob

[peterj]

Two suggestions.

1) Set -Xms and -Xmx to the same size - this prevents the JVM from asking the OS for more memory, which can case the system time to go up.

2) Set the NewSize to 1/3 or 1/4 of your heap size. With a heap of 512MB, set -XX:newSize=150MB and -XX:MaxNewSize=150MB.

If the server is dedicated to running the application server, I would set heap to 1200MB and NewSize to 300MB. Those are usually good starting numbers for a system that has 2GB RAM.

[hamilrk1]

Implemented each of the suggestions in 1 and 2 and also went up to 1024/250 with really no noticed improvement in the ratio. I'll keep tweaking but I'm wondering, does everyone else see a similar ratio between user and system cpu time?

Thanks,

-Rob

[hamilrk1]

Interesting there are no other takers on this ... Nobody else is seeing high system time (1:1 with User cpu time)?

I separated apache and Jboss to different physical boxes and the problem followed jboss/jvm. So under load, apache is truely snoozing...

I'm looking into things like strace, oprofile, gdb, etc. now to try and figure out what is happening inside the JVM.

Might also consider JRockit as it supposedly has some nice features for peering inside the JVM ... Anyone have any thoughts on what the best approach would be for getting insight into the JVM or the JBoss microkernel?

Of course it could be the code too ... My developers are resisting.. :)

[peterj]

Getting a few thread dump might help pinpoint where in the application the problem is. I recall helping one customer whose system was showing 80% CPU usage when no sessions were active. Turns out that the application code had an infinite loop, and three of the requests were in that loop. Doing several dumps in a row an noticing that those three threads were still in the same code after a couple of minutes helped to pinpoint the problem.

[hamilrk1]

Hey Pete,

We did take a closer look at some of the TP-Processorxxx threads and that got the developers thinking it might be their code. We've now isolated it to our application code.

Now the real fun begins...

-Rob

[hamilrk1]

Found the problem in the custom application code. Apparently there was a system call to get the system time which was executing 1000's of times per transaction ... :)

Thanks for all the assist/ideas ....