Occasional long wait for a JDBC connection

[Darren Davis <da...@virtualvoodoo.net>]

Recently we deployed our production application on a Tomcat 8.0.14 web
server.  We are using the Tomcat JDBC Connection pool against MySQL 5.  Our
web application uses Spring (3.2.11.RELEASE) /Hibernate (3.6.10.Final) for
transaction management.  We are using a Cent OS 6 linux server in the cloud
running the 2.6.32-504 kernel.  We're using the 1.8.0_25 jdk.



Ever since deployment, we've noticed that a couple of times per day, when
Spring is attempting to prepare/open a new JDBC Connection, the thread in
question times out for about 15 minutes, and then resumes as if everything
is fine.

The line that appears to be hanging from the hibernate side is
factory.getConnectionProvider().getConnection(), which I think simply asks
for a connection from the pool.

The following options are defined in the Resource definition:
auth="Container"
factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
type="javax.sql.DataSource"
driverClassName="com.mysql.jdbc.Driver"
maxActive=500
maxIdle=55
maxWait=15000
validationQuery="Select 1"
testOnBorrow="true"
defaultAutoCommit="false"

At this time of year, our user load peaks around 150, so we shouldn't be
coming close to the maxActive defined.  MySql is configured to allow for
1010 maximum connections (we have two Tomcat instances that point to it,
configured similarly)

This application has ran for years without a problem against a Tomcat 6
instance, but after moving to Jdk 8 and Tomcat 8, we're seeing this 15
minute wait.

Any ideas on what could cause this sort of thing, and as there additional
logging we could turn on to try and figure out what is happening inside the
pool to make it wait so long?

Re: Occasional long wait for a JDBC connection

[Filip Hanik <fi...@hanik.com>]

The timeout happens in your SocketRead, this is configurable (default is
forever)
http://dev.mysql.com/doc/connector-j/en/connector-j-reference-configuration-properties.html

what appears to be happening is that somewhere there isn't a reset packet
sent from the server to the JDBC driver. Setting a timeout may alleviate
this. This property is not the same as query timeout, this is simply a
timeout in between packets. but if you have long running queries, this may
affect it.

*socketTimeout*



On Wed, Jan 14, 2015 at 11:44 AM, Christopher Schultz <
chris@christopherschultz.net> wrote:

> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Darren,
>
> On 1/13/15 11:32 PM, Darren Davis wrote:
> > On Tue, Jan 13, 2015 at 8:39 PM, Christopher Schultz <
> > chris@christopherschultz.net> wrote:
> >
> > Darren,
> >
> > (Sorry... just had to remove that monstrous stack trace...)
> >
> > On 1/13/15 5:04 PM, Darren Davis wrote:
> >>>> Hi Christopher.  Yes, we've tried a show process list and can
> >>>> find no evidence of the validation query running on mysql.
> >
> > Strange. Maybe you are waiting for the db server's buffer to flush
> > or something like that.
> >
> >
> >> I think this is because the client thinks it still has an open
> >> connection, the client net stat command shows an open connection
> >> over port 3306, at least for a few minutes after it's killed by
> >> the load balancer.  The Server loses its connection in netstat
> >> immediately.
> >
> >
> >>>> We also just tried an experiment outside of Tomcat
> >>>> completely, but connecting to a downed web server host and
> >>>> manually opening up a mysql client connection to the data
> >>>> server and executing a single command.
> >>>>
> >>>> We left that client window idle for an hour and 5 minutes,
> >>>> and attempted to execute a simple select count(*) command
> >>>> against a tiny table.  The client attempted to execute the
> >>>> query, and a NetStat on that box showed an open connection
> >>>> between the two servers using port 3306.  We also checked the
> >>>> process list during this time and could not find any queries
> >>>> at all from the sever in question.
> >>>>
> >>>> At about the 15 minute wait mark, the client finally came
> >>>> back with this message: "ERROR 2013 (HY000): Lost connection
> >>>> to MySQL server during query.
> >
> > Was this with the MySQL command-line client? What query did you
> > issue ("SELECT 1")?
> >
> >
> >> Yes, it was just the command line client, and we issued a select
> >> count(*) from a table with a couple rows in it.
> >
> >
> >>>> Attempting the execute the command a 2nd time (using the up
> >>>> arrow), re-established the connection and it ran perfectly in
> >>>> a few milliseconds.
> >
> > That's interesting. I've never experienced anything like that with
> > MySQL, but we use a VLAN between our application and database
> > servers with no hardware firewall, so we don't have any connection
> > timeout problems. Also, when connections are dropped due to
> > inactivity, they re-connect without any problems.
> >
> >>>> I checked the mysql configuration and it is set to the
> >>>> default values for keeping connections/interactive
> >>>> connections open (for 8 hours), so it seems that maybe the
> >>>> Cisco firewall between the two servers is terminating
> >>>> connections out from under us, but in a way what the O/S
> >>>> cannot detect it.
> >
> > What if you set that idle connection timeout to something like 5
> > minutes? Can you reproduce this issue more quickly? Can you look
> > at the fw configuration to see if you can change the idle timeout
> > /down/ to something more testable?
> >
> > As part of our move to the new versions of Tomcat/Java, we are in a
> > new
> >> cloud environment which features a different type of firewall.
> >> The provider confirmed to us late today, that it is configured to
> >> kill "idle" TCP connections after an hour, which is something our
> >> old firewall didn't do.
> >
> >> Because we sometimes have low traffic during this time of the
> >> year, especially on the weekends, what we think is happening is
> >> that one or more of the minimum 10 connections is going unused
> >> for more than an hour, and since we didn't have any connection
> >> testing while idle turned on, they were being killed by the
> >> firewall out from under the pool, and depending on how soon they
> >> were used after that, we would run into the 15 minute delay
> >> before they were deemed lost, and replaced with a new
> >> connection.
>
> This should be entirely possible. That's the point of the
> connection-validation operation (whether done by an actual query or
> not). The question is why the connection is being dropped in a way
> that is thwarting the connection-validation at all. It may come down
> to some kind of OS-level setting, or a slightly different
> configuration on the firewall.
>
> It seems that removing the firewall's idle-connection policy would be
> an easy way to try to get around this issue at least temporarily.
>
> >>>> I've also fired up the yourKit profiler on this box and am
> >>>> seeing other threads which have had to wait in the same
> >>>> SocketInputStream.read code, all three started a few seconds
> >>>> apart, it just wasn't detected as a deadlock, because it took
> >>>> place outside of any synchronized methods.
> >
> > What makes you think it's deadlock? Deadlock is a very specific
> > thing. Just because many threads are waiting in
> > SocketInputStream.read doesn't mean there are any threading issues
> > at all. I suspect that each SocketInputStream is distinct and only
> > in use by a single thread. The threads are blocked on I/O, right?
> > So they aren't waiting on a monitor. The best you could do would be
> > to find the native file descriptor for each socket and determine
> > that they are different from each other. I would be very surprised
> > if they are the same, used across threads. If you *are* using
> > Connection objects across threads, you should be very careful.
> > Connection objects ought to be threadsafe (I think) but use of
> > Statement and ResultSet objects across threads is a terrible idea.
> >
> >> We have a couple of synchronized methods in two of our services
> >> which hold locks in order to update a centralized record.  We
> >> realize this is a bad design and are already working on
> >> re-factoring this code to remove this need.
>
> Yes: this won't work if you have more than one instance of the
> application running.
>
> >> We've have a few instances where the 15 minute wait has happened
> >> inside of the synchronized block of code, meaning that several
> >> other threads are also having to wait for the 15 minutes to end
> >> before they get their turn inside that block of code.  Our
> >> website analyzer (YourKit) can detect this blocked threads as
> >> deadlocks, and colors them red in the thread graph.
>
> In those cases, the sync block would not have occurred in the
> SocketInputStream, though... it would have occurred in your code
> somewhere. YourKit displays threads waiting on a monitor in red, but
> waiting on a monitor does not itself indicate deadlock.
>
> Deadlock occurs when two (or more) threads are holding locks against
> each other such that none of the threads can ever proceed. If you use
> "synchronized" then this is easy to do because "synchronized" doesn't
> allow your code to attempt to acquire a lock and give up after a
> certain period of time. If you want that kind of behavior, you need to
> look at using a different kind of lock (like java.util.concurrent.Lock).
>
> >>>> It seems that sometime around the hour mark, connections get
> >>>> dropped, so we're thinking that either adding idle checking
> >>>> or dropping old connections may help us avoid this.  Although
> >>>> we are a little concerned by the various Connector / J
> >>>> alleged socket read issues which may as a possible problem.
> >
> > I don't think you should blame Connector/J at this point. They may
> > have ClassLoader pinning issues (don't get me started), but the
> > driver is fairly robust and mature.
> >
> >>>> We're running an older 5.1.18 version of the Connector/J
> >>>> driver, but aren't sure of moving to the latest .34 release
> >>>> would change anything.
> >
> > We are also still using 5.1.18 and have never had any of these
> > kinds of issues. I would highly suspect the network environment.
> > See what you can find out by tinkering with the firewall and db
> > idle policies. You may find that the pipe across the network gets
> > into a state where the client is sure the connection is still
> > valid, but it's simply never going to return any data. In that
> > case, you'll need to figure out how to have that connection fail
> > faster.
> >
> > Do you have a read-timeout set on your driver?
> >
> >> We have re-configured the driver by setting maxAge to 360000,
> >> testWhileIdle to true, validationQueryTimeout to 5,
> >> logValidationErrors to true.  We restarted the Tomcat service 5
> >> 1/2 hours ago, and so far haven't seen this error return yet.  We
> >> are also hopeful that even if it did, the validationQueryTimeout
> >> change would prevent it from holding things up for 15 minutes.
> >
> >> We really appreciate all of the feedback from you and others
> >> today, since we've focused most of our dev team on trying to
> >> understand and troubleshoot this issue for the past few days.
>
> Good luck. This kind of thing can drive you insane.
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1
> Comment: GPGTools - http://gpgtools.org
>
> iQIcBAEBCAAGBQJUtrj5AAoJEBzwKT+lPKRYw3UQAKJcXsyPM14QOIsvJh1V5vGU
> +TQBHLPAfezyhSrEg1+vKEpWF/9VvXlzwoj8KEFgfWTCUogfKUT1kyLN2GCb3k6s
> Cl04yndqqdb/N1ORsoTG9/utLdktOCgDds7qwLtsS9h4gUGME/wXIJSsazBAAlv4
> +dkJfVgzyVrizGEIt3s1uVz+X2VOfU/4FVaGwvbsU6hBgVBjfmZH6bwuy+6I3D63
> nxTePgK+BILW3pPgd3l46z+gBeaHCPEcjnMmdaZSc8iftzh2udT0HGMrSf/Fso0V
> SFnQj0qVe+nV6WuqExcQBrgvCXh0fdUb74YXfD1UFiZFjAxKY1+B3BDtMIdTizSL
> byAPfC/XRnWPzJa+yqO64nINe2Yhdo/BhOEFAkLl7ds7RLD3qwEwIQ70iwZd0vXR
> RqKpQ/vhtfgRDEvpFmHpGKXnn8LpDv0InJG8mEwyI+2hVpwwGa3E2fOvgYijeybl
> IPTuCaqvsaH8wToEuw64k75On2HDzFBIc9YvWBC6i5gZiIDIdDl+ehjZx8iBIeyJ
> 7MAIK8UL9OqXVVDBSD/rFhGD4TsQpi6NvLEwiibz0faQWl2AXEoabxd4zJvwbP3U
> 2lf1KUs7lWtj/yoK6PSGFHjOBiyZe+z+RdjUpUSqnGB97wUKIP0bSadS7xtziSvX
> zA3Y1KuirLdEsynDcQu+
> =LqcN
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>

Re: Occasional long wait for a JDBC connection

[Christopher Schultz <ch...@christopherschultz.net>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Darren,

On 1/13/15 11:32 PM, Darren Davis wrote:
> On Tue, Jan 13, 2015 at 8:39 PM, Christopher Schultz < 
> chris@christopherschultz.net> wrote:
> 
> Darren,
> 
> (Sorry... just had to remove that monstrous stack trace...)
> 
> On 1/13/15 5:04 PM, Darren Davis wrote:
>>>> Hi Christopher.  Yes, we've tried a show process list and can
>>>> find no evidence of the validation query running on mysql.
> 
> Strange. Maybe you are waiting for the db server's buffer to flush
> or something like that.
> 
> 
>> I think this is because the client thinks it still has an open
>> connection, the client net stat command shows an open connection
>> over port 3306, at least for a few minutes after it's killed by
>> the load balancer.  The Server loses its connection in netstat
>> immediately.
> 
> 
>>>> We also just tried an experiment outside of Tomcat
>>>> completely, but connecting to a downed web server host and
>>>> manually opening up a mysql client connection to the data
>>>> server and executing a single command.
>>>> 
>>>> We left that client window idle for an hour and 5 minutes,
>>>> and attempted to execute a simple select count(*) command
>>>> against a tiny table.  The client attempted to execute the
>>>> query, and a NetStat on that box showed an open connection
>>>> between the two servers using port 3306.  We also checked the
>>>> process list during this time and could not find any queries
>>>> at all from the sever in question.
>>>> 
>>>> At about the 15 minute wait mark, the client finally came
>>>> back with this message: "ERROR 2013 (HY000): Lost connection
>>>> to MySQL server during query.
> 
> Was this with the MySQL command-line client? What query did you
> issue ("SELECT 1")?
> 
> 
>> Yes, it was just the command line client, and we issued a select
>> count(*) from a table with a couple rows in it.
> 
> 
>>>> Attempting the execute the command a 2nd time (using the up 
>>>> arrow), re-established the connection and it ran perfectly in
>>>> a few milliseconds.
> 
> That's interesting. I've never experienced anything like that with 
> MySQL, but we use a VLAN between our application and database
> servers with no hardware firewall, so we don't have any connection
> timeout problems. Also, when connections are dropped due to
> inactivity, they re-connect without any problems.
> 
>>>> I checked the mysql configuration and it is set to the
>>>> default values for keeping connections/interactive
>>>> connections open (for 8 hours), so it seems that maybe the
>>>> Cisco firewall between the two servers is terminating
>>>> connections out from under us, but in a way what the O/S
>>>> cannot detect it.
> 
> What if you set that idle connection timeout to something like 5 
> minutes? Can you reproduce this issue more quickly? Can you look
> at the fw configuration to see if you can change the idle timeout
> /down/ to something more testable?
> 
> As part of our move to the new versions of Tomcat/Java, we are in a
> new
>> cloud environment which features a different type of firewall.
>> The provider confirmed to us late today, that it is configured to
>> kill "idle" TCP connections after an hour, which is something our
>> old firewall didn't do.
> 
>> Because we sometimes have low traffic during this time of the
>> year, especially on the weekends, what we think is happening is
>> that one or more of the minimum 10 connections is going unused
>> for more than an hour, and since we didn't have any connection
>> testing while idle turned on, they were being killed by the
>> firewall out from under the pool, and depending on how soon they
>> were used after that, we would run into the 15 minute delay 
>> before they were deemed lost, and replaced with a new
>> connection.

This should be entirely possible. That's the point of the
connection-validation operation (whether done by an actual query or
not). The question is why the connection is being dropped in a way
that is thwarting the connection-validation at all. It may come down
to some kind of OS-level setting, or a slightly different
configuration on the firewall.

It seems that removing the firewall's idle-connection policy would be
an easy way to try to get around this issue at least temporarily.

>>>> I've also fired up the yourKit profiler on this box and am
>>>> seeing other threads which have had to wait in the same 
>>>> SocketInputStream.read code, all three started a few seconds
>>>> apart, it just wasn't detected as a deadlock, because it took
>>>> place outside of any synchronized methods.
> 
> What makes you think it's deadlock? Deadlock is a very specific
> thing. Just because many threads are waiting in
> SocketInputStream.read doesn't mean there are any threading issues
> at all. I suspect that each SocketInputStream is distinct and only
> in use by a single thread. The threads are blocked on I/O, right?
> So they aren't waiting on a monitor. The best you could do would be
> to find the native file descriptor for each socket and determine
> that they are different from each other. I would be very surprised
> if they are the same, used across threads. If you *are* using
> Connection objects across threads, you should be very careful.
> Connection objects ought to be threadsafe (I think) but use of
> Statement and ResultSet objects across threads is a terrible idea.
> 
>> We have a couple of synchronized methods in two of our services
>> which hold locks in order to update a centralized record.  We
>> realize this is a bad design and are already working on
>> re-factoring this code to remove this need.

Yes: this won't work if you have more than one instance of the
application running.

>> We've have a few instances where the 15 minute wait has happened 
>> inside of the synchronized block of code, meaning that several
>> other threads are also having to wait for the 15 minutes to end
>> before they get their turn inside that block of code.  Our
>> website analyzer (YourKit) can detect this blocked threads as
>> deadlocks, and colors them red in the thread graph.

In those cases, the sync block would not have occurred in the
SocketInputStream, though... it would have occurred in your code
somewhere. YourKit displays threads waiting on a monitor in red, but
waiting on a monitor does not itself indicate deadlock.

Deadlock occurs when two (or more) threads are holding locks against
each other such that none of the threads can ever proceed. If you use
"synchronized" then this is easy to do because "synchronized" doesn't
allow your code to attempt to acquire a lock and give up after a
certain period of time. If you want that kind of behavior, you need to
look at using a different kind of lock (like java.util.concurrent.Lock).

>>>> It seems that sometime around the hour mark, connections get 
>>>> dropped, so we're thinking that either adding idle checking
>>>> or dropping old connections may help us avoid this.  Although
>>>> we are a little concerned by the various Connector / J
>>>> alleged socket read issues which may as a possible problem.
> 
> I don't think you should blame Connector/J at this point. They may 
> have ClassLoader pinning issues (don't get me started), but the
> driver is fairly robust and mature.
> 
>>>> We're running an older 5.1.18 version of the Connector/J
>>>> driver, but aren't sure of moving to the latest .34 release
>>>> would change anything.
> 
> We are also still using 5.1.18 and have never had any of these
> kinds of issues. I would highly suspect the network environment.
> See what you can find out by tinkering with the firewall and db
> idle policies. You may find that the pipe across the network gets
> into a state where the client is sure the connection is still
> valid, but it's simply never going to return any data. In that
> case, you'll need to figure out how to have that connection fail
> faster.
> 
> Do you have a read-timeout set on your driver?
> 
>> We have re-configured the driver by setting maxAge to 360000, 
>> testWhileIdle to true, validationQueryTimeout to 5,
>> logValidationErrors to true.  We restarted the Tomcat service 5
>> 1/2 hours ago, and so far haven't seen this error return yet.  We
>> are also hopeful that even if it did, the validationQueryTimeout
>> change would prevent it from holding things up for 15 minutes.
> 
>> We really appreciate all of the feedback from you and others
>> today, since we've focused most of our dev team on trying to
>> understand and troubleshoot this issue for the past few days.

Good luck. This kind of thing can drive you insane.

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
Comment: GPGTools - http://gpgtools.org

iQIcBAEBCAAGBQJUtrj5AAoJEBzwKT+lPKRYw3UQAKJcXsyPM14QOIsvJh1V5vGU
+TQBHLPAfezyhSrEg1+vKEpWF/9VvXlzwoj8KEFgfWTCUogfKUT1kyLN2GCb3k6s
Cl04yndqqdb/N1ORsoTG9/utLdktOCgDds7qwLtsS9h4gUGME/wXIJSsazBAAlv4
+dkJfVgzyVrizGEIt3s1uVz+X2VOfU/4FVaGwvbsU6hBgVBjfmZH6bwuy+6I3D63
nxTePgK+BILW3pPgd3l46z+gBeaHCPEcjnMmdaZSc8iftzh2udT0HGMrSf/Fso0V
SFnQj0qVe+nV6WuqExcQBrgvCXh0fdUb74YXfD1UFiZFjAxKY1+B3BDtMIdTizSL
byAPfC/XRnWPzJa+yqO64nINe2Yhdo/BhOEFAkLl7ds7RLD3qwEwIQ70iwZd0vXR
RqKpQ/vhtfgRDEvpFmHpGKXnn8LpDv0InJG8mEwyI+2hVpwwGa3E2fOvgYijeybl
IPTuCaqvsaH8wToEuw64k75On2HDzFBIc9YvWBC6i5gZiIDIdDl+ehjZx8iBIeyJ
7MAIK8UL9OqXVVDBSD/rFhGD4TsQpi6NvLEwiibz0faQWl2AXEoabxd4zJvwbP3U
2lf1KUs7lWtj/yoK6PSGFHjOBiyZe+z+RdjUpUSqnGB97wUKIP0bSadS7xtziSvX
zA3Y1KuirLdEsynDcQu+
=LqcN
-----END PGP SIGNATURE-----

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Occasional long wait for a JDBC connection

[Darren Davis <da...@virtualvoodoo.net>]

On Tue, Jan 13, 2015 at 8:39 PM, Christopher Schultz <
chris@christopherschultz.net> wrote:

> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Darren,
>
> (Sorry... just had to remove that monstrous stack trace...)
>
> On 1/13/15 5:04 PM, Darren Davis wrote:
> > Hi Christopher.  Yes, we've tried a show process list and can find
> > no evidence of the validation query running on mysql.
>
> Strange. Maybe you are waiting for the db server's buffer to flush or
> something like that.
>
>
I think this is because the client thinks it still has an open connection,
the client net stat command shows an open connection over port 3306, at
least for a few minutes after it's killed by the load balancer.  The Server
loses its connection in netstat immediately.


> > We also just tried an experiment outside of Tomcat completely, but
> > connecting to a downed web server host and manually opening up a
> > mysql client connection to the data server and executing a single
> > command.
> >
> > We left that client window idle for an hour and 5 minutes, and
> > attempted to execute a simple select count(*) command against a
> > tiny table.  The client attempted to execute the query, and a
> > NetStat on that box showed an open connection between the two
> > servers using port 3306.  We also checked the process list during
> > this time and could not find any queries at all from the sever in
> > question.
> >
> > At about the 15 minute wait mark, the client finally came back with
> > this message: "ERROR 2013 (HY000): Lost connection to MySQL server
> > during query.
>
> Was this with the MySQL command-line client? What query did you issue
> ("SELECT 1")?
>
>
Yes, it was just the command line client, and we issued a select count(*)
from a table with a couple rows in it.


> > Attempting the execute the command a 2nd time (using the up
> > arrow), re-established the connection and it ran perfectly in a few
> > milliseconds.
>
> That's interesting. I've never experienced anything like that with
> MySQL, but we use a VLAN between our application and database servers
> with no hardware firewall, so we don't have any connection timeout
> problems. Also, when connections are dropped due to inactivity, they
> re-connect without any problems.
>
> > I checked the mysql configuration and it is set to the default
> > values for keeping connections/interactive connections open (for 8
> > hours), so it seems that maybe the Cisco firewall between the two
> > servers is terminating connections out from under us, but in a way
> > what the O/S cannot detect it.
>
> What if you set that idle connection timeout to something like 5
> minutes? Can you reproduce this issue more quickly? Can you look at
> the fw configuration to see if you can change the idle timeout /down/
> to something more testable?
>
> As part of our move to the new versions of Tomcat/Java, we are in a new
cloud environment which features a different type of firewall.  The
provider confirmed to us late today, that it is configured to kill "idle"
TCP connections after an hour, which is something our old firewall didn't
do.

Because we sometimes have low traffic during this time of the year,
especially on the weekends, what we think is happening is that one or more
of the minimum 10 connections is going unused for more than an hour, and
since we didn't have any connection testing while idle turned on, they were
being killed by the firewall out from under the pool, and depending on how
soon they were used after that, we would run into the 15 minute delay
before they were deemed lost, and replaced with a new connection.


> > I've also fired up the yourKit profiler on this box and am seeing
> > other threads which have had to wait in the same
> > SocketInputStream.read code, all three started a few seconds apart,
> > it just wasn't detected as a deadlock, because it took place
> > outside of any synchronized methods.
>
> What makes you think it's deadlock? Deadlock is a very specific thing.
> Just because many threads are waiting in SocketInputStream.read
> doesn't mean there are any threading issues at all. I suspect that
> each SocketInputStream is distinct and only in use by a single thread.
> The threads are blocked on I/O, right? So they aren't waiting on a
> monitor. The best you could do would be to find the native file
> descriptor for each socket and determine that they are different from
> each other. I would be very surprised if they are the same, used
> across threads. If you *are* using Connection objects across threads,
> you should be very careful. Connection objects ought to be threadsafe
> (I think) but use of Statement and ResultSet objects across threads is
> a terrible idea.
>
> We have a couple of synchronized methods in two of our services which hold
locks in order to update a centralized record.  We realize this is a bad
design and are already working on re-factoring this code to remove this
need.  We've have a few instances where the 15 minute wait has happened
inside of the synchronized block of code, meaning that several other
threads are also having to wait for the 15 minutes to end before they get
their turn inside that block of code.  Our website analyzer (YourKit) can
detect this blocked threads as deadlocks, and colors them red in the thread
graph.


> > It seems that sometime around the hour mark, connections get
> > dropped, so we're thinking that either adding idle checking or
> > dropping old connections may help us avoid this.  Although we are a
> > little concerned by the various Connector / J alleged socket read
> > issues which may as a possible problem.
>
> I don't think you should blame Connector/J at this point. They may
> have ClassLoader pinning issues (don't get me started), but the driver
> is fairly robust and mature.
>
> > We're running an older 5.1.18 version of the Connector/J driver,
> > but aren't sure of moving to the latest .34 release would change
> > anything.
>
> We are also still using 5.1.18 and have never had any of these kinds
> of issues. I would highly suspect the network environment. See what
> you can find out by tinkering with the firewall and db idle policies.
> You may find that the pipe across the network gets into a state where
> the client is sure the connection is still valid, but it's simply
> never going to return any data. In that case, you'll need to figure
> out how to have that connection fail faster.
>
> Do you have a read-timeout set on your driver?
>
> We have re-configured the driver by setting maxAge to 360000,
testWhileIdle to true, validationQueryTimeout to 5, logValidationErrors to
true.  We restarted the Tomcat service 5 1/2 hours ago, and so far haven't
seen this error return yet.  We are also hopeful that even if it did, the
validationQueryTimeout change would prevent it from holding things up for
15 minutes.

We really appreciate all of the feedback from you and others today, since
we've focused most of our dev team on trying to understand and troubleshoot
this issue for the past few days.



> - -chris
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1
> Comment: GPGTools - http://gpgtools.org
>
> iQIcBAEBCAAGBQJUteT3AAoJEBzwKT+lPKRY7BUP/3IV0Xsakr3rWRpqnro1IbUl
> nbNHHIm9fqG+7mbvkeIQIE5XnZvA822HZvp9whC+4499kfQZNtrT0IIj1F20YH5r
> SMMkalCbY6XIzj1ST4aPf7YE2MlBtBwFZUwIGG2aT2XUKwSwHVdTcQxI2H4sG5vf
> iCkvS7YdJg5h6QSj5CQHg6dnsVR2hbF42tftti33hOsRPZu3cXOe0ajrXsoimMuk
> WWt+hpk8rjWtEnrMgaKlyntKGAI2tqXYVzPxraR3wwevm1tbHjHk2U3hFrq9teuV
> FA57RhWTlba/OJ+ph+LEiT39IdEdzESspTI+JeQvN5LJEsaMpxmRpnmLnhD/3EXx
> aNRze3eRw5M7qG0CcMduCMFe1j2i8TCwBLtHHJnplXWzve9PgqbJBtk7acJpn/Ls
> 54j23u5Z26TvAAJxiCa6/zxiJ6xRZDLfxfZsYVMImRHpC9s+GDPuAylUjaXVmoa+
> HAIEQGUxTI16oQQZIG6mevehNtT8ik+zwVLMSk+QonvDRnRxsyPr8jItSanG3YXb
> th0kyE99y1rogJ+zeC9S+8NBiNkrU9EH7uUWZY7WyLuEHC+EyjCVaAV8SB+QBKKm
> PLs/EFnEVLLQWpj7Gzl7/421Fy6ttemeDEfj+VO2kSo7Wsy4kW3hcH/5spFCqeFj
> +WEiED5vvH5w9LrOkUcL
> =hPlo
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
> Hi Christopher,

Re: Occasional long wait for a JDBC connection

[Christopher Schultz <ch...@christopherschultz.net>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Darren,

(Sorry... just had to remove that monstrous stack trace...)

On 1/13/15 5:04 PM, Darren Davis wrote:
> Hi Christopher.  Yes, we've tried a show process list and can find
> no evidence of the validation query running on mysql.

Strange. Maybe you are waiting for the db server's buffer to flush or
something like that.

> We also just tried an experiment outside of Tomcat completely, but 
> connecting to a downed web server host and manually opening up a
> mysql client connection to the data server and executing a single
> command.
> 
> We left that client window idle for an hour and 5 minutes, and
> attempted to execute a simple select count(*) command against a
> tiny table.  The client attempted to execute the query, and a
> NetStat on that box showed an open connection between the two
> servers using port 3306.  We also checked the process list during
> this time and could not find any queries at all from the sever in
> question.
> 
> At about the 15 minute wait mark, the client finally came back with
> this message: "ERROR 2013 (HY000): Lost connection to MySQL server
> during query.

Was this with the MySQL command-line client? What query did you issue
("SELECT 1")?

> Attempting the execute the command a 2nd time (using the up
> arrow), re-established the connection and it ran perfectly in a few
> milliseconds.

That's interesting. I've never experienced anything like that with
MySQL, but we use a VLAN between our application and database servers
with no hardware firewall, so we don't have any connection timeout
problems. Also, when connections are dropped due to inactivity, they
re-connect without any problems.

> I checked the mysql configuration and it is set to the default
> values for keeping connections/interactive connections open (for 8
> hours), so it seems that maybe the Cisco firewall between the two
> servers is terminating connections out from under us, but in a way
> what the O/S cannot detect it.

What if you set that idle connection timeout to something like 5
minutes? Can you reproduce this issue more quickly? Can you look at
the fw configuration to see if you can change the idle timeout /down/
to something more testable?

> I've also fired up the yourKit profiler on this box and am seeing
> other threads which have had to wait in the same
> SocketInputStream.read code, all three started a few seconds apart,
> it just wasn't detected as a deadlock, because it took place
> outside of any synchronized methods.

What makes you think it's deadlock? Deadlock is a very specific thing.
Just because many threads are waiting in SocketInputStream.read
doesn't mean there are any threading issues at all. I suspect that
each SocketInputStream is distinct and only in use by a single thread.
The threads are blocked on I/O, right? So they aren't waiting on a
monitor. The best you could do would be to find the native file
descriptor for each socket and determine that they are different from
each other. I would be very surprised if they are the same, used
across threads. If you *are* using Connection objects across threads,
you should be very careful. Connection objects ought to be threadsafe
(I think) but use of Statement and ResultSet objects across threads is
a terrible idea.

> It seems that sometime around the hour mark, connections get
> dropped, so we're thinking that either adding idle checking or
> dropping old connections may help us avoid this.  Although we are a
> little concerned by the various Connector / J alleged socket read
> issues which may as a possible problem.

I don't think you should blame Connector/J at this point. They may
have ClassLoader pinning issues (don't get me started), but the driver
is fairly robust and mature.

> We're running an older 5.1.18 version of the Connector/J driver,
> but aren't sure of moving to the latest .34 release would change
> anything.

We are also still using 5.1.18 and have never had any of these kinds
of issues. I would highly suspect the network environment. See what
you can find out by tinkering with the firewall and db idle policies.
You may find that the pipe across the network gets into a state where
the client is sure the connection is still valid, but it's simply
never going to return any data. In that case, you'll need to figure
out how to have that connection fail faster.

Do you have a read-timeout set on your driver?

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
Comment: GPGTools - http://gpgtools.org

iQIcBAEBCAAGBQJUteT3AAoJEBzwKT+lPKRY7BUP/3IV0Xsakr3rWRpqnro1IbUl
nbNHHIm9fqG+7mbvkeIQIE5XnZvA822HZvp9whC+4499kfQZNtrT0IIj1F20YH5r
SMMkalCbY6XIzj1ST4aPf7YE2MlBtBwFZUwIGG2aT2XUKwSwHVdTcQxI2H4sG5vf
iCkvS7YdJg5h6QSj5CQHg6dnsVR2hbF42tftti33hOsRPZu3cXOe0ajrXsoimMuk
WWt+hpk8rjWtEnrMgaKlyntKGAI2tqXYVzPxraR3wwevm1tbHjHk2U3hFrq9teuV
FA57RhWTlba/OJ+ph+LEiT39IdEdzESspTI+JeQvN5LJEsaMpxmRpnmLnhD/3EXx
aNRze3eRw5M7qG0CcMduCMFe1j2i8TCwBLtHHJnplXWzve9PgqbJBtk7acJpn/Ls
54j23u5Z26TvAAJxiCa6/zxiJ6xRZDLfxfZsYVMImRHpC9s+GDPuAylUjaXVmoa+
HAIEQGUxTI16oQQZIG6mevehNtT8ik+zwVLMSk+QonvDRnRxsyPr8jItSanG3YXb
th0kyE99y1rogJ+zeC9S+8NBiNkrU9EH7uUWZY7WyLuEHC+EyjCVaAV8SB+QBKKm
PLs/EFnEVLLQWpj7Gzl7/421Fy6ttemeDEfj+VO2kSo7Wsy4kW3hcH/5spFCqeFj
+WEiED5vvH5w9LrOkUcL
=hPlo
-----END PGP SIGNATURE-----

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Occasional long wait for a JDBC connection

[Darren Davis <da...@virtualvoodoo.net>]

On Tue, Jan 13, 2015 at 2:33 PM, Christopher Schultz <
chris@christopherschultz.net> wrote:

> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Darren,
>
> On 1/13/15 1:04 PM, Christopher Schultz wrote:
> > On 1/13/15 11:49 AM, Darren Davis wrote:
> >> The problem occurred again this morning.  I was able to generate
> >> a thread dump and narrow down the source of our problem to
> >> tomcat thread 23.
> >
> >>> From 8:45:51,397 to 09:01:19,083, it was stuck in the validate
> >>> check for a
> >> newly instantiated connection:
> >
> >> I ran the thread dump several times during this interval, and
> >> the stack trace for thread 23 did not change at all.
> >
> >> I did check our database log file and determined that during the
> >> 8 hours that led up to our first error on the server yesterday,
> >> we had just a total of 12 unique connections.  The problem
> >> occurred the the creation of connection # 13, which was then used
> >> several other times later.
> >
> >> The incident this morning also coincided with creating a new
> >> connection in the pool.  It does not make any sense that the
> >> simple validation query of "SELECT 1" would require a wait of 15
> >> minutes to succeed.
> >
> > Agreed.
> >
> >> It's also strange that this only happens sporadically, and not
> >> every time a new connection is being "birthed" by the system.
> >
> >> We've tried two different pooling technologies: DBCP and the new
> >> Apache JDBC pooling on this server and both exhibit the same 15
> >> minute occasional wait.
> >
> > The problem is with the driver and/or database, not with the
> > connection pool. It's not surprising that you are experiencing
> > problems regardless of the pool being used.
> >
> >> we've come across documentation that suggests we could modify our
> >>  validation statement by prefixing it with /* ping */, which
> >> we're thinking about trying
> >
> > Using "/* ping */" is usually a good idea for MySQL, but it may
> > mask the problem. What you may find is that the next "real" query
> > you use hangs for 15 minutes. If you are going to use /* ping */
> > and you are going to use the tomcat-jdbc pool, then you may as well
> > not configure a validation query at all because Tomcat's pool will
> > use Connection.isValid which amounts to the same thing (and will
> > work for any compliant JDBC driver, not just with MySQL).
> >
> >> "http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0
> >> tid=0x00007f0658387000 nid=0x7a60 runnable [0x00007f05e7466000]
> >> java.lang.Thread.State: RUNNABLE at
> >> java.net.SocketInputStream.$$YJP$$socketRead0(Native Method) at
> >> java.net.SocketInputStream.socketRead0(SocketInputStream.java)
> >> at java.net.SocketInputStream.read(SocketInputStream.java:150)
> >> at java.net.SocketInputStream.read(SocketInputStream.java:121) at
> >>
> >>
> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
> >
> >>
> >
> > at
> >>
> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
> >
> >>
> >
> > at
> >>
> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
> >
> >>
> >
> > - locked <0x00000000bdf09420> (a
> >> com.mysql.jdbc.util.ReadAheadInputStream) at
> >> com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549) at
> >> com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002) at
> >> com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991) at
> >> com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532) at
> >> com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002) at
> >> com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163) at
> >> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
> >> - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
> >> at
> >> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
> >> at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842)
> >> - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
> >> - locked <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl)
> >> at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681)
> >> at
> >>
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:503)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:437)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:763)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:617)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
> >
> >>
> >
> > at
> >>
> org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
> >
> >>
> >
> > at
> >>
> org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
> >
> >>
> >
> > at
> >>
> org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
> >
> >>
> >
> > at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
> >> at
> >> org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
> >
> >>
> >
> > at
> >> org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
> >
> >>
> >
> > at
> >>
> org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:424)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
> >
> >>
> >
> > at
> >>
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> >
> >>
> >
> > at
> >>
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> >
> >>
> >
> > at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
> >> at
> >>
> com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSystemTask(SynchronizationServiceImpl.java:115)
> >
> >>
> >
> > - locked <0x00000000a45652b8> (a
> >> com.tracom.max.service.impl.SynchronizationServiceImpl) at
> >>
> com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(SessionServiceImpl.java:1767)
> >
> >>
> >
> > at
> >>
> com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(SessionServiceImpl.java:1697)
> >
> >>
> >
> > at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
> >> at
> >>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> >
> >>
> >
> > at java.lang.reflect.Method.invoke(Method.java:483)
> >> at
> >>
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
> >
> >>
> >
> > at
> >>
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> >
> >>
> >
> > at
> >>
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
> >
> >>
> >
> > at
> >>
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
> >
> >>
> >
> > at
> >>
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> >
> >>
> >
> > at
> >>
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> >
> >>
> >
> > at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
> >> at
> >>
> com.tracom.tracomlearning.controller.InviteRaterController.processInviteRater(InviteRaterController.java:461)
> >
> >>
> >
> > at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
> >> at
> >>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> >
> >>
> >
> > at java.lang.reflect.Method.invoke(Method.java:483)
> >> at
> >>
> org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
> >
> >>
> >
> > at
> >>
> org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
> >
> >>
> >
> > at
> >>
> org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
> >
> >>
> >
> > at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
> >> at
> >>
> org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
> >
> >>
> >
> > at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
> >> at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> >
> >>
> >
> > at
> >> org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> >
> >>
> >
> > at
> >>
> com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.java:33)
> >
> >>
> >
> > at
> >>
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
> >
> >>
> >
> > at
> >>
> org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
> >
> >>
> >
> > at
> >>
> org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
> >
> >>
> >
> > at
> >>
> org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> >
> >>
> >
> > at
> >>
> org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
> >
> >>
> >
> > at
> >>
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
> >
> >>
> >
> > at
> >>
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:537)
> >
> >>
> >
> > at
> >>
> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1081)
> >
> >>
> >
> > at
> >>
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:658)
> >
> >>
> >
> > at
> >>
> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
> >
> >>
> >
> > - locked <0x00000000fecbac90> (a
> >> org.apache.tomcat.util.net.SecureNioChannel) at
> >>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> >
> >>
> >
> > at
> >>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> >
> >>
> >
> > at
> >>
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> >
> >>
> >
> > at java.lang.Thread.run(Thread.java:745)
> >
> > Is it possible to rule-out any network problems? Is there any
> > pattern at all to the pauses?
>
> Another thought: what do you get if you run SHOW PROCESSLIST on the
> server during these long pauses?
>
> I remember a guy who once did a START TRANSACTION and then locked up
> some tables before going to lunch without either a ROLLBACK or COMMIT,
> and he help up loads of transactions that were waiting to get locks
> (presumably for PK sequences or whatever).
>
> Could there be some other process that is starting a conflicting
> transaction here? "SELECT 1" should require no no locks whatsoever,
> but it might be something silly like contention with the query cache.
> I've seen MySQL do some colossally stupid things before... maybe
> something odd like that is happening, here.
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1
> Comment: GPGTools - http://gpgtools.org
>
> iQIcBAEBCAAGBQJUtY8jAAoJEBzwKT+lPKRYsvUP/28Mpo5cV1Xeogqc4JWspJbi
> zWwyHM1J9sLps8nYib2+DUtxBfUYaEIXtCzoZ62e4/Z1c9h/oJaECFocnvz8fSbS
> Af5cPJexPSMkx6ggOLl61ymBYiZmItJwtfhwoyh+DDQmPZalFU6znJ/txHKUO5+7
> MmxccIo9N/S7mmktUYaeG63MIq8v/gmH9+VsDEChYqbucK6n11EL+Y+whfntfcWS
> pS18vkYlF1albiB7Epd7fl6wuoZH1hoTJsnr23lIEP42hH8Kb7yE49nIaAM/IB1D
> vXMRQSWhLNZCpEWpa3wJGJk19DeTJaTcs+yuJIDtPyZxtuCPlA7zDqdTGQmLdKgf
> aWq08ei6Vq5POWrIdBHJ6OHZUgsgBmMS7c53INNm7sC+XXY4hIUW5SWoZQUHERoG
> 3ms+LMJtaP5zhteFYc8BvptFuIHreZCL19kcaRA0W1BPnhxXKL9C1e/BJG1LCS8d
> b5UH4xC4LPcmz0FF6/e9DH81SBmRTR4EWcLekFxjihtBtDxxl52GnjFFB/ynsFvd
> PweCCo9R+itj5hUhFj3VQqli8DF+3/puwikHlaQjQEvi3smVP0faTSL6b89zk3uM
> T/DzEIyyvvLA45qQoxFbUsDBNWvJYDbr3NZu7pty+XNupsD1Ys4mxTxce0rjHhk4
> EJjblPF13mtCisFA2z/p
> =9u7v
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
HI Christopher.  Yes, we've tried a show process list and can find no
evidence of the validation query running on mysql.

We also just tried an experiment outside of Tomcat completely, but
connecting to a downed web server host and manually opening up a mysql
client connection to the data server and executing a single command.

We left that client window idle for an hour and 5 minutes, and attempted to
execute a simple select count(*) command against a tiny table.  The client
attempted to execute the query, and a NetStat on that box showed an open
connection between the two servers using port 3306.  We also checked the
process list during this time and could not find any queries at all from
the sever in question.

At about the 15 minute wait mark, the client finally came back with this
message: "ERROR 2013 (HY000): Lost connection to MySQL server during query.

Attempting the execute the command a 2nd time (using the up arrow),
re-established the connection and it ran perfectly in a few milliseconds.

I checked the mysql configuration and it is set to the default values for
keeping connections/interactive connections open (for 8 hours), so it seems
that maybe the Cisco firewall between the two servers is terminating
connections out from under us, but in a way what the O/S cannot detect it.

I've also fired up the yourKit profiler on this box and am seeing other
threads which have had to wait in the same SocketInputStream.read code, all
three started a few seconds apart, it just wasn't detected as a deadlock,
because it took place outside of any synchronized methods.

It seems that sometime around the hour mark, connections get dropped, so
we're thinking that either adding idle checking or dropping old connections
may help us avoid this.  Although we are a little concerned by the various
Connector / J alleged socket read issues which may as a possible problem.

We're running an older 5.1.18 version of the Connector/J driver, but aren't
sure of moving to the latest .34 release would change anything.

Re: Occasional long wait for a JDBC connection

[Christopher Schultz <ch...@christopherschultz.net>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Darren,

On 1/13/15 1:04 PM, Christopher Schultz wrote:
> On 1/13/15 11:49 AM, Darren Davis wrote:
>> The problem occurred again this morning.  I was able to generate
>> a thread dump and narrow down the source of our problem to
>> tomcat thread 23.
> 
>>> From 8:45:51,397 to 09:01:19,083, it was stuck in the validate 
>>> check for a
>> newly instantiated connection:
> 
>> I ran the thread dump several times during this interval, and
>> the stack trace for thread 23 did not change at all.
> 
>> I did check our database log file and determined that during the
>> 8 hours that led up to our first error on the server yesterday,
>> we had just a total of 12 unique connections.  The problem
>> occurred the the creation of connection # 13, which was then used
>> several other times later.
> 
>> The incident this morning also coincided with creating a new 
>> connection in the pool.  It does not make any sense that the
>> simple validation query of "SELECT 1" would require a wait of 15
>> minutes to succeed.
> 
> Agreed.
> 
>> It's also strange that this only happens sporadically, and not 
>> every time a new connection is being "birthed" by the system.
> 
>> We've tried two different pooling technologies: DBCP and the new 
>> Apache JDBC pooling on this server and both exhibit the same 15 
>> minute occasional wait.
> 
> The problem is with the driver and/or database, not with the 
> connection pool. It's not surprising that you are experiencing 
> problems regardless of the pool being used.
> 
>> we've come across documentation that suggests we could modify our
>>  validation statement by prefixing it with /* ping */, which
>> we're thinking about trying
> 
> Using "/* ping */" is usually a good idea for MySQL, but it may
> mask the problem. What you may find is that the next "real" query
> you use hangs for 15 minutes. If you are going to use /* ping */
> and you are going to use the tomcat-jdbc pool, then you may as well
> not configure a validation query at all because Tomcat's pool will
> use Connection.isValid which amounts to the same thing (and will
> work for any compliant JDBC driver, not just with MySQL).
> 
>> "http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0 
>> tid=0x00007f0658387000 nid=0x7a60 runnable [0x00007f05e7466000] 
>> java.lang.Thread.State: RUNNABLE at 
>> java.net.SocketInputStream.$$YJP$$socketRead0(Native Method) at 
>> java.net.SocketInputStream.socketRead0(SocketInputStream.java)
>> at java.net.SocketInputStream.read(SocketInputStream.java:150)
>> at java.net.SocketInputStream.read(SocketInputStream.java:121) at
>>  
>> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
>
>> 
> 
> at
>> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
>
>> 
> 
> at
>> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
>
>> 
> 
> - locked <0x00000000bdf09420> (a
>> com.mysql.jdbc.util.ReadAheadInputStream) at 
>> com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549) at 
>> com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002) at 
>> com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991) at 
>> com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532) at 
>> com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002) at 
>> com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163) at 
>> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
>> - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
>> at 
>> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
>> at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842)
>> - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
>> - locked <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl)
>> at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681)
>> at 
>> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:503)
>
>> 
> 
> at
>> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:437)
>
>> 
> 
> at
>> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:763)
>
>> 
> 
> at
>> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:617)
>
>> 
> 
> at
>> org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
>
>> 
> 
> at
>> org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
>
>> 
> 
> at
>> org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
>
>> 
> 
> at
>> org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
>
>> 
> 
> at
>> org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
>
>> 
> 
> at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
>> at 
>> org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
>
>> 
> 
> at
>> org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
>
>> 
> 
> at
>> org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
>
>> 
> 
> at
>> org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:424)
>
>> 
> 
> at
>> org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348)
>
>> 
> 
> at
>> org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
>
>> 
> 
> at
>> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
>
>> 
> 
> at
>> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
>
>> 
> 
> at
>> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>
>> 
> 
> at
>> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
>
>> 
> 
> at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
>> at 
>> com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSystemTask(SynchronizationServiceImpl.java:115)
>
>> 
> 
> - locked <0x00000000a45652b8> (a
>> com.tracom.max.service.impl.SynchronizationServiceImpl) at 
>> com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(SessionServiceImpl.java:1767)
>
>> 
> 
> at
>> com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(SessionServiceImpl.java:1697)
>
>> 
> 
> at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
>> at 
>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>> 
> 
> at java.lang.reflect.Method.invoke(Method.java:483)
>> at 
>> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
>
>> 
> 
> at
>> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
>
>> 
> 
> at
>> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
>
>> 
> 
> at
>> org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
>
>> 
> 
> at
>> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
>
>> 
> 
> at
>> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
>
>> 
> 
> at
>> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>
>> 
> 
> at
>> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
>
>> 
> 
> at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
>> at 
>> com.tracom.tracomlearning.controller.InviteRaterController.processInviteRater(InviteRaterController.java:461)
>
>> 
> 
> at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
>> at 
>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>> 
> 
> at java.lang.reflect.Method.invoke(Method.java:483)
>> at 
>> org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
>
>> 
> 
> at
>> org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
>
>> 
> 
> at
>> org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
>
>> 
> 
> at
>> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
>
>> 
> 
> at
>> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
>
>> 
> 
> at
>> org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
>
>> 
> 
> at
>> org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
>
>> 
> 
> at
>> org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
>
>> 
> 
> at
>> org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
>
>> 
> 
> at
>> org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
>
>> 
> 
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
>> at 
>> org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
>
>> 
> 
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
>> at 
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
>> 
> 
> at
>> org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
>> 
> 
> at
>> com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.java:33)
>
>> 
> 
> at
>> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
>
>> 
> 
> at
>> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
>
>> 
> 
> at
>> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
>
>> 
> 
> at
>> org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
>
>> 
> 
> at
>> org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
>
>> 
> 
> at
>> org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
>> 
> 
> at
>> org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
>
>> 
> 
> at
>> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
>> 
> 
> at
>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
>> 
> 
> at
>> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
>
>> 
> 
> at
>> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
>
>> 
> 
> at
>> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
>
>> 
> 
> at
>> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
>
>> 
> 
> at
>> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
>
>> 
> 
> at
>> org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
>
>> 
> 
> at
>> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
>
>> 
> 
> at
>> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:537)
>
>> 
> 
> at
>> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1081)
>
>> 
> 
> at
>> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:658)
>
>> 
> 
> at
>> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
>
>> 
> 
> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
>
>> 
> 
> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
>
>> 
> 
> - locked <0x00000000fecbac90> (a
>> org.apache.tomcat.util.net.SecureNioChannel) at 
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>
>> 
> 
> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>
>> 
> 
> at
>> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>
>> 
> 
> at java.lang.Thread.run(Thread.java:745)
> 
> Is it possible to rule-out any network problems? Is there any
> pattern at all to the pauses?

Another thought: what do you get if you run SHOW PROCESSLIST on the
server during these long pauses?

I remember a guy who once did a START TRANSACTION and then locked up
some tables before going to lunch without either a ROLLBACK or COMMIT,
and he help up loads of transactions that were waiting to get locks
(presumably for PK sequences or whatever).

Could there be some other process that is starting a conflicting
transaction here? "SELECT 1" should require no no locks whatsoever,
but it might be something silly like contention with the query cache.
I've seen MySQL do some colossally stupid things before... maybe
something odd like that is happening, here.

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
Comment: GPGTools - http://gpgtools.org

iQIcBAEBCAAGBQJUtY8jAAoJEBzwKT+lPKRYsvUP/28Mpo5cV1Xeogqc4JWspJbi
zWwyHM1J9sLps8nYib2+DUtxBfUYaEIXtCzoZ62e4/Z1c9h/oJaECFocnvz8fSbS
Af5cPJexPSMkx6ggOLl61ymBYiZmItJwtfhwoyh+DDQmPZalFU6znJ/txHKUO5+7
MmxccIo9N/S7mmktUYaeG63MIq8v/gmH9+VsDEChYqbucK6n11EL+Y+whfntfcWS
pS18vkYlF1albiB7Epd7fl6wuoZH1hoTJsnr23lIEP42hH8Kb7yE49nIaAM/IB1D
vXMRQSWhLNZCpEWpa3wJGJk19DeTJaTcs+yuJIDtPyZxtuCPlA7zDqdTGQmLdKgf
aWq08ei6Vq5POWrIdBHJ6OHZUgsgBmMS7c53INNm7sC+XXY4hIUW5SWoZQUHERoG
3ms+LMJtaP5zhteFYc8BvptFuIHreZCL19kcaRA0W1BPnhxXKL9C1e/BJG1LCS8d
b5UH4xC4LPcmz0FF6/e9DH81SBmRTR4EWcLekFxjihtBtDxxl52GnjFFB/ynsFvd
PweCCo9R+itj5hUhFj3VQqli8DF+3/puwikHlaQjQEvi3smVP0faTSL6b89zk3uM
T/DzEIyyvvLA45qQoxFbUsDBNWvJYDbr3NZu7pty+XNupsD1Ys4mxTxce0rjHhk4
EJjblPF13mtCisFA2z/p
=9u7v
-----END PGP SIGNATURE-----

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

RE: Occasional long wait for a JDBC connection

[MW...@loftware.com]

> From: Christopher Schultz [mailto:chris@christopherschultz.net]
> Sent: Tuesday, January 13, 2015 1:05 PM
> To: Tomcat Users List
> Subject: Re: Occasional long wait for a JDBC connection
>
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Darren,
>
> On 1/13/15 11:49 AM, Darren Davis wrote:
> > The problem occurred again this morning.  I was able to generate a
> > thread dump and narrow down the source of our problem to tomcat
> thread
> > 23.
> >
> >> From 8:45:51,397 to 09:01:19,083, it was stuck in the validate check
> >> for a
> > newly instantiated connection:
> >
> > I ran the thread dump several times during this interval, and the
> > stack trace for thread 23 did not change at all.
> >
> > I did check our database log file and determined that during the 8
> > hours that led up to our first error on the server yesterday, we had
> > just a total of 12 unique connections.  The problem occurred the the
> > creation of connection # 13, which was then used several other times
> > later.
> >
> > The incident this morning also coincided with creating a new
> > connection in the pool.  It does not make any sense that the simple
> > validation query of "SELECT 1" would require a wait of 15 minutes to
> > succeed.
>
> Agreed.
>
> > It's also strange that this only happens sporadically, and not every
> > time a new connection is being "birthed" by the system.
> >
> > We've tried two different pooling technologies: DBCP and the new
> > Apache JDBC pooling on this server and both exhibit the same 15 minute
> > occasional wait.
>
> The problem is with the driver and/or database, not with the connection
> pool. It's not surprising that you are experiencing problems regardless of the
> pool being used.
>
> > we've come across documentation that suggests we could modify our
> > validation statement by prefixing it with /* ping */, which we're
> > thinking about trying
>
> Using "/* ping */" is usually a good idea for MySQL, but it may mask the
> problem. What you may find is that the next "real" query you use hangs for
> 15 minutes. If you are going to use /* ping */ and you are going to use the
> tomcat-jdbc pool, then you may as well not configure a validation query at all
> because Tomcat's pool will use Connection.isValid which amounts to the
> same thing (and will work for any compliant JDBC driver, not just with
> MySQL).
>
> > "http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0
> > tid=0x00007f0658387000 nid=0x7a60 runnable [0x00007f05e7466000]
> > java.lang.Thread.State: RUNNABLE at
> > java.net.SocketInputStream.$$YJP$$socketRead0(Native Method) at
> > java.net.SocketInputStream.socketRead0(SocketInputStream.java) at
> > java.net.SocketInputStream.read(SocketInputStream.java:150) at
> > java.net.SocketInputStream.read(SocketInputStream.java:121) at
> >
> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.jav
> > a:114)
> >
> >
> at
> >
> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfN
> ec
> > essary(ReadAheadInputStream.java:161)
> >
> >
> at
> >
> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.j
> av
> > a:189)
> >
> >
> - - locked <0x00000000bdf09420> (a
> > com.mysql.jdbc.util.ReadAheadInputStream) at
> > com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549) at
> > com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002) at
> > com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991) at
> > com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532) at
> > com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002) at
> > com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163) at
> > com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618) -
> > locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection) at
> > com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568) at
> > com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842) - locked
> > <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection) - locked
> > <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl) at
> > com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681) at
> >
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection
> > .java:503)
> >
> >
> at
> >
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection
> > .java:437)
> >
> >
> at
> >
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(Connectio
> n
> > Pool.java:763)
> >
> >
> at
> >
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(Connectio
> n
> > Pool.java:617)
> >
> >
> at
> >
> org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPoo
> > l.java:186)
> >
> >
> at
> >
> org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourcePr
> > oxy.java:127)
> >
> >
> at
> >
> org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.g
> > etConnection(LocalDataSourceConnectionProvider.java:83)
> >
> >
> at
> >
> org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManag
> er.
> > java:446)
> >
> >
> at
> >
> org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager
> .j
> > ava:167)
> >
> >
> at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
> > at
> > org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:8
> > 1)
> >
> >
> at
> > org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
> >
> >
> at
> >
> org.springframework.orm.hibernate3.HibernateTransactionManager.doBegi
> n
> > (HibernateTransactionManager.java:556)
> >
> >
> at
> > org.springframework.transaction.support.AbstractPlatformTransactionMan
> > ager.handleExistingTransaction(AbstractPlatformTransactionManager.java
> > :424)
> >
> >
> at
> > org.springframework.transaction.support.AbstractPlatformTransactionMan
> > ager.getTransaction(AbstractPlatformTransactionManager.java:348)
> >
> >
> at
> > org.springframework.transaction.interceptor.TransactionAspectSupport.c
> > reateTransactionIfNecessary(TransactionAspectSupport.java:417)
> >
> >
> at
> > org.springframework.transaction.interceptor.TransactionAspectSupport.i
> > nvokeWithinTransaction(TransactionAspectSupport.java:255)
> >
> >
> at
> > org.springframework.transaction.interceptor.TransactionInterceptor.inv
> > oke(TransactionInterceptor.java:94)
> >
> >
> at
> >
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(
> R
> > eflectiveMethodInvocation.java:172)
> >
> >
> at
> >
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDyna
> mic
> > AopProxy.java:204)
> >
> >
> at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
> > at
> > com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSys
> > temTask(SynchronizationServiceImpl.java:115)
> >
> >
> - - locked <0x00000000a45652b8> (a
> > com.tracom.max.service.impl.SynchronizationServiceImpl) at
> > com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(
> > SessionServiceImpl.java:1767)
> >
> >
> at
> > com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(Sessi
> > onServiceImpl.java:1697)
> >
> >
> at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
> > at
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
> s
> > orImpl.java:43)
> >
> >
> at java.lang.reflect.Method.invoke(Method.java:483)
> > at
> > org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflectio
> > n(AopUtils.java:317)
> >
> >
> at
> >
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoi
> > npoint(ReflectiveMethodInvocation.java:183)
> >
> >
> at
> >
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(
> R
> > eflectiveMethodInvocation.java:150)
> >
> >
> at
> > org.springframework.transaction.interceptor.TransactionInterceptor$1.p
> > roceedWithInvocation(TransactionInterceptor.java:96)
> >
> >
> at
> > org.springframework.transaction.interceptor.TransactionAspectSupport.i
> > nvokeWithinTransaction(TransactionAspectSupport.java:260)
> >
> >
> at
> > org.springframework.transaction.interceptor.TransactionInterceptor.inv
> > oke(TransactionInterceptor.java:94)
> >
> >
> at
> >
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(
> R
> > eflectiveMethodInvocation.java:172)
> >
> >
> at
> >
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDyna
> mic
> > AopProxy.java:204)
> >
> >
> at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
> > at
> > com.tracom.tracomlearning.controller.InviteRaterController.processInvi
> > teRater(InviteRaterController.java:461)
> >
> >
> at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
> > at
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
> s
> > orImpl.java:43)
> >
> >
> at java.lang.reflect.Method.invoke(Method.java:483)
> > at
> >
> org.springframework.web.method.support.InvocableHandlerMethod.invok
> e(I
> > nvocableHandlerMethod.java:215)
> >
> >
> at
> >
> org.springframework.web.method.support.InvocableHandlerMethod.invok
> eFo
> > rRequest(InvocableHandlerMethod.java:132)
> >
> >
> at
> >
> org.springframework.web.servlet.mvc.method.annotation.ServletInvocable
> >
> HandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104
> )
> >
> >
> at
> >
> org.springframework.web.servlet.mvc.method.annotation.RequestMapping
> Ha
> >
> ndlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:7
> 45)
> >
> >
> at
> >
> org.springframework.web.servlet.mvc.method.annotation.RequestMapping
> Ha
> > ndlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
> >
> >
> at
> >
> org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAda
> pte
> > r.handle(AbstractHandlerMethodAdapter.java:80)
> >
> >
> at
> > org.springframework.web.servlet.DispatcherServlet.doDispatch(Dispatche
> > rServlet.java:919)
> >
> >
> at
> > org.springframework.web.servlet.DispatcherServlet.doService(Dispatcher
> > Servlet.java:851)
> >
> >
> at
> >
> org.springframework.web.servlet.FrameworkServlet.processRequest(Frame
> w
> > orkServlet.java:953)
> >
> >
> at
> >
> org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkSer
> vl
> > et.java:855)
> >
> >
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
> > at
> >
> org.springframework.web.servlet.FrameworkServlet.service(FrameworkSer
> v
> > let.java:829)
> >
> >
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
> > at
> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli
> > cationFilterChain.java:291)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi
> > lterChain.java:206)
> >
> >
> at
> > org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli
> > cationFilterChain.java:239)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi
> > lterChain.java:206)
> >
> >
> at
> > com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.j
> > ava:33)
> >
> >
> at
> > org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRe
> > questFilter.java:106)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli
> > cationFilterChain.java:239)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi
> > lterChain.java:206)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:330)
> >
> >
> at
> > org.springframework.security.web.access.intercept.FilterSecurityInterc
> > eptor.invoke(FilterSecurityInterceptor.java:118)
> >
> >
> at
> > org.springframework.security.web.access.intercept.FilterSecurityInterc
> > eptor.doFilter(FilterSecurityInterceptor.java:84)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.access.ExceptionTranslationFilter.doF
> > ilter(ExceptionTranslationFilter.java:113)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.session.SessionManagementFilter.doFil
> > ter(SessionManagementFilter.java:103)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> >
> org.springframework.security.web.authentication.AnonymousAuthenticatio
> > nFilter.doFilter(AnonymousAuthenticationFilter.java:113)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.servletapi.SecurityContextHolderAware
> > RequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54
> > )
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> >
> org.springframework.security.web.savedrequest.RequestCacheAwareFilter.
> > doFilter(RequestCacheAwareFilter.java:45)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.authentication.www.BasicAuthenticatio
> > nFilter.doFilter(BasicAuthenticationFilter.java:150)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.authentication.AbstractAuthentication
> > ProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:
> > 183)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.authentication.logout.LogoutFilter.do
> > Filter(LogoutFilter.java:105)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.context.SecurityContextPersistenceFil
> > ter.doFilter(SecurityContextPersistenceFilter.java:87)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy$VirtualFilterChain.d
> > oFilter(FilterChainProxy.java:342)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy.doFilterInternal(Fil
> > terChainProxy.java:192)
> >
> >
> at
> > org.springframework.security.web.FilterChainProxy.doFilter(FilterChain
> > Proxy.java:160)
> >
> >
> at
> > org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(De
> > legatingFilterProxy.java:343)
> >
> >
> at
> > org.springframework.web.filter.DelegatingFilterProxy.doFilter(Delegati
> > ngFilterProxy.java:260)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli
> > cationFilterChain.java:239)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi
> > lterChain.java:206)
> >
> >
> at
> > org.springframework.web.filter.CharacterEncodingFilter.doFilterInterna
> > l(CharacterEncodingFilter.java:88)
> >
> >
> at
> > org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRe
> > questFilter.java:106)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appli
> > cationFilterChain.java:239)
> >
> >
> at
> > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFi
> > lterChain.java:206)
> >
> >
> at
> >
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperV
> a
> > lve.java:219)
> >
> >
> at
> >
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextVa
> > lve.java:106)
> >
> >
> at
> > org.apache.catalina.authenticator.AuthenticatorBase.invoke(Authenticat
> > orBase.java:506)
> >
> >
> at
> > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.ja
> > va:142)
> >
> >
> at
> > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.ja
> > va:79)
> >
> >
> at
> > org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAcces
> > sLogValve.java:610)
> >
> >
> at
> > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValv
> > e.java:88)
> >
> >
> at
> > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java
> > :537)
> >
> >
> at
> > org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp1
> > 1Processor.java:1081)
> >
> >
> at
> >
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(A
> > bstractProtocol.java:658)
> >
> >
> at
> >
> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.pro
> > cess(Http11NioProtocol.java:222)
> >
> >
> at
> >
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoi
> > nt.java:1566)
> >
> >
> at
> > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint
> > .java:1523)
> >
> >
> - - locked <0x00000000fecbac90> (a
> > org.apache.tomcat.util.net.SecureNioChannel) at
> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.j
> > ava:1142)
> >
> >
> at
> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.
> > java:617)
> >
> >
> at
> >
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThr
> > ead.java:61)
> >
> >
> at java.lang.Thread.run(Thread.java:745)
>
> Is it possible to rule-out any network problems? Is there any pattern at all to
> the pauses?
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1
> Comment: GPGTools - http://gpgtools.org
>
> iQIcBAEBCAAGBQJUtV5CAAoJEBzwKT+lPKRYpOgP/RNMzeCZf1NdihufZvs26a
> s6
> AfvsJik+W7w5FPh6McxF+fIv14KMCftxV+gthoFi6M5XemQndBmt/iWiCfA5DEi
> E
> QeLM8uY3HNP6gWJbpNvyV+TLu87+TVusJG/7QjNi+FvdBdWalwnBQ658P/jU
> gITr
> VVkheN2RHzTtgCLTAjcah9eAibeGV8sr/5jikeuVGCxj7JdGwkxuJBAtT7XNc6VY
> oF0N0SmsLCukEWPzNuc5dhLFMhiNnbBEnRvIuLyCyG5i/CaPvDzJnaxBEZcyXC
> P/
> /BLvwIzOeb22Sx9l1NVU3CLogaLW+UYjraD9FMcADG7KIZn5NFxLpCbdkjOdYq
> Yw
> yLb+mNH31JSoRJErb2cfJzu+JYQYKDCa+5eIcQrDZ561gGDd5oDQBdW/0hQADf
> mF
> D4NGc1epCiFh3Fbx26ti1h5gYrZO1GVBlpU6JESaIPUBCEDO0stbGx9avPxlrr0k
> szLTWvigz7YOFKhdgVuXdXogxQdEcbICGUDrPOhOLQJJN4+RAuqZI1xSQPH+
> M0cQ
> WSgl7vNZT1R66aa3doYtmFdypSPGCIrJ24vz4cuOtiRvADW7hca5X5D+tig1/7EL
> 38mzJ/5U7p90kxTzPe1UYQEu3rv5EG10ER8VLuVUUl0lIByhx6lZuluc038dD+4i
> o0YGlRfVHb4I3YmZyQk6
> =/ayz
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>


 There are numerous MySQL/Connector J bugs that are related to the stacktrace you sent, and more or less match the symptoms you are seeing, most around incorrect threading.    See #9515, #24995, #56411, #74979.

Re: Occasional long wait for a JDBC connection

[Christopher Schultz <ch...@christopherschultz.net>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Darren,

On 1/13/15 11:49 AM, Darren Davis wrote:
> The problem occurred again this morning.  I was able to generate a
> thread dump and narrow down the source of our problem to tomcat
> thread 23.
> 
>> From 8:45:51,397 to 09:01:19,083, it was stuck in the validate
>> check for a
> newly instantiated connection:
> 
> I ran the thread dump several times during this interval, and the
> stack trace for thread 23 did not change at all.
> 
> I did check our database log file and determined that during the 8
> hours that led up to our first error on the server yesterday, we
> had just a total of 12 unique connections.  The problem occurred
> the the creation of connection # 13, which was then used several
> other times later.
> 
> The incident this morning also coincided with creating a new
> connection in the pool.  It does not make any sense that the simple
> validation query of "SELECT 1" would require a wait of 15 minutes
> to succeed.

Agreed.

> It's also strange that this only happens sporadically, and not
> every time a new connection is being "birthed" by the system.
> 
> We've tried two different pooling technologies: DBCP and the new
> Apache JDBC pooling on this server and both exhibit the same 15
> minute occasional wait.

The problem is with the driver and/or database, not with the
connection pool. It's not surprising that you are experiencing
problems regardless of the pool being used.

> we've come across documentation that suggests we could modify our 
> validation statement by prefixing it with /* ping */, which we're
> thinking about trying

Using "/* ping */" is usually a good idea for MySQL, but it may mask
the problem. What you may find is that the next "real" query you use
hangs for 15 minutes. If you are going to use /* ping */ and you are
going to use the tomcat-jdbc pool, then you may as well not configure
a validation query at all because Tomcat's pool will use
Connection.isValid which amounts to the same thing (and will work for
any compliant JDBC driver, not just with MySQL).

> "http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0
> tid=0x00007f0658387000 nid=0x7a60 runnable [0x00007f05e7466000] 
> java.lang.Thread.State: RUNNABLE at
> java.net.SocketInputStream.$$YJP$$socketRead0(Native Method) at
> java.net.SocketInputStream.socketRead0(SocketInputStream.java) at
> java.net.SocketInputStream.read(SocketInputStream.java:150) at
> java.net.SocketInputStream.read(SocketInputStream.java:121) at 
> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
>
> 
at
> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
>
> 
at
> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
>
> 
- - locked <0x00000000bdf09420> (a
> com.mysql.jdbc.util.ReadAheadInputStream) at
> com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549) at
> com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002) at
> com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991) at
> com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532) at
> com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002) at
> com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163) at
> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618) -
> locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection) at
> com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568) at
> com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842) -
> locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection) -
> locked <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl) at
> com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681) at 
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:503)
>
> 
at
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:437)
>
> 
at
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:763)
>
> 
at
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:617)
>
> 
at
> org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
>
> 
at
> org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
>
> 
at
> org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
>
> 
at
> org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
>
> 
at
> org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
>
> 
at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
> at 
> org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
>
> 
at
> org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
>
> 
at
> org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
>
> 
at
> org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:424)
>
> 
at
> org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348)
>
> 
at
> org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
>
> 
at
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
>
> 
at
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
>
> 
at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>
> 
at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
>
> 
at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
> at 
> com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSystemTask(SynchronizationServiceImpl.java:115)
>
> 
- - locked <0x00000000a45652b8> (a
> com.tracom.max.service.impl.SynchronizationServiceImpl) at 
> com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(SessionServiceImpl.java:1767)
>
> 
at
> com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(SessionServiceImpl.java:1697)
>
> 
at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
> at 
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
> 
at java.lang.reflect.Method.invoke(Method.java:483)
> at 
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
>
> 
at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
>
> 
at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
>
> 
at
> org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
>
> 
at
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
>
> 
at
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
>
> 
at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>
> 
at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
>
> 
at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
> at 
> com.tracom.tracomlearning.controller.InviteRaterController.processInviteRater(InviteRaterController.java:461)
>
> 
at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
> at 
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
> 
at java.lang.reflect.Method.invoke(Method.java:483)
> at 
> org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
>
> 
at
> org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
>
> 
at
> org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
>
> 
at
> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
>
> 
at
> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
>
> 
at
> org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
>
> 
at
> org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
>
> 
at
> org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
>
> 
at
> org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
>
> 
at
> org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
>
> 
at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
> at 
> org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
>
> 
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
> at 
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
> 
at
> org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
> 
at
> com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.java:33)
>
> 
at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
>
> 
at
> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
>
> 
at
> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
>
> 
at
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>
> 
at
> org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
>
> 
at
> org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
>
> 
at
> org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
>
> 
at
> org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
> 
at
> org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
>
> 
at
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>
> 
at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>
> 
at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
>
> 
at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
>
> 
at
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
>
> 
at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
>
> 
at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
>
> 
at
> org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
>
> 
at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
>
> 
at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:537)
>
> 
at
> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1081)
>
> 
at
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:658)
>
> 
at
> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
>
> 
at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
>
> 
at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
>
> 
- - locked <0x00000000fecbac90> (a
> org.apache.tomcat.util.net.SecureNioChannel) at 
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>
> 
at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>
> 
at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>
> 
at java.lang.Thread.run(Thread.java:745)

Is it possible to rule-out any network problems? Is there any pattern
at all to the pauses?

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1
Comment: GPGTools - http://gpgtools.org

iQIcBAEBCAAGBQJUtV5CAAoJEBzwKT+lPKRYpOgP/RNMzeCZf1NdihufZvs26as6
AfvsJik+W7w5FPh6McxF+fIv14KMCftxV+gthoFi6M5XemQndBmt/iWiCfA5DEiE
QeLM8uY3HNP6gWJbpNvyV+TLu87+TVusJG/7QjNi+FvdBdWalwnBQ658P/jUgITr
VVkheN2RHzTtgCLTAjcah9eAibeGV8sr/5jikeuVGCxj7JdGwkxuJBAtT7XNc6VY
oF0N0SmsLCukEWPzNuc5dhLFMhiNnbBEnRvIuLyCyG5i/CaPvDzJnaxBEZcyXCP/
/BLvwIzOeb22Sx9l1NVU3CLogaLW+UYjraD9FMcADG7KIZn5NFxLpCbdkjOdYqYw
yLb+mNH31JSoRJErb2cfJzu+JYQYKDCa+5eIcQrDZ561gGDd5oDQBdW/0hQADfmF
D4NGc1epCiFh3Fbx26ti1h5gYrZO1GVBlpU6JESaIPUBCEDO0stbGx9avPxlrr0k
szLTWvigz7YOFKhdgVuXdXogxQdEcbICGUDrPOhOLQJJN4+RAuqZI1xSQPH+M0cQ
WSgl7vNZT1R66aa3doYtmFdypSPGCIrJ24vz4cuOtiRvADW7hca5X5D+tig1/7EL
38mzJ/5U7p90kxTzPe1UYQEu3rv5EG10ER8VLuVUUl0lIByhx6lZuluc038dD+4i
o0YGlRfVHb4I3YmZyQk6
=/ayz
-----END PGP SIGNATURE-----

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Occasional long wait for a JDBC connection

[Daniel Mikusa <dm...@pivotal.io>]

On Tue, Jan 13, 2015 at 11:49 AM, Darren Davis <da...@virtualvoodoo.net>
wrote:

First thing, please don't top post.  The convention followed on this list
is to either reply inline, like this, or reply at the bottom.

The problem occurred again this morning.  I was able to generate a thread
> dump and narrow down the source of our problem to tomcat thread 23.
>
> From 8:45:51,397 to 09:01:19,083, it was stuck in the validate check for a
> newly instantiated connection:
>
> I ran the thread dump several times during this interval, and the stack
> trace for thread 23 did not change at all.
>
> I did check our database log file and determined that during the 8 hours
> that led up to our first error on the server yesterday, we had just a total
> of 12 unique connections.  The problem occurred the the creation of
> connection # 13, which was then used several other times later.
>
> The incident this morning also coincided with creating a new connection in
> the pool.  It does not make any sense that the simple validation query of
> "SELECT 1" would require a wait of 15 minutes to succeed.
>

I would agree.  If things are working properly the validation request
should return very quickly.  As to what's happening here I can't say
exactly, but do you by chance have a firewall in between Tomcat and the
database?

What can sometimes happen when there's a firewall between Tomcat and the
database that causes similar behavior is that the firewall will disconnect
persistent idle connections (your db connections) after a certain period of
time (often 30 or 60 minutes).  Depending on how the firewall is configured
it may just passively drop packets for that connection.  In this case,
there's no way to know what's happened and it can take a considerable
amount of time for the connection to timeout.

If this is what's happening, you have a couple possibilities for working
around it.

   - configure an idle validation test (i.e. testWhileIdle and friends).
This should periodically send traffic, in the form of a validation query,
to each connection sitting idle in the pool.

   - set maxAge to something less than the limit set by the firewall.  If
using Tomcat's jdbc-pool (not sure if this is supported by other pools), it
will throw out connections older than this value (in ms).

   - reconfigure your idle limits so you don't have as many idle
connections.  You've likely got connections sitting idle in the pool for a
very long time, which means you probably don't need that many idle
connections.  If you lower this, the connections might get used more and
not be closed by the firewall.

There's probably other possible fixes as well, those are in no particular
order and just the first ones that came to mind.


> It's also strange that this only happens sporadically, and not every time a
> new connection is being "birthed" by the system.
>
> We've tried two different pooling technologies: DBCP and the new Apache
> JDBC pooling on this server and both exhibit the same 15 minute occasional
> wait.
>
> we've come across documentation that suggests we could modify our
> validation statement by prefixing it with /* ping */, which we're thinking
> about trying
>

I don't think this will help here, but it's a good idea.  It's an
optimization for the MySQL jdbc driver that should make your validation
queries faster.

Dan


>
>
> "http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0 tid=0x00007f0658387000
> nid=0x7a60 runnable [0x00007f05e7466000]
>    java.lang.Thread.State: RUNNABLE
>         at java.net.SocketInputStream.$$YJP$$socketRead0(Native Method)
>         at java.net.SocketInputStream.socketRead0(SocketInputStream.java)
>         at java.net.SocketInputStream.read(SocketInputStream.java:150)
>         at java.net.SocketInputStream.read(SocketInputStream.java:121)
>         at
>
> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
>         at
>
> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
>         at
>
> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
>         - locked <0x00000000bdf09420> (a
> com.mysql.jdbc.util.ReadAheadInputStream)
>         at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549)
>         at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
>         at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
>         at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
>         at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
>         at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
>         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
>         - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
>         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
>         at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842)
>         - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
>         - locked <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl)
>         at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681)
>         at
>
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:503)
>         at
>
> org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:437)
>         at
>
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:763)
>         at
>
> org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:617)
>         at
>
> org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
>         at
>
> org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
>         at
>
> org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
>         at
>
> org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
>         at
>
> org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
>         at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
>         at
> org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
>         at
> org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
>         at
>
> org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
>         at
>
> org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:424)
>         at
>
> org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348)
>         at
>
> org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
>         at
>
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
>         at
>
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
>         at
>
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>         at
>
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
>         at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
>         at
>
> com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSystemTask(SynchronizationServiceImpl.java:115)
>         - locked <0x00000000a45652b8> (a
> com.tracom.max.service.impl.SynchronizationServiceImpl)
>         at
>
> com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(SessionServiceImpl.java:1767)
>         at
>
> com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(SessionServiceImpl.java:1697)
>         at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
>         at
>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:483)
>         at
>
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
>         at
>
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
>         at
>
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
>         at
>
> org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
>         at
>
> org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
>         at
>
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
>         at
>
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>         at
>
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
>         at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
>         at
>
> com.tracom.tracomlearning.controller.InviteRaterController.processInviteRater(InviteRaterController.java:461)
>         at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
>         at
>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:483)
>         at
>
> org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
>         at
>
> org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
>         at
>
> org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
>         at
>
> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
>         at
>
> org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
>         at
>
> org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
>         at
>
> org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
>         at
>
> org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
>         at
>
> org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
>         at
>
> org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
>         at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
>         at
>
> org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
>         at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>         at
> org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>         at
>
> com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.java:33)
>         at
>
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
>        at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
>         at
>
> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
>         at
>
> org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
>         at
>
> org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
>         at
>
> org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
>         at
>
> org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
>         at
>
> org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
>         at
>
> org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>         at
>
> org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
>         at
>
> org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
>         at
>
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
>         at
>
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
>         at
>
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
>         at
>
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
>         at
>
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
>         at
>
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
>         at
>
> org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
>         at
>
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
>         at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:537)
>         at
>
> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1081)
>         at
>
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:658)
>         at
>
> org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
>         at
>
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
>         at
>
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
>         - locked <0x00000000fecbac90> (a
> org.apache.tomcat.util.net.SecureNioChannel)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>         at
>
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>         at java.lang.Thread.run(Thread.java:745)
>
> On Tue, Jan 13, 2015 at 8:21 AM, Daniel Mikusa <dm...@pivotal.io> wrote:
>
> > On Tue, Jan 13, 2015 at 9:51 AM, Darren Davis <da...@virtualvoodoo.net>
> > wrote:
> >
> > > Recently we deployed our production application on a Tomcat 8.0.14 web
> > > server.  We are using the Tomcat JDBC Connection pool against MySQL 5.
> > Our
> > > web application uses Spring (3.2.11.RELEASE) /Hibernate (3.6.10.Final)
> > for
> > > transaction management.  We are using a Cent OS 6 linux server in the
> > cloud
> > > running the 2.6.32-504 kernel.  We're using the 1.8.0_25 jdk.
> > >
> > >
> > >
> > > Ever since deployment, we've noticed that a couple of times per day,
> when
> > > Spring is attempting to prepare/open a new JDBC Connection, the thread
> in
> > > question times out for about 15 minutes, and then resumes as if
> > everything
> > > is fine.
> > >
> >
> > What's the CPU usage like at this time?  Seems unlikely, but maybe your
> in
> > the middle of a massive full GC.
> >
> >
> > >
> > > The line that appears to be hanging from the hibernate side is
> > > factory.getConnectionProvider().getConnection(), which I think simply
> > asks
> > > for a connection from the pool.
> > >
> >
> > Out of curiosity how did you determine this?  Did you take a thread dump?
> > If not, that would be a good place to start.  Grab three or four thread
> > dumps during that 15 minute window.  The thread dump will tell you
> exactly
> > what's happening in the thread at the time.  Looking at multiple dumps
> will
> > also show you if the thread has progressed from one dump to the next.
> >
> > Instructions for taking at thread dump can be found here:
> >
> >
> >
> >
> http://wiki.apache.org/tomcat/HowTo#How_do_I_obtain_a_thread_dump_of_my_running_webapp_.3F
> >
> > Dan
> >
> >
> > >
> > > The following options are defined in the Resource definition:
> > > auth="Container"
> > > factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
> > > type="javax.sql.DataSource"
> > > driverClassName="com.mysql.jdbc.Driver"
> > > maxActive=500
> > > maxIdle=55
> > > maxWait=15000
> > > validationQuery="Select 1"
> > > testOnBorrow="true"
> > > defaultAutoCommit="false"
> > >
> > > At this time of year, our user load peaks around 150, so we shouldn't
> be
> > > coming close to the maxActive defined.  MySql is configured to allow
> for
> > > 1010 maximum connections (we have two Tomcat instances that point to
> it,
> > > configured similarly)
> >
> >
> > > This application has ran for years without a problem against a Tomcat 6
> > > instance, but after moving to Jdk 8 and Tomcat 8, we're seeing this 15
> > > minute wait.
> > >
> > > Any ideas on what could cause this sort of thing, and as there
> additional
> > > logging we could turn on to try and figure out what is happening inside
> > the
> > > pool to make it wait so long?
> > >
> >
>

Re: Occasional long wait for a JDBC connection

[Darren Davis <da...@virtualvoodoo.net>]

The problem occurred again this morning.  I was able to generate a thread
dump and narrow down the source of our problem to tomcat thread 23.

>From 8:45:51,397 to 09:01:19,083, it was stuck in the validate check for a
newly instantiated connection:

I ran the thread dump several times during this interval, and the stack
trace for thread 23 did not change at all.

I did check our database log file and determined that during the 8 hours
that led up to our first error on the server yesterday, we had just a total
of 12 unique connections.  The problem occurred the the creation of
connection # 13, which was then used several other times later.

The incident this morning also coincided with creating a new connection in
the pool.  It does not make any sense that the simple validation query of
"SELECT 1" would require a wait of 15 minutes to succeed.

It's also strange that this only happens sporadically, and not every time a
new connection is being "birthed" by the system.

We've tried two different pooling technologies: DBCP and the new Apache
JDBC pooling on this server and both exhibit the same 15 minute occasional
wait.

we've come across documentation that suggests we could modify our
validation statement by prefixing it with /* ping */, which we're thinking
about trying


"http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0 tid=0x00007f0658387000
nid=0x7a60 runnable [0x00007f05e7466000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.$$YJP$$socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead0(SocketInputStream.java)
        at java.net.SocketInputStream.read(SocketInputStream.java:150)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
        at
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
        at
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
        - locked <0x00000000bdf09420> (a
com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
        - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
        at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842)
        - locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
        - locked <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl)
        at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681)
        at
org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:503)
        at
org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:437)
        at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:763)
        at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:617)
        at
org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
        at
org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
        at
org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
        at
org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
        at
org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
        at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
        at
org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
        at
org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
        at
org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
        at
org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:424)
        at
org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348)
        at
org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
        at
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
        at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
        at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
        at
com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSystemTask(SynchronizationServiceImpl.java:115)
        - locked <0x00000000a45652b8> (a
com.tracom.max.service.impl.SynchronizationServiceImpl)
        at
com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(SessionServiceImpl.java:1767)
        at
com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(SessionServiceImpl.java:1697)
        at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:483)
        at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
        at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
        at
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
        at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
        at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
        at
com.tracom.tracomlearning.controller.InviteRaterController.processInviteRater(InviteRaterController.java:461)
        at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:483)
        at
org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
        at
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
        at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
        at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
        at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
        at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
        at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
        at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
        at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
        at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
        at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at
com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.java:33)
        at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
       at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
        at
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
        at
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
        at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
        at
org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
        at
org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
        at
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
        at
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
        at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
        at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
        at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
        at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
        at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
        at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
        at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
        at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:537)
        at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1081)
        at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:658)
        at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
        at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
        at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
        - locked <0x00000000fecbac90> (a
org.apache.tomcat.util.net.SecureNioChannel)
        at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

On Tue, Jan 13, 2015 at 8:21 AM, Daniel Mikusa <dm...@pivotal.io> wrote:

> On Tue, Jan 13, 2015 at 9:51 AM, Darren Davis <da...@virtualvoodoo.net>
> wrote:
>
> > Recently we deployed our production application on a Tomcat 8.0.14 web
> > server.  We are using the Tomcat JDBC Connection pool against MySQL 5.
> Our
> > web application uses Spring (3.2.11.RELEASE) /Hibernate (3.6.10.Final)
> for
> > transaction management.  We are using a Cent OS 6 linux server in the
> cloud
> > running the 2.6.32-504 kernel.  We're using the 1.8.0_25 jdk.
> >
> >
> >
> > Ever since deployment, we've noticed that a couple of times per day, when
> > Spring is attempting to prepare/open a new JDBC Connection, the thread in
> > question times out for about 15 minutes, and then resumes as if
> everything
> > is fine.
> >
>
> What's the CPU usage like at this time?  Seems unlikely, but maybe your in
> the middle of a massive full GC.
>
>
> >
> > The line that appears to be hanging from the hibernate side is
> > factory.getConnectionProvider().getConnection(), which I think simply
> asks
> > for a connection from the pool.
> >
>
> Out of curiosity how did you determine this?  Did you take a thread dump?
> If not, that would be a good place to start.  Grab three or four thread
> dumps during that 15 minute window.  The thread dump will tell you exactly
> what's happening in the thread at the time.  Looking at multiple dumps will
> also show you if the thread has progressed from one dump to the next.
>
> Instructions for taking at thread dump can be found here:
>
>
>
> http://wiki.apache.org/tomcat/HowTo#How_do_I_obtain_a_thread_dump_of_my_running_webapp_.3F
>
> Dan
>
>
> >
> > The following options are defined in the Resource definition:
> > auth="Container"
> > factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
> > type="javax.sql.DataSource"
> > driverClassName="com.mysql.jdbc.Driver"
> > maxActive=500
> > maxIdle=55
> > maxWait=15000
> > validationQuery="Select 1"
> > testOnBorrow="true"
> > defaultAutoCommit="false"
> >
> > At this time of year, our user load peaks around 150, so we shouldn't be
> > coming close to the maxActive defined.  MySql is configured to allow for
> > 1010 maximum connections (we have two Tomcat instances that point to it,
> > configured similarly)
>
>
> > This application has ran for years without a problem against a Tomcat 6
> > instance, but after moving to Jdk 8 and Tomcat 8, we're seeing this 15
> > minute wait.
> >
> > Any ideas on what could cause this sort of thing, and as there additional
> > logging we could turn on to try and figure out what is happening inside
> the
> > pool to make it wait so long?
> >
>

Re: Occasional long wait for a JDBC connection

[Daniel Mikusa <dm...@pivotal.io>]

On Tue, Jan 13, 2015 at 9:51 AM, Darren Davis <da...@virtualvoodoo.net>
wrote:

> Recently we deployed our production application on a Tomcat 8.0.14 web
> server.  We are using the Tomcat JDBC Connection pool against MySQL 5.  Our
> web application uses Spring (3.2.11.RELEASE) /Hibernate (3.6.10.Final) for
> transaction management.  We are using a Cent OS 6 linux server in the cloud
> running the 2.6.32-504 kernel.  We're using the 1.8.0_25 jdk.
>
>
>
> Ever since deployment, we've noticed that a couple of times per day, when
> Spring is attempting to prepare/open a new JDBC Connection, the thread in
> question times out for about 15 minutes, and then resumes as if everything
> is fine.
>

What's the CPU usage like at this time?  Seems unlikely, but maybe your in
the middle of a massive full GC.


>
> The line that appears to be hanging from the hibernate side is
> factory.getConnectionProvider().getConnection(), which I think simply asks
> for a connection from the pool.
>

Out of curiosity how did you determine this?  Did you take a thread dump?
If not, that would be a good place to start.  Grab three or four thread
dumps during that 15 minute window.  The thread dump will tell you exactly
what's happening in the thread at the time.  Looking at multiple dumps will
also show you if the thread has progressed from one dump to the next.

Instructions for taking at thread dump can be found here:


http://wiki.apache.org/tomcat/HowTo#How_do_I_obtain_a_thread_dump_of_my_running_webapp_.3F

Dan


>
> The following options are defined in the Resource definition:
> auth="Container"
> factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
> type="javax.sql.DataSource"
> driverClassName="com.mysql.jdbc.Driver"
> maxActive=500
> maxIdle=55
> maxWait=15000
> validationQuery="Select 1"
> testOnBorrow="true"
> defaultAutoCommit="false"
>
> At this time of year, our user load peaks around 150, so we shouldn't be
> coming close to the maxActive defined.  MySql is configured to allow for
> 1010 maximum connections (we have two Tomcat instances that point to it,
> configured similarly)


> This application has ran for years without a problem against a Tomcat 6
> instance, but after moving to Jdk 8 and Tomcat 8, we're seeing this 15
> minute wait.
>
> Any ideas on what could cause this sort of thing, and as there additional
> logging we could turn on to try and figure out what is happening inside the
> pool to make it wait so long?
>