You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@commons.apache.org by sebb <se...@gmail.com> on 2010/01/13 08:51:44 UTC
[DBCP] Continuum failure - discussion of timings
Here is the output from
http://vmbuild.apache.org/continuum/buildResult.action?buildId=268733&projectId=22
I've rearranged it so the threads are in ConnectionStart order.
I moved ConnectionStart to the beginning, added the Thread number at
the end (dropping irrelevant stuff), and deleted the prefix
"ConnectStart: 355958"
7635. StartupDelay: 13. ConnectTime: 2. Runtime: 218. 1
7637. StartupDelay: 0. ConnectTime: 280. Runtime: 481. 2
7724. StartupDelay: 0. ConnectTime: 193. Runtime: 394. 4
7737. StartupDelay: 13. ConnectTime: 180. Runtime: 381. 5
7750. StartupDelay: 112. ConnectTime: 167. Runtime: 368. 3
7775. StartupDelay: 38. ConnectTime: 142. Runtime: 343. 6
7785. StartupDelay: 10. ConnectTime: 132. Runtime: 333. 7
7816. StartupDelay: 31. ConnectTime: 101. Runtime: 302. 8
7853. StartupDelay: 38. ConnectTime: 1. Runtime: 202. 9
7865. StartupDelay: 11. ConnectTime: 52. Runtime: 252. 10
7874. StartupDelay: 9. ConnectTime: 43. Runtime: 243. 11
7918. StartupDelay: 44. ConnectTime: -. Runtime: 109. 12
7927. StartupDelay: 9. ConnectTime: -. Runtime: 113. 13
7941. StartupDelay: 14. ConnectTime: -. Runtime: 104. 14
7944. StartupDelay: 3. ConnectTime: -. Runtime: 101. 15
7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 17
7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 18
7953. StartupDelay: 0. ConnectTime: -. Runtime: 101. 19
7954. StartupDelay: 1. ConnectTime: -. Runtime: 100. 20
7954. StartupDelay: 10. ConnectTime: -. Runtime: 100. 16
It can be seen that thread 2 reaches the getConnection() method some
while before the next thread (7724-7637=87ms) yet takes longer than
any of the other threads to return from the method.
This could mean that there is a window somewhere in the code that
causes this thread to pause whilst others progress. There does seem to
be a problem here.
I need to do a bit more analysis on the numbers (and perhaps update
the debug) to see how the connected threads overlap.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by Phil Steitz <ph...@gmail.com>.
sebb wrote:
> Here is the output from
> http://vmbuild.apache.org/continuum/buildResult.action?buildId=268733&projectId=22
>
> I've rearranged it so the threads are in ConnectionStart order.
> I moved ConnectionStart to the beginning, added the Thread number at
> the end (dropping irrelevant stuff), and deleted the prefix
> "ConnectStart: 355958"
>
> 7635. StartupDelay: 13. ConnectTime: 2. Runtime: 218. 1
> 7637. StartupDelay: 0. ConnectTime: 280. Runtime: 481. 2
> 7724. StartupDelay: 0. ConnectTime: 193. Runtime: 394. 4
> 7737. StartupDelay: 13. ConnectTime: 180. Runtime: 381. 5
> 7750. StartupDelay: 112. ConnectTime: 167. Runtime: 368. 3
> 7775. StartupDelay: 38. ConnectTime: 142. Runtime: 343. 6
> 7785. StartupDelay: 10. ConnectTime: 132. Runtime: 333. 7
> 7816. StartupDelay: 31. ConnectTime: 101. Runtime: 302. 8
> 7853. StartupDelay: 38. ConnectTime: 1. Runtime: 202. 9
> 7865. StartupDelay: 11. ConnectTime: 52. Runtime: 252. 10
> 7874. StartupDelay: 9. ConnectTime: 43. Runtime: 243. 11
> 7918. StartupDelay: 44. ConnectTime: -. Runtime: 109. 12
> 7927. StartupDelay: 9. ConnectTime: -. Runtime: 113. 13
> 7941. StartupDelay: 14. ConnectTime: -. Runtime: 104. 14
> 7944. StartupDelay: 3. ConnectTime: -. Runtime: 101. 15
> 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 17
> 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 18
> 7953. StartupDelay: 0. ConnectTime: -. Runtime: 101. 19
> 7954. StartupDelay: 1. ConnectTime: -. Runtime: 100. 20
> 7954. StartupDelay: 10. ConnectTime: -. Runtime: 100. 16
>
> It can be seen that thread 2 reaches the getConnection() method some
> while before the next thread (7724-7637=87ms) yet takes longer than
> any of the other threads to return from the method.
>
> This could mean that there is a window somewhere in the code that
> causes this thread to pause whilst others progress. There does seem to
> be a problem here.
>
> I need to do a bit more analysis on the numbers (and perhaps update
> the debug) to see how the connected threads overlap.
Interesting and consistent with the last failed run. Neither of
these really explains anything, but two things to note:
1) The one obvious difference between to consider is the thread that
registers the pool. Should not stall because of that and synch in
registerPool will halt all others while it is completing.
2) Look at borrowObject in GKOP. When maxWait is positive and when
exhausted action is block, the client thread will wait for maxWait
ms and before exiting with a failure when the wait has ended it will
look to see if an instance has been allocated to it. If so, it will
happily grab that instance and succeed. This makes it possible to
exceed maxWait by timing accuracy of wait + a time it takes to
acquire a lock on the pool to check for an allocated object.
It could be that what is going on is that while thread 2 is waiting
to acquire the pool lock in this section, another thread comes in
and returns an instance. Timing computations do not work; however,
as there should not be enough elapsed time for the other thread to
release its instance.
Phil
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> For additional commands, e-mail: dev-help@commons.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by Phil Steitz <ph...@gmail.com>.
sebb wrote:
> On 14/01/2010, Phil Steitz <ph...@gmail.com> wrote:
>> On 1/14/10, sebb <se...@gmail.com> wrote:
>> >
>> > On 14/01/2010, Phil Steitz <ph...@gmail.com> wrote:
>> > > Unless I am reading the output of the latest failures wrong or we
>> > > are picking up the wrong hashcode (should be innermost delegate),
>> >
>> > It's currently the connection returned by getConnection().
>> > I'll fix that.
>>
>>
>>
>> Should actually be correct as is. As you recall from equals() discussion,.
>> DelegatingConnection hashCode gets it from the
>> innermostDelegate. System.idendityHashCode should pick this up. Could be
>> overrriden somewhere, but I don't think so.
>>
>
> System.identityHashCode() uses Object.hashCode().
>
> Had I used conn.hashCode() it would have been OK, but I thought I
> wanted to distinguish different "equal" objects. That was possibly
> wrong.
Yeah, sorry, temporary brain deadness. The Delegating connection
returned is new each time and you need to use the overridden
hashCode to see if the underlying connection is the same.
>
> However, after fixing it to use the innermost delegate I ran a local
> test with hold=wait and I could see the same hash being re-used.
That is good. Consistent with subsequent Continuum runs.
Phi
>
>> Phil
>>
>>
>> > this is now looking like it could be a pool bug - allowing more than
>> > > maxActive distinct connections to be simultaneously active. Need to
>> > > look at this some more. It is worth temporarily modifying the pom
>> > > to use pool 1.4 for a test.
>> >
>> > OK; I think we should see if there are duplicate hashes first.
>> >
>> > >
>> > > Phil
>> > >
>> > > ---------------------------------------------------------------------
>> > > To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
>> > > For additional commands, e-mail: dev-help@commons.apache.org
>> > >
>> > >
>> >
>> > ---------------------------------------------------------------------
>> > To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
>> > For additional commands, e-mail: dev-help@commons.apache.org
>> >
>> >
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> For additional commands, e-mail: dev-help@commons.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by sebb <se...@gmail.com>.
On 14/01/2010, Phil Steitz <ph...@gmail.com> wrote:
> On 1/14/10, sebb <se...@gmail.com> wrote:
> >
> > On 14/01/2010, Phil Steitz <ph...@gmail.com> wrote:
> > > Unless I am reading the output of the latest failures wrong or we
> > > are picking up the wrong hashcode (should be innermost delegate),
> >
> > It's currently the connection returned by getConnection().
> > I'll fix that.
>
>
>
> Should actually be correct as is. As you recall from equals() discussion,.
> DelegatingConnection hashCode gets it from the
> innermostDelegate. System.idendityHashCode should pick this up. Could be
> overrriden somewhere, but I don't think so.
>
System.identityHashCode() uses Object.hashCode().
Had I used conn.hashCode() it would have been OK, but I thought I
wanted to distinguish different "equal" objects. That was possibly
wrong.
However, after fixing it to use the innermost delegate I ran a local
test with hold=wait and I could see the same hash being re-used.
> Phil
>
>
> > this is now looking like it could be a pool bug - allowing more than
> > > maxActive distinct connections to be simultaneously active. Need to
> > > look at this some more. It is worth temporarily modifying the pom
> > > to use pool 1.4 for a test.
> >
> > OK; I think we should see if there are duplicate hashes first.
> >
> > >
> > > Phil
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> > > For additional commands, e-mail: dev-help@commons.apache.org
> > >
> > >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> > For additional commands, e-mail: dev-help@commons.apache.org
> >
> >
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by Phil Steitz <ph...@gmail.com>.
On 1/14/10, sebb <se...@gmail.com> wrote:
>
> On 14/01/2010, Phil Steitz <ph...@gmail.com> wrote:
> > Unless I am reading the output of the latest failures wrong or we
> > are picking up the wrong hashcode (should be innermost delegate),
>
> It's currently the connection returned by getConnection().
> I'll fix that.
Should actually be correct as is. As you recall from equals() discussion,.
DelegatingConnection hashCode gets it from the
innermostDelegate. System.idendityHashCode should pick this up. Could be
overrriden somewhere, but I don't think so.
Phil
> this is now looking like it could be a pool bug - allowing more than
> > maxActive distinct connections to be simultaneously active. Need to
> > look at this some more. It is worth temporarily modifying the pom
> > to use pool 1.4 for a test.
>
> OK; I think we should see if there are duplicate hashes first.
>
> >
> > Phil
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> > For additional commands, e-mail: dev-help@commons.apache.org
> >
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> For additional commands, e-mail: dev-help@commons.apache.org
>
>
Re: [DBCP] Continuum failure - discussion of timings
Posted by sebb <se...@gmail.com>.
On 14/01/2010, Phil Steitz <ph...@gmail.com> wrote:
> Unless I am reading the output of the latest failures wrong or we
> are picking up the wrong hashcode (should be innermost delegate),
It's currently the connection returned by getConnection().
I'll fix that.
> this is now looking like it could be a pool bug - allowing more than
> maxActive distinct connections to be simultaneously active. Need to
> look at this some more. It is worth temporarily modifying the pom
> to use pool 1.4 for a test.
OK; I think we should see if there are duplicate hashes first.
>
> Phil
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
> For additional commands, e-mail: dev-help@commons.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by Phil Steitz <ph...@gmail.com>.
Unless I am reading the output of the latest failures wrong or we
are picking up the wrong hashcode (should be innermost delegate),
this is now looking like it could be a pool bug - allowing more than
maxActive distinct connections to be simultaneously active. Need to
look at this some more. It is worth temporarily modifying the pom
to use pool 1.4 for a test.
Phil
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by sebb <se...@gmail.com>.
On 13/01/2010, sebb <se...@gmail.com> wrote:
> On 13/01/2010, sebb <se...@gmail.com> wrote:
> > On 13/01/2010, sebb <se...@gmail.com> wrote:
> > > Here is the output from
> > > http://vmbuild.apache.org/continuum/buildResult.action?buildId=268733&projectId=22
> > >
> > > I've rearranged it so the threads are in ConnectionStart order.
> > > I moved ConnectionStart to the beginning, added the Thread number at
> > > the end (dropping irrelevant stuff), and deleted the prefix
> > > "ConnectStart: 355958"
> > >
> > > 7635. StartupDelay: 13. ConnectTime: 2. Runtime: 218. 1
> > > 7637. StartupDelay: 0. ConnectTime: 280. Runtime: 481. 2
> > > 7724. StartupDelay: 0. ConnectTime: 193. Runtime: 394. 4
> > > 7737. StartupDelay: 13. ConnectTime: 180. Runtime: 381. 5
> > > 7750. StartupDelay: 112. ConnectTime: 167. Runtime: 368. 3
> > > 7775. StartupDelay: 38. ConnectTime: 142. Runtime: 343. 6
> > > 7785. StartupDelay: 10. ConnectTime: 132. Runtime: 333. 7
> > > 7816. StartupDelay: 31. ConnectTime: 101. Runtime: 302. 8
> > > 7853. StartupDelay: 38. ConnectTime: 1. Runtime: 202. 9
> > > 7865. StartupDelay: 11. ConnectTime: 52. Runtime: 252. 10
> > > 7874. StartupDelay: 9. ConnectTime: 43. Runtime: 243. 11
> > > 7918. StartupDelay: 44. ConnectTime: -. Runtime: 109. 12
> > > 7927. StartupDelay: 9. ConnectTime: -. Runtime: 113. 13
> > > 7941. StartupDelay: 14. ConnectTime: -. Runtime: 104. 14
> > > 7944. StartupDelay: 3. ConnectTime: -. Runtime: 101. 15
> > > 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 17
> > > 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 18
> > > 7953. StartupDelay: 0. ConnectTime: -. Runtime: 101. 19
> > > 7954. StartupDelay: 1. ConnectTime: -. Runtime: 100. 20
> > > 7954. StartupDelay: 10. ConnectTime: -. Runtime: 100. 16
> > >
> > > It can be seen that thread 2 reaches the getConnection() method some
> > > while before the next thread (7724-7637=87ms) yet takes longer than
> > > any of the other threads to return from the method.
> > >
> > > This could mean that there is a window somewhere in the code that
> > > causes this thread to pause whilst others progress. There does seem to
> > > be a problem here.
> > >
> > > I need to do a bit more analysis on the numbers (and perhaps update
> > > the debug) to see how the connected threads overlap.
> > >
> >
> >
> > A bit more analysis (see below) shows that the first thread completes
> > (releases its connnection) before some of the other threads call
> > getConnection(). All the other threads release their connections after
> > the last thread invokes getConnection(), so only the first waiting
> > thread gets a connection.
> >
> > One way to fix this might be to change the holdTime to 3*waitTime
> > instead of twice. Or more.
> >
> > However there is still a puzzle - why does the second thread take so
> > long to get the connection? And why do the threads that take longer
> > than waitTime to get a connection not fail with a timeout?
> >
> > PreConnect
> > ! EndRun = PreConnect+RunTime
> > ! ! StartDelay (elapsed)
> > ! ! ! getConn() (elapsed)
> > ! ! ! ! RunTime (elapsed)
> > ! ! ! ! ! IDX
> > 7635 7853 13 2 218 1
> > 7637 8118 0 280 481 2
> > 7724 8118 0 193 394 4
> > 7737 8118 13 180 381 5
> > 7750 8118 112 167 368 3
> > 7775 8118 38 142 343 6
> > 7785 8118 10 132 333 7
> > 7816 8118 31 101 302 8
> > 7853 8055 38 1 202 9
> > 7865 8117 11 52 252 10
> > 7874 8117 9 43 243 11
> > 7918 8027 44 - 109 12
> > 7927 8040 9 - 113 13
> > 7941 8045 14 - 104 14
> > 7944 8045 3 - 101 15
> > 7953 8053 0 - 100 17
> > 7953 8053 0 - 100 18
> > 7953 8054 0 - 101 19
> > 7954 8054 1 - 100 20
> > 7954 8054 10 - 100 16
> >
> > The PreConnect and Endtime values are in ms from an arbitrary point in time
> > The elapsed times are in ms.
>
>
> Rats! The problem is clearly not solved, see failures from
>
> http://vmbuild.apache.org/continuum/buildResult.action?buildId=269039&projectId=22
>
> In both cases, the earliest connection release (Post) is after the
> latest getConnection (Pre), by a margin of about 80ms.
>
> These look like a different failure mode from the previous run, where
> one connection was released too early.
>
> Unless there is some additional processing that goes on after the
> connection has been made available but before the conn.close() can
> return? In which case, maybe there would be time for the connection to
> be snapped up.
>
> I propose increasing the hold time to 3* wait and see what happens.
I did this, and it has helped - usually now only one of the
testMultiThreaded2() tests fails.
However, it's not necessarily the one with holdTime = 3 * waitTime.
It's looking less and less likely that the problem is due to one
thread releasing the connection early enough to allow another thread
to grab it.
> Pre: 8. Post: 213. Startup: 8. getConn(): 1. Runtime: 205. IDX: 0.
> Pre: 39. Post: 352. Startup: 29. getConn(): 108. Runtime: 313. IDX: 1.
> Pre: 24. Post: 351. Startup: 1. getConn(): 123. Runtime: 327. IDX: 2.
> Pre: 24. Post: 352. Startup: 1. getConn(): 124. Runtime: 328. IDX: 3.
> Pre: 24. Post: 352. Startup: 0. getConn(): 124. Runtime: 328. IDX: 4.
> Pre: 24. Post: 352. Startup: 0. getConn(): 124. Runtime: 328. IDX: 5.
> Pre: 43. Post: 351. Startup: 3. getConn(): 104. Runtime: 308. IDX: 6.
> Pre: 86. Post: 351. Startup: 1. getConn(): 61. Runtime: 265. IDX: 7.
> Pre: 114. Post: 351. Startup: 28. getConn(): 33. Runtime: 237. IDX: 8.
> Pre: 116. Post: 351. Startup: 2. getConn(): 31. Runtime: 235. IDX: 9.
> Pre: 116. Post: 417. Startup: 0. getConn(): 99. Runtime: 301. IDX: 10.
> Pre: 148. Post: -. Startup: 32. getConn(): -. Runtime: 100. IDX: 11.
> Pre: 148. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 12.
> Pre: 149. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 13.
> Pre: 149. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 14.
> Pre: 150. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 15.
> Pre: 150. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 16.
> Pre: 150. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 17.
> Pre: 152. Post: -. Startup: 2. getConn(): -. Runtime: 100. IDX: 18.
> Pre: 152. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 19.
>
> Pre: 0. Post: 201. Startup: 0. getConn(): 1. Runtime: 201. IDX: 0.
> Pre: 1. Post: 319. Startup: 0. getConn(): 117. Runtime: 318. IDX: 1.
> Pre: 43. Post: 320. Startup: 42. getConn(): 76. Runtime: 277. IDX: 2.
> Pre: 43. Post: 319. Startup: 0. getConn(): 76. Runtime: 276. IDX: 3.
> Pre: 68. Post: 320. Startup: 25. getConn(): 51. Runtime: 252. IDX: 4.
> Pre: 68. Post: 320. Startup: 0. getConn(): 51. Runtime: 252. IDX: 5.
> Pre: 93. Post: 319. Startup: 25. getConn(): 26. Runtime: 226. IDX: 6.
> Pre: 94. Post: 319. Startup: 1. getConn(): 25. Runtime: 225. IDX: 7.
> Pre: 118. Post: 319. Startup: 24. getConn(): 1. Runtime: 201. IDX: 8.
> Pre: 120. Post: 320. Startup: 2. getConn(): 0. Runtime: 200. IDX: 9.
> Pre: 120. Post: 402. Startup: 0. getConn(): 81. Runtime: 282. IDX: 10.
> Pre: 120. Post: -. Startup: 0. getConn(): -. Runtime: 101. IDX: 11.
> Pre: 121. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 12.
> Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 13.
> Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 14.
> Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 15.
> Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 101. IDX: 16.
> Pre: 122. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 17.
> Pre: 122. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 18.
> Pre: 122. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 19.
>
>
> >
> > S///
> >
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by sebb <se...@gmail.com>.
On 13/01/2010, sebb <se...@gmail.com> wrote:
> On 13/01/2010, sebb <se...@gmail.com> wrote:
> > Here is the output from
> > http://vmbuild.apache.org/continuum/buildResult.action?buildId=268733&projectId=22
> >
> > I've rearranged it so the threads are in ConnectionStart order.
> > I moved ConnectionStart to the beginning, added the Thread number at
> > the end (dropping irrelevant stuff), and deleted the prefix
> > "ConnectStart: 355958"
> >
> > 7635. StartupDelay: 13. ConnectTime: 2. Runtime: 218. 1
> > 7637. StartupDelay: 0. ConnectTime: 280. Runtime: 481. 2
> > 7724. StartupDelay: 0. ConnectTime: 193. Runtime: 394. 4
> > 7737. StartupDelay: 13. ConnectTime: 180. Runtime: 381. 5
> > 7750. StartupDelay: 112. ConnectTime: 167. Runtime: 368. 3
> > 7775. StartupDelay: 38. ConnectTime: 142. Runtime: 343. 6
> > 7785. StartupDelay: 10. ConnectTime: 132. Runtime: 333. 7
> > 7816. StartupDelay: 31. ConnectTime: 101. Runtime: 302. 8
> > 7853. StartupDelay: 38. ConnectTime: 1. Runtime: 202. 9
> > 7865. StartupDelay: 11. ConnectTime: 52. Runtime: 252. 10
> > 7874. StartupDelay: 9. ConnectTime: 43. Runtime: 243. 11
> > 7918. StartupDelay: 44. ConnectTime: -. Runtime: 109. 12
> > 7927. StartupDelay: 9. ConnectTime: -. Runtime: 113. 13
> > 7941. StartupDelay: 14. ConnectTime: -. Runtime: 104. 14
> > 7944. StartupDelay: 3. ConnectTime: -. Runtime: 101. 15
> > 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 17
> > 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 18
> > 7953. StartupDelay: 0. ConnectTime: -. Runtime: 101. 19
> > 7954. StartupDelay: 1. ConnectTime: -. Runtime: 100. 20
> > 7954. StartupDelay: 10. ConnectTime: -. Runtime: 100. 16
> >
> > It can be seen that thread 2 reaches the getConnection() method some
> > while before the next thread (7724-7637=87ms) yet takes longer than
> > any of the other threads to return from the method.
> >
> > This could mean that there is a window somewhere in the code that
> > causes this thread to pause whilst others progress. There does seem to
> > be a problem here.
> >
> > I need to do a bit more analysis on the numbers (and perhaps update
> > the debug) to see how the connected threads overlap.
> >
>
>
> A bit more analysis (see below) shows that the first thread completes
> (releases its connnection) before some of the other threads call
> getConnection(). All the other threads release their connections after
> the last thread invokes getConnection(), so only the first waiting
> thread gets a connection.
>
> One way to fix this might be to change the holdTime to 3*waitTime
> instead of twice. Or more.
>
> However there is still a puzzle - why does the second thread take so
> long to get the connection? And why do the threads that take longer
> than waitTime to get a connection not fail with a timeout?
>
> PreConnect
> ! EndRun = PreConnect+RunTime
> ! ! StartDelay (elapsed)
> ! ! ! getConn() (elapsed)
> ! ! ! ! RunTime (elapsed)
> ! ! ! ! ! IDX
> 7635 7853 13 2 218 1
> 7637 8118 0 280 481 2
> 7724 8118 0 193 394 4
> 7737 8118 13 180 381 5
> 7750 8118 112 167 368 3
> 7775 8118 38 142 343 6
> 7785 8118 10 132 333 7
> 7816 8118 31 101 302 8
> 7853 8055 38 1 202 9
> 7865 8117 11 52 252 10
> 7874 8117 9 43 243 11
> 7918 8027 44 - 109 12
> 7927 8040 9 - 113 13
> 7941 8045 14 - 104 14
> 7944 8045 3 - 101 15
> 7953 8053 0 - 100 17
> 7953 8053 0 - 100 18
> 7953 8054 0 - 101 19
> 7954 8054 1 - 100 20
> 7954 8054 10 - 100 16
>
> The PreConnect and Endtime values are in ms from an arbitrary point in time
> The elapsed times are in ms.
Rats! The problem is clearly not solved, see failures from
http://vmbuild.apache.org/continuum/buildResult.action?buildId=269039&projectId=22
In both cases, the earliest connection release (Post) is after the
latest getConnection (Pre), by a margin of about 80ms.
These look like a different failure mode from the previous run, where
one connection was released too early.
Unless there is some additional processing that goes on after the
connection has been made available but before the conn.close() can
return? In which case, maybe there would be time for the connection to
be snapped up.
I propose increasing the hold time to 3* wait and see what happens.
Pre: 8. Post: 213. Startup: 8. getConn(): 1. Runtime: 205. IDX: 0.
Pre: 39. Post: 352. Startup: 29. getConn(): 108. Runtime: 313. IDX: 1.
Pre: 24. Post: 351. Startup: 1. getConn(): 123. Runtime: 327. IDX: 2.
Pre: 24. Post: 352. Startup: 1. getConn(): 124. Runtime: 328. IDX: 3.
Pre: 24. Post: 352. Startup: 0. getConn(): 124. Runtime: 328. IDX: 4.
Pre: 24. Post: 352. Startup: 0. getConn(): 124. Runtime: 328. IDX: 5.
Pre: 43. Post: 351. Startup: 3. getConn(): 104. Runtime: 308. IDX: 6.
Pre: 86. Post: 351. Startup: 1. getConn(): 61. Runtime: 265. IDX: 7.
Pre: 114. Post: 351. Startup: 28. getConn(): 33. Runtime: 237. IDX: 8.
Pre: 116. Post: 351. Startup: 2. getConn(): 31. Runtime: 235. IDX: 9.
Pre: 116. Post: 417. Startup: 0. getConn(): 99. Runtime: 301. IDX: 10.
Pre: 148. Post: -. Startup: 32. getConn(): -. Runtime: 100. IDX: 11.
Pre: 148. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 12.
Pre: 149. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 13.
Pre: 149. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 14.
Pre: 150. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 15.
Pre: 150. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 16.
Pre: 150. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 17.
Pre: 152. Post: -. Startup: 2. getConn(): -. Runtime: 100. IDX: 18.
Pre: 152. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 19.
Pre: 0. Post: 201. Startup: 0. getConn(): 1. Runtime: 201. IDX: 0.
Pre: 1. Post: 319. Startup: 0. getConn(): 117. Runtime: 318. IDX: 1.
Pre: 43. Post: 320. Startup: 42. getConn(): 76. Runtime: 277. IDX: 2.
Pre: 43. Post: 319. Startup: 0. getConn(): 76. Runtime: 276. IDX: 3.
Pre: 68. Post: 320. Startup: 25. getConn(): 51. Runtime: 252. IDX: 4.
Pre: 68. Post: 320. Startup: 0. getConn(): 51. Runtime: 252. IDX: 5.
Pre: 93. Post: 319. Startup: 25. getConn(): 26. Runtime: 226. IDX: 6.
Pre: 94. Post: 319. Startup: 1. getConn(): 25. Runtime: 225. IDX: 7.
Pre: 118. Post: 319. Startup: 24. getConn(): 1. Runtime: 201. IDX: 8.
Pre: 120. Post: 320. Startup: 2. getConn(): 0. Runtime: 200. IDX: 9.
Pre: 120. Post: 402. Startup: 0. getConn(): 81. Runtime: 282. IDX: 10.
Pre: 120. Post: -. Startup: 0. getConn(): -. Runtime: 101. IDX: 11.
Pre: 121. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 12.
Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 13.
Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 14.
Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 15.
Pre: 121. Post: -. Startup: 0. getConn(): -. Runtime: 101. IDX: 16.
Pre: 122. Post: -. Startup: 1. getConn(): -. Runtime: 100. IDX: 17.
Pre: 122. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 18.
Pre: 122. Post: -. Startup: 0. getConn(): -. Runtime: 100. IDX: 19.
>
> S///
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org
Re: [DBCP] Continuum failure - discussion of timings
Posted by sebb <se...@gmail.com>.
On 13/01/2010, sebb <se...@gmail.com> wrote:
> Here is the output from
> http://vmbuild.apache.org/continuum/buildResult.action?buildId=268733&projectId=22
>
> I've rearranged it so the threads are in ConnectionStart order.
> I moved ConnectionStart to the beginning, added the Thread number at
> the end (dropping irrelevant stuff), and deleted the prefix
> "ConnectStart: 355958"
>
> 7635. StartupDelay: 13. ConnectTime: 2. Runtime: 218. 1
> 7637. StartupDelay: 0. ConnectTime: 280. Runtime: 481. 2
> 7724. StartupDelay: 0. ConnectTime: 193. Runtime: 394. 4
> 7737. StartupDelay: 13. ConnectTime: 180. Runtime: 381. 5
> 7750. StartupDelay: 112. ConnectTime: 167. Runtime: 368. 3
> 7775. StartupDelay: 38. ConnectTime: 142. Runtime: 343. 6
> 7785. StartupDelay: 10. ConnectTime: 132. Runtime: 333. 7
> 7816. StartupDelay: 31. ConnectTime: 101. Runtime: 302. 8
> 7853. StartupDelay: 38. ConnectTime: 1. Runtime: 202. 9
> 7865. StartupDelay: 11. ConnectTime: 52. Runtime: 252. 10
> 7874. StartupDelay: 9. ConnectTime: 43. Runtime: 243. 11
> 7918. StartupDelay: 44. ConnectTime: -. Runtime: 109. 12
> 7927. StartupDelay: 9. ConnectTime: -. Runtime: 113. 13
> 7941. StartupDelay: 14. ConnectTime: -. Runtime: 104. 14
> 7944. StartupDelay: 3. ConnectTime: -. Runtime: 101. 15
> 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 17
> 7953. StartupDelay: 0. ConnectTime: -. Runtime: 100. 18
> 7953. StartupDelay: 0. ConnectTime: -. Runtime: 101. 19
> 7954. StartupDelay: 1. ConnectTime: -. Runtime: 100. 20
> 7954. StartupDelay: 10. ConnectTime: -. Runtime: 100. 16
>
> It can be seen that thread 2 reaches the getConnection() method some
> while before the next thread (7724-7637=87ms) yet takes longer than
> any of the other threads to return from the method.
>
> This could mean that there is a window somewhere in the code that
> causes this thread to pause whilst others progress. There does seem to
> be a problem here.
>
> I need to do a bit more analysis on the numbers (and perhaps update
> the debug) to see how the connected threads overlap.
>
A bit more analysis (see below) shows that the first thread completes
(releases its connnection) before some of the other threads call
getConnection(). All the other threads release their connections after
the last thread invokes getConnection(), so only the first waiting
thread gets a connection.
One way to fix this might be to change the holdTime to 3*waitTime
instead of twice. Or more.
However there is still a puzzle - why does the second thread take so
long to get the connection? And why do the threads that take longer
than waitTime to get a connection not fail with a timeout?
PreConnect
! EndRun = PreConnect+RunTime
! ! StartDelay (elapsed)
! ! ! getConn() (elapsed)
! ! ! ! RunTime (elapsed)
! ! ! ! ! IDX
7635 7853 13 2 218 1
7637 8118 0 280 481 2
7724 8118 0 193 394 4
7737 8118 13 180 381 5
7750 8118 112 167 368 3
7775 8118 38 142 343 6
7785 8118 10 132 333 7
7816 8118 31 101 302 8
7853 8055 38 1 202 9
7865 8117 11 52 252 10
7874 8117 9 43 243 11
7918 8027 44 - 109 12
7927 8040 9 - 113 13
7941 8045 14 - 104 14
7944 8045 3 - 101 15
7953 8053 0 - 100 17
7953 8053 0 - 100 18
7953 8054 0 - 101 19
7954 8054 1 - 100 20
7954 8054 10 - 100 16
The PreConnect and Endtime values are in ms from an arbitrary point in time
The elapsed times are in ms.
S///
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@commons.apache.org
For additional commands, e-mail: dev-help@commons.apache.org