Re: High CPU Usage with Apache Portable Runtime

Thu, 21 Sep 2006 07:10:10 -0700 

Using Dtrace , I tried to gather some more information.
Here is the output of a Dtrace script called dapptrace.
It confirms the fact that the tomcat thread spends its cpu time in the Poll functions however I still don't understand why listening to events on port can't use so much cpu. 
Any hint or clue on how I could understand the reason of this behaviour ?


PID/LWP   RELATIVE  ELAPSD    CPU CALL(args)             = return
1736/16: 5211128 . . -> libtcnative-1.so.0.1.3:Java_org_apache_tomcat_jni_Poll_poll(0x876717C, 0xD4CCFC44, 0x8 
7086B8)
21736/16: 5211131 . . -> libapr-1.so.0.2.7:apr_pollset_poll(0x86BD6E0, 0x7D0, 0x0) 21736/16: 5211133 . . -> libc.so.1:__div64(0x7D0, 0x0, 0xF4240) 21736/16: 5211134 . . -> libc.so.1:divmod64(0xD8FF5680, 0xD5208246, 0x7D0) 21736/16: 5211134 13 0 <- libc.so.1:divmod64 = 48 21736/16: 5211135 37 2 <- libc.so.1:__div64 = 47 21736/16: 5211136 . . -> libc.so.1:__div64(0x7D0, 0x0, 0x3E8) 21736/16: 5211136 . . -> libc.so.1:divmod64(0xD8FF5680, 0xD5208265, 0x7D0) 21736/16: 5211137 13 0 <- libc.so.1:divmod64 = 48 21736/16: 5211137 36 1 <- libc.so.1:__div64 = 47 21736/16: 5211138 . . -> libc.so.1:__rem64(0x2, 0x0, 0x3E8) 21736/16: 5211139 . . -> libc.so.1:divmod64(0x2, 0xD520827D, 0x2) 21736/16: 5211140 13 0 <- libc.so.1:divmod64 = 48 21736/16: 5211140 37 2 <- libc.so.1:__rem64 = 88 21736/16: 5211143 . . -> libc.so.1:port_getn(0x17, 0x86BF6B0, 0x2000) 21736/16: 5211145 . . -> libc.so.1:_portfs(0x6, 0x17, 0x86BF6B0) 21736/16: 5211150 19 5 <- libc.so.1:_portfs = 13 21736/16: 5211151 . . -> libc.so.1:___errno(0x86BD6E0, 0xD522284C, 0x0) 21736/16: 5211151 13 0 <- libc.so.1:___errno = 32 21736/16: 5211152 68 9 <- libc.so.1:port_getn = 112 21736/16: 5211153 . . -> libc.so.1:___errno(0x7D0, 0xD8FF5680, 0xD52749E4) 21736/16: 5211153 12 0 <- libc.so.1:___errno = 32 21736/16: 5211154 261 22 <- libapr-1.so.0.2.7:apr_pollset_poll = 1297 21736/16: 5211154 295 25 <- libtcnative-1.so.0.1.3:Java_org_apache_tomcat_jni_Poll_poll = 525 

Yann

Yann Rouillard a écrit :
Yes from what I understand a native call is used when you use the apache portable runtime with tomcat. 

Yann

David Delbecq a écrit :

Nice, in a native call :/

"ajp-8009-Poller-0" daemon prio=5 tid=0x087670e0 nid=0x10 runnable
[0xd4ccf000..0xd4ccfd98]
    at org.apache.tomcat.jni.Poll.poll(Native Method)
    at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1153)
    at java.lang.Thread.run(Thread.java:534)

can't help you then :)

Yann Rouillard a écrit :

Here is the jvm thread dump:

Full thread dump Java HotSpot(TM) Client VM (1.4.2_11-b06 mixed mode):

"ajp-8009-3" daemon prio=5 tid=0x083ee530 nid=0x12 in Object.wait()
[0xd4c4b000..0xd4c4bd98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd5e5c1f8> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at java.lang.Object.wait(Object.java:429)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1255) 

    - locked <0xd5e5c1f8> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1280)
    at java.lang.Thread.run(Thread.java:534)

"ajp-8009-2" daemon prio=5 tid=0x087813b0 nid=0x11 in Object.wait()
[0xd4c8d000..0xd4c8dd98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd62a0060> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at java.lang.Object.wait(Object.java:429)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1255) 

    - locked <0xd62a0060> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1280)
    at java.lang.Thread.run(Thread.java:534)

"ajp-8009-Poller-0" daemon prio=5 tid=0x087670e0 nid=0x10 runnable
[0xd4ccf000..0xd4ccfd98]
    at org.apache.tomcat.jni.Poll.poll(Native Method)
    at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1153)
    at java.lang.Thread.run(Thread.java:534)

"ajp-8009-1" daemon prio=5 tid=0x087646c0 nid=0xf in Object.wait()
[0xd4d11000..0xd4d11d98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd906b2c0> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at java.lang.Object.wait(Object.java:429)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1255) 

    - locked <0xd906b2c0> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1280)
    at java.lang.Thread.run(Thread.java:534)

"ajp-8009-Acceptor-0" daemon prio=5 tid=0x086bd478 nid=0xe runnable
[0xd4d53000..0xd4d53d98]
    at org.apache.tomcat.jni.Socket.accept(Native Method)
    at
org.apache.tomcat.util.net.AprEndpoint$Acceptor.run(AprEndpoint.java:999) 
    at java.lang.Thread.run(Thread.java:534)

"http-8080-1" daemon prio=5 tid=0x086b98d0 nid=0xd in Object.wait()
[0xd4d95000..0xd4d95d98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd8ff0bb8> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at java.lang.Object.wait(Object.java:429)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1255) 

    - locked <0xd8ff0bb8> (a
org.apache.tomcat.util.net.AprEndpoint$Worker)
    at
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1280)
    at java.lang.Thread.run(Thread.java:534)

"http-8080-Sendfile-0" daemon prio=5 tid=0x083cf830 nid=0xc in
Object.wait() [0xd4dd7000..0xd4dd7d98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd8ff0c20> (a
org.apache.tomcat.util.net.AprEndpoint$Sendfile)
    at java.lang.Object.wait(Object.java:429)
    at
org.apache.tomcat.util.net.AprEndpoint$Sendfile.run(AprEndpoint.java:1486) 

    - locked <0xd8ff0c20> (a
org.apache.tomcat.util.net.AprEndpoint$Sendfile)
    at java.lang.Thread.run(Thread.java:534)

"http-8080-Poller-0" daemon prio=5 tid=0x083c4eb0 nid=0xb in
Object.wait() [0xd4e19000..0xd4e19d98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd8ff0c98> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
    at java.lang.Object.wait(Object.java:429)
    at
org.apache.tomcat.util.net.AprEndpoint$Poller.run(AprEndpoint.java:1127)
    - locked <0xd8ff0c98> (a
org.apache.tomcat.util.net.AprEndpoint$Poller)
    at java.lang.Thread.run(Thread.java:534)

"http-8080-Acceptor-0" daemon prio=5 tid=0x083a1d58 nid=0xa runnable
[0xd4e5b000..0xd4e5bd98]
    at org.apache.tomcat.jni.Socket.accept(Native Method)
    at
org.apache.tomcat.util.net.AprEndpoint$Acceptor.run(AprEndpoint.java:999) 
    at java.lang.Thread.run(Thread.java:534)

"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=5
tid=0x0839d4b8 nid=0x9 waiting on condition [0xd4e9d000..0xd4e9dd98]
    at java.lang.Thread.sleep(Native Method)
    at
org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1547) 

    at java.lang.Thread.run(Thread.java:534)

"Signal Dispatcher" daemon prio=10 tid=0x08116e10 nid=0x6 waiting on
condition [0x00000000..0x00000000]

"Finalizer" daemon prio=8 tid=0x0810fba0 nid=0x4 in Object.wait()
[0xfc06d000..0xfc06dd98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd85bb9d0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111)
    - locked <0xd85bb9d0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0810f188 nid=0x3 in
Object.wait() [0xfc0cc000..0xfc0ccd98]
    at java.lang.Object.wait(Native Method)
    - waiting on <0xd85bba38> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:429)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115)
    - locked <0xd85bba38> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x080741c8 nid=0x1 runnable [0x08046000..0x08046ed0]
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:353)
    - locked <0xd62a0418> (a java.net.PlainSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:448)
    at java.net.ServerSocket.accept(ServerSocket.java:419)
    at
org.apache.catalina.core.StandardServer.await(StandardServer.java:388)
    at org.apache.catalina.startup.Catalina.await(Catalina.java:615)
    at org.apache.catalina.startup.Catalina.start(Catalina.java:575)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 

    at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) 

    at java.lang.reflect.Method.invoke(Method.java:324)
    at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:294)
    at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:432)

"VM Thread" prio=5 tid=0x0810e340 nid=0x2 runnable

"VM Periodic Task Thread" prio=10 tid=0x08118988 nid=0x8 waiting on
condition
"Suspend Checker Thread" prio=10 tid=0x081164a8 nid=0x5 runnable



David Delbecq a écrit :
Could you send us a few jvm thread dumps while the CPU usage, i bet this 
an be more helpful than an os dump.
To generate a Thread dump, simply send the signal 3 to the java process
(assuming you use a SUN jvm or derivative)

Yann Rouillard a écrit :

Did you tried it with Tomcat 5.5.17?

No but I can try. Some modifications have been on this area ?


Yes, a lots of them, see the:
http://tomcat.apache.org/tomcat-5.5-doc/changelog.html

The way how Poller is handled has changed, so just try the
5.5.17.

Ok, I have tried with 5.5.17 and the problem is still present.
The thread using the CPU is still the thread doing the polling:

-----------------  lwp# 16 / thread# 16  --------------------
 fef3fff7 portfs   (6, 17, 86bf6b0, 2000, 1, d4ccfbb4)
 d52083d6 apr_pollset_poll (86bd6e0, 7d0, 0, d4ccfc04, d4ccfc10) + 1fe
 d524ccec Java_org_apache_tomcat_jni_Poll_poll (876717c, d4ccfc44,
87086b8, 0, 7d0, 0) + 64


Yann



---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]



---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]



---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]




---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]




---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]




---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]

Reply via email to