sebb wrote: > On 11/01/2010, Phil Steitz <phil.ste...@gmail.com> wrote: >> Phil Steitz wrote: >> > Posting the last failed build output while it is, um....still available: > > I assume this is from: > > http://vmbuild.apache.org/continuum/buildResult.action?buildId=267625&projectId=22 > >> > >> > Multithread test time = 489 ms. Threads: 20. Loops: 20. Hold time: >> > 200. Maxwait: 100. Done: 11. Did not run: 0. Failed: 9. expectError: >> > true >> > StartupDelay: 0. ConnectTime: 3. Runtime: 203. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 0. ConnectTime: 132. Runtime: 333. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 42. ConnectTime: 90. Runtime: 290. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 0. ConnectTime: 90. Runtime: 291. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 76. ConnectTime: 14. Runtime: 215. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 13. ConnectTime: 1. Runtime: 202. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 16. ConnectTime: 0. Runtime: 200. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 1. ConnectTime: 0. Runtime: 200. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 11. ConnectTime: 0. Runtime: 200. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 18. ConnectTime: 0. Runtime: 201. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 7. ConnectTime: 17. Runtime: 218. Loops: 1. State: >> > Done. thrown: null. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 101. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 1. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 101. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 1. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > StartupDelay: 0. ConnectTime: -. Runtime: 100. Loops: 1. State: >> > Getting Connection. thrown: >> > org.apache.commons.dbcp.SQLNestedException: Could not retrieve >> > connection info from pool. (using nanoTime) >> > >> > There are three things that look odd here. First is that the second >> > successful thread should have failed with a timeout. That may be >> > explainable by "wakeup delay." The second is that unless >> > startupDelay is not reliable, the allocation looks unfair and pool >> > 1.5 is supposed to implement fairness - i.e., it should be the >> > threads with lower startupDelays that are served first. >> >> >> Scratch that. pooledConnectionAndInfo has a synch block before the >> call to borrowObject to create or acquire the pool. All threads are >> going after the same pool. The first one in has to create the pool. >> > > It's rather odd. > > The successful threads all took 200+ms to complete, during which time > there should be no spare connections available. > > Yet the second thread only appears to have waited 132ms to get the connection. > [Which should have caused a timeout error, but perhaps that's excusable.] > However, it should not be possible to aquire the 11th connection in > less than 200ms. > What happened to that thread? > Did it somehow stall before waiting for the connection? > If so, why is the overall runtime for the thread only 333ms? > > I will add some more info to the debug output.
Still no failures. This weekend, NTP was re-enabled on vmbuild. It had been disabled for some time. As I said above, loaded guests running under Vmware are known to lose clock accuracy. See [1], [2]. [1] http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1006072 [2] http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1006072 Phil > >> Phil >> >> >> >> This could >> > point to a pool bug. Finally, the connectTimes for some of the >> > successful threads are way too long. >> > >> > Phil >> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: dev-unsubscr...@commons.apache.org >> For additional commands, e-mail: dev-h...@commons.apache.org >> >> > > --------------------------------------------------------------------- > To unsubscribe, e-mail: dev-unsubscr...@commons.apache.org > For additional commands, e-mail: dev-h...@commons.apache.org > --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@commons.apache.org For additional commands, e-mail: dev-h...@commons.apache.org
