You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Milo van der Zee <mi...@vanderzee.org> on 2015/06/07 20:56:06 UTC
org.apache.tomcat.util.net.AprEndpoint to 100% CPU
Hello,
I'm having trouble with the following setup:
- Gentoo / mariaDB
- Tomcat 8.0.23
- Tomcat native 1.1.33
- Apache http 2.4.12 with modproxy_ajp
server.xml:
...
<Connector port="8208" enableLookups="false" maxThreads="1000"
protocol="org.apache.coyote.ajp.AjpAprProtocol"
connectionTimeout="5000"
maxConnections="8000"
/>
...
Everything works fina as long as I don' restart the apache server while
the tomcat server is also running. If I do so the I get this in my
catalina.out (after tweaking logging.properties):
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,023,232]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,023,232] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,023,232] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,078,656]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,078,656] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,078,656] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,023,232]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,023,232] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,023,232] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,078,656]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,078,656] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,078,656] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,023,232]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,023,232] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,023,232] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,078,656]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,078,656] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,078,656] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,023,232]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,023,232] from poller
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,023,232] for event(s) [1]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,918,626,078,656]
07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,918,626,078,656] from poller
07-Jun-2015 11:47:48.218 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,918,626,078,656] for event(s) [1]
As long as everything is running fine the output is like:
07-Jun-2015 20:44:01.106 FINE [http-apr-127.0.0.1-8508-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
[139,978,017,344,528] for event(s) [1]
07-Jun-2015 20:44:01.109 FINE [http-apr-127.0.0.1-8508-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,978,017,344,528] from poller
07-Jun-2015 20:44:01.929 FINE [http-apr-127.0.0.1-8508-Acceptor-0]
org.apache.tomcat.util.net.AprEndpoint$Acceptor.run APR socket
[139,977,950,259,008] opened with remote port [38,896]
07-Jun-2015 20:44:01.930 FINE [http-apr-127.0.0.1-8508-Acceptor-0]
org.apache.tomcat.util.net.AprEndpoint.processSocketWithOptions socket
[139,977,950,259,008]
07-Jun-2015 20:44:01.944 FINE [http-apr-127.0.0.1-8508-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,977,950,259,008]
07-Jun-2015 20:44:01.944 FINE [http-apr-127.0.0.1-8508-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,259,008] from poller
07-Jun-2015 20:44:06.471 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,977,950,307,072]
07-Jun-2015 20:44:06.471 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,307,072] from poller
07-Jun-2015 20:44:06.497 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,977,950,291,840]
07-Jun-2015 20:44:06.497 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,291,840] from poller
07-Jun-2015 20:44:06.501 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,977,950,322,336]
07-Jun-2015 20:44:06.501 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,322,336] from poller
07-Jun-2015 20:44:06.826 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
[139,977,950,271,008]
07-Jun-2015 20:44:06.826 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,271,008] from poller
07-Jun-2015 20:44:12.766 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
[139,977,950,307,072]
07-Jun-2015 20:44:12.766 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,307,072] from poller
07-Jun-2015 20:44:12.766 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
[139,977,950,307,072] from poller
07-Jun-2015 20:44:12.767 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
[139,977,950,271,008]
07-Jun-2015 20:44:12.767 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,271,008] from poller
07-Jun-2015 20:44:12.767 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
[139,977,950,271,008] from poller
07-Jun-2015 20:44:12.768 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
[139,977,950,322,336]
07-Jun-2015 20:44:12.768 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,322,336] from poller
07-Jun-2015 20:44:12.768 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
[139,977,950,322,336] from poller
07-Jun-2015 20:44:12.769 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
[139,977,950,291,840]
07-Jun-2015 20:44:12.769 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
Attempting to remove [139,977,950,291,840] from poller
07-Jun-2015 20:44:12.769 FINE [ajp-apr-8208-Poller]
org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
[139,977,950,291,840] from poller
To me this looks like a bug that Tomcat is not able to detect that the
apache socket has gone away. But could also be a bug in the native ajp
implementation of the socket handlers. When disabling apr support from
server.xml all seems to function as expected and restarting apache does
not result in a flood of messages.
Any ideas on what could be happening? A bug?
Thanks for any help,
Milo van der Zee
Re: org.apache.tomcat.util.net.AprEndpoint to 100% CPU
Posted by Milo van der Zee <mi...@vanderzee.org>.
Hello all,
Should I submit a bug report?
The fact that Tomcat starts consuming 100% CPU as soon as Apache-HTTP is
restarted does to me sound like a bug. Without using APR there is no issue.
Thanks,
Milo
On 06/07/2015 08:56 PM, Milo van der Zee wrote:
> Hello,
>
> I'm having trouble with the following setup:
> - Gentoo / mariaDB
> - Tomcat 8.0.23
> - Tomcat native 1.1.33
> - Apache http 2.4.12 with modproxy_ajp
>
> server.xml:
> ...
> <Connector port="8208" enableLookups="false" maxThreads="1000"
> protocol="org.apache.coyote.ajp.AjpAprProtocol"
> connectionTimeout="5000"
> maxConnections="8000"
> />
> ...
>
> Everything works fina as long as I don' restart the apache server
> while the tomcat server is also running. If I do so the I get this in
> my catalina.out (after tweaking logging.properties):
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,023,232]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,023,232] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,023,232] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,078,656]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,078,656] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,078,656] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,023,232]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,023,232] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,023,232] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,078,656]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,078,656] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,078,656] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,023,232]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,023,232] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,023,232] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,078,656]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,078,656] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,078,656] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,023,232]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,023,232] from poller
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,023,232] for event(s) [1]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,918,626,078,656]
> 07-Jun-2015 11:47:48.217 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,918,626,078,656] from poller
> 07-Jun-2015 11:47:48.218 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,918,626,078,656] for event(s) [1]
>
> As long as everything is running fine the output is like:
> 07-Jun-2015 20:44:01.106 FINE [http-apr-127.0.0.1-8508-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Processing socket
> [139,978,017,344,528] for event(s) [1]
> 07-Jun-2015 20:44:01.109 FINE [http-apr-127.0.0.1-8508-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,978,017,344,528] from poller
> 07-Jun-2015 20:44:01.929 FINE [http-apr-127.0.0.1-8508-Acceptor-0]
> org.apache.tomcat.util.net.AprEndpoint$Acceptor.run APR socket
> [139,977,950,259,008] opened with remote port [38,896]
> 07-Jun-2015 20:44:01.930 FINE [http-apr-127.0.0.1-8508-Acceptor-0]
> org.apache.tomcat.util.net.AprEndpoint.processSocketWithOptions socket
> [139,977,950,259,008]
> 07-Jun-2015 20:44:01.944 FINE [http-apr-127.0.0.1-8508-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,977,950,259,008]
> 07-Jun-2015 20:44:01.944 FINE [http-apr-127.0.0.1-8508-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,259,008] from poller
> 07-Jun-2015 20:44:06.471 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,977,950,307,072]
> 07-Jun-2015 20:44:06.471 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,307,072] from poller
> 07-Jun-2015 20:44:06.497 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,977,950,291,840]
> 07-Jun-2015 20:44:06.497 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,291,840] from poller
> 07-Jun-2015 20:44:06.501 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,977,950,322,336]
> 07-Jun-2015 20:44:06.501 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,322,336] from poller
> 07-Jun-2015 20:44:06.826 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.run Add to poller socket
> [139,977,950,271,008]
> 07-Jun-2015 20:44:06.826 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,271,008] from poller
> 07-Jun-2015 20:44:12.766 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
> [139,977,950,307,072]
> 07-Jun-2015 20:44:12.766 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,307,072] from poller
> 07-Jun-2015 20:44:12.766 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
> [139,977,950,307,072] from poller
> 07-Jun-2015 20:44:12.767 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
> [139,977,950,271,008]
> 07-Jun-2015 20:44:12.767 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,271,008] from poller
> 07-Jun-2015 20:44:12.767 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
> [139,977,950,271,008] from poller
> 07-Jun-2015 20:44:12.768 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
> [139,977,950,322,336]
> 07-Jun-2015 20:44:12.768 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,322,336] from poller
> 07-Jun-2015 20:44:12.768 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
> [139,977,950,322,336] from poller
> 07-Jun-2015 20:44:12.769 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.maintain Timing out
> [139,977,950,291,840]
> 07-Jun-2015 20:44:12.769 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller
> Attempting to remove [139,977,950,291,840] from poller
> 07-Jun-2015 20:44:12.769 FINE [ajp-apr-8208-Poller]
> org.apache.tomcat.util.net.AprEndpoint$Poller.removeFromPoller Removed
> [139,977,950,291,840] from poller
>
> To me this looks like a bug that Tomcat is not able to detect that the
> apache socket has gone away. But could also be a bug in the native ajp
> implementation of the socket handlers. When disabling apr support from
> server.xml all seems to function as expected and restarting apache
> does not result in a flood of messages.
>
> Any ideas on what could be happening? A bug?
>
> Thanks for any help,
> Milo van der Zee
>
>