6 Replies Latest reply on Oct 17, 2007 10:05 AM by Rob Hamilton

    High System CPU Time

    Rob Hamilton Newbie

      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

        • 1. Re: High System CPU Time
          Peter Johnson Master

          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.

          • 2. Re: High System CPU Time
            Rob Hamilton Newbie

            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

            • 3. Re: High System CPU Time
              Rob Hamilton Newbie

              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.. :)

              • 4. Re: High System CPU Time
                Peter Johnson Master

                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.

                • 5. Re: High System CPU Time
                  Rob Hamilton Newbie

                  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

                  • 6. Re: High System CPU Time
                    Rob Hamilton Newbie

                    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 ....