| << Back to previous view |
|
[QB-2063] ChangesResource (RESTful API) seems to block h2 Engine.
|
|
| Status: | Resolved |
| Project: | QuickBuild |
| Component/s: | None |
| Affects Version/s: | 5.1.22 |
| Fix Version/s: | 5.1.29 |
| Type: | Bug | Priority: | Blocker |
| Reporter: | AlSt | Assigned To: | Unassigned |
| Resolution: | Fixed | Votes: | 1 |
| Remaining Estimate: | Unknown | Time Spent: | Unknown |
| Original Estimate: | Unknown | ||
| File Attachments: |
cpu_sampling.PNG
Threads.PNG
|
| Description |
|
We encounter some problems with the h2 database connection. As shown in the screenshot there are a lot of threads which are blocked by the h2 Engine within a REST call.
This problem slows down Quickbuild dramatically. It seems that somewhere the Database connection is held open and because of this it is not possible to open a new session. Maybe it is another cause, but I think that somewhere there is a resource leak. |
| Comments |
| Comment by AlSt [ 27/May/14 11:22 AM ] |
|
We are getting exception like:
2014-05-27 13:02:09,869 [qtp272376094-17846492] ERROR com.pmease.quickbuild.rest.providers.GenericExceptionMapper - Error serving restful request. com.pmease.quickbuild.plugin.report.engine.exception.DatabaseException: Open database [/media/data/quickbuild/storage/configurations/365/reports/scm_activity/DEFAULT] failed. Database status [No active connections]. at com.pmease.quickbuild.plugin.report.engine.datastore.DbStore.open(DbStore.java:356) at com.pmease.quickbuild.plugin.report.changes.ChangesHelper.getChangesets(ChangesHelper.java:411) at com.pmease.quickbuild.plugin.report.changes.rest.ChangesResource.getCommits(ChangesResource.java:306) at sun.reflect.GeneratedMethodAccessor96.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:149) at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:67) at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:259) at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:133) at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:83) at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:133) at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:71) at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:990) at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:941) at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:932) at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:384) at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:451) at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:632) at com.pmease.quickbuild.rest.RestServlet.service(RestServlet.java:48) at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1336) at com.pmease.quickbuild.Quickbuild$DisableTraceFilter.doFilter(Quickbuild.java:1033) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1072) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) at org.eclipse.jetty.server.Server.handle(Server.java:365) at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485) at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:926) at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:988) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:635) at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235) at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) at java.lang.Thread.run(Thread.java:744) Caused by: com.pmease.quickbuild.plugin.report.engine.exception.DatabaseException: Unable to get connection from database url: jdbc:h2:/media/data/quickbuild/storage/configurations/365/reports/scm_activity/DEFAULT/scm_activity;ACCESS_MODE_DATA=r at com.pmease.quickbuild.plugin.report.engine.datastore.ConnectionManager.getConnection(ConnectionManager.java:25) at com.pmease.quickbuild.plugin.report.engine.datastore.DbStore.getConnection(DbStore.java:391) at com.pmease.quickbuild.plugin.report.engine.datastore.DbStore.open(DbStore.java:323) ... 45 more Caused by: org.h2.jdbc.JdbcSQLException: Database may be already in use: "Waited for database closing longer than 1 minute". Possible solutions: close all other connection(s); use the server mode [90020-175] at org.h2.message.DbException.getJdbcSQLException(DbException.java:332) at org.h2.message.DbException.get(DbException.java:172) at org.h2.message.DbException.get(DbException.java:149) at org.h2.engine.Engine.openSession(Engine.java:168) at org.h2.engine.Engine.createSessionAndValidate(Engine.java:139) at org.h2.engine.Engine.createSession(Engine.java:122) at org.h2.engine.Engine.createSession(Engine.java:28) at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:323) at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:105) at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:90) at org.h2.Driver.connect(Driver.java:73) at java.sql.DriverManager.getConnection(DriverManager.java:571) at java.sql.DriverManager.getConnection(DriverManager.java:215) at com.pmease.quickbuild.plugin.report.engine.datastore.ConnectionManager.getConnection(ConnectionManager.java:23) ... 47 more |
| Comment by Steve Luo [ 27/May/14 11:38 AM ] |
|
Thank you for the updating.
For this issue, I have posted to h2 forum and the reply was that if open/close the database too fast (for h2 embedded mode), it will cause such error, and even worse, the resoltion for this error seems to have to restart your QuickBuild server. I'm not very understanding what is your screen shot mean. But from your error log: Database status [No active connections], I think all connections for database should have been closed. Also, it seems that this error was often seen when using REST api to query reports (including changes) too frequently. |
| Comment by AlSt [ 27/May/14 11:52 AM ] |
|
The screenshots are just a result of my investigation. On Thread.PNG you can see that there are some threads which are blocked because another thread is waiting for a h2 connection, and this thread is trying to server the rest request.
On the other screenshot you can see that this waiting also uses a lot of cpu. |
| Comment by AlSt [ 27/May/14 11:53 AM ] |
| Also: Wouldn't it be better to use a real database system and not an embedded system? |
| Comment by Steve Luo [ 27/May/14 12:09 PM ] |
|
Is it possible that every 1 second or less, a request is made to get changes from REST? and when one is waiting for connection, all others are blocked?
For configurations and builds as well as users etc., we do use a real database system. But for reports, we are not, the reason is there will be too many data need be stored (just think that we have 100 tests per build, 10K builds will get 100M data), one database cannot handle this situation. |
| Comment by Steve Luo [ 27/May/14 12:10 PM ] |
| Sorry, for 100 tests per build, 10K builds should be 1M data, it also very big. |
| Comment by AlSt [ 27/May/14 12:14 PM ] |
| Ok thanks for the explanation. |
| Comment by Maikel vd Hurk [ 01/Jun/14 02:23 PM ] |
|
We are facing kind of similar issue when people are requesting by RestAPI many data like SCM and JUnit reports, then the normal storage of the master server gets blocked in some occasions resulting in following stack :
com.pmease.quickbuild.plugin.report.engine.exception.DatabaseException: Open database [/opt/quickbuild/storage/builds/2068548/reports/junit/Release Linux-X86 Reflection ] failed. Database status [No active connections]. at com.pmease.quickbuild.plugin.report.engine.datastore.DbStore.open(DbStore.java:356) at com.pmease.quickbuild.plugin.report.engine.metadata.ReportCategory.getRowsCount(ReportCategory.java:317) at com.pmease.quickbuild.plugin.report.engine.metadata.ReportCategory.getRowsCount(ReportCategory.java:326) at com.pmease.quickbuild.plugin.report.engine.renderer.unprocessed.UnProcessedRenderer.isApplicable(UnProcessedRenderer.java:51) at com.pmease.quickbuild.plugin.report.engine.contribution.web.CategoryBuildTab.getTabs(CategoryBuildTab.java:77) at com.pmease.quickbuild.web.page.build.BuildPage.onInitialize(BuildPage.java:745) at org.apache.wicket.Component.fireInitialize(Component.java:924) at org.apache.wicket.MarkupContainer.internalInitialize(MarkupContainer.java:1002) at org.apache.wicket.Page.internalPrepareForRender(Page.java:278) at org.apache.wicket.Component.render(Component.java:2280) at org.apache.wicket.Page.renderPage(Page.java:1035) at org.apache.wicket.request.handler.render.WebPageRenderer.renderPage(WebPageRenderer.java:105) at org.apache.wicket.request.handler.render.WebPageRenderer.respond(WebPageRenderer.java:182) at org.apache.wicket.request.handler.RenderPageRequestHandler.respond(RenderPageRequestHandler.java:147) at org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:719) at org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:63) at org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:210) at org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:253) at org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:162) com.pmease.quickbuild.plugin.report.engine.exception.DatabaseException: Unable to get connection from database url: jdbc:h2:/opt/quickbuild/storage/builds/2068548/reports/junit/Release Linux-X86 Reflection /junit;ACCESS_MODE_DATA=r at com.pmease.quickbuild.plugin.report.engine.datastore.ConnectionManager.getConnection(ConnectionManager.java:25) at com.pmease.quickbuild.plugin.report.engine.datastore.DbStore.getConnection(DbStore.java:391) at com.pmease.quickbuild.plugin.report.engine.datastore.DbStore.open(DbStore.java:323) at com.pmease.quickbuild.plugin.report.engine.metadata.ReportCategory.getRowsCount(ReportCategory.java:317) at com.pmease.quickbuild.plugin.report.engine.metadata.ReportCategory.getRowsCount(ReportCategory.java:326) at com.pmease.quickbuild.plugin.report.engine.renderer.unprocessed.UnProcessedRenderer.isApplicable(UnProcessedRenderer.java:51) at com.pmease.quickbuild.plugin.report.engine.contribution.web.CategoryBuildTab.getTabs(CategoryBuildTab.java:77) at com.pmease.quickbuild.web.page.build.BuildPage.onInitialize(BuildPage.java:745) at org.apache.wicket.Component.fireInitialize(Component.java:924) at org.apache.wicket.MarkupContainer.internalInitialize(MarkupContainer.java:1002) at org.apache.wicket.Page.internalPrepareForRender(Page.java:278) at org.apache.wicket.Component.render(Component.java:2280) at org.apache.wicket.Page.renderPage(Page.java:1035) at org.apache.wicket.request.handler.render.WebPageRenderer.renderPage(WebPageRenderer.java:105) at org.apache.wicket.request.handler.render.WebPageRenderer.respond(WebPageRenderer.java:182) at org.apache.wicket.request.handler.RenderPageRequestHandler.respond(RenderPageRequestHandler.java:147) at org.apache.wicket.request.cycle.RequestCycle$HandlerExecutor.respond(RequestCycle.java:719) at org.apache.wicket.request.RequestHandlerStack.execute(RequestHandlerStack.java:63) at org.apache.wicket.request.cycle.RequestCycle.processRequest(RequestCycle.java:210) at org.apache.wicket.request.cycle.RequestCycle.processRequestAndDetach(RequestCycle.java:253) at org.apache.wicket.protocol.http.WicketFilter.processRequest(WicketFilter.java:162) Additionally we see: Open database [/opt/quickbuild/storage/builds/2148109/reports/jira/DEFAULT] failed. Database status [No active connections]. caused by: Unable to get connection from database url: jdbc:h2:/opt/quickbuild/storage/builds/2148109/reports/jira/DEFAULT/jira caused by: Error opening database: "Sleep interrupted" [8000-175] caused by: sleep interrupted or Open database [/opt/quickbuild/storage/builds/2134358/reports/junit/Release Linux-X86 Reflection SkipForNDS] failed. Database status [No active connections]. caused by: Unable to get connection from database url: jdbc:h2:/opt/quickbuild/storage/builds/2134358/reports/junit/Release Linux-X86 Reflection SkipForNDS/junit;ACCESS_MODE_DATA=r caused by: The database is read only [90097-175] or Open database [/opt/quickbuild/storage/builds/2068548/reports/junit/Release Linux-X86 Reflection ] failed. Database status [No active connections]. caused by: Unable to get connection from database url: jdbc:h2:/opt/quickbuild/storage/builds/2068548/reports/junit/Release Linux-X86 Reflection /junit;ACCESS_MODE_DATA=r caused by: File corrupted while reading record: "23033 of 2944". Possible solution: use the recovery tool [90030-175] |
| Comment by Steve Luo [ 01/Jun/14 02:42 PM ] |
|
Hi Maikel,
How about restart your QuickBuild server to see whether this can be recovered. Now, there're more evidence to show that too many REST calls can cause h2 jdbc driver fail. I will contact with h2 development team to see if there is any resolution. Currently, I think you can try reduce the REST calls, especially reduce frequency of the calls to one report. |
| Comment by Maikel vd Hurk [ 01/Jun/14 03:30 PM ] |
|
Hi Steve,
We have already reduced the number of RestAPI calls, also we are using nqinx proxy to throttle the number of RestAPI calls to the main server. Shouldn't just the main application just always get priority on RestAPI? |
| Comment by Steve Luo [ 01/Jun/14 03:37 PM ] |
| Then, what is your frequency of REST calls to one report? |
| Comment by Maikel vd Hurk [ 01/Jun/14 04:45 PM ] |
|
Depends on the call done:
1) build status every 5 minutes 2) report data (junit) every day |
| Comment by Steve Luo [ 01/Jun/14 05:14 PM ] |
|
It seems that your frequency is very low. Then I'm a bit confused, in your post, you said:
We are facing kind of similar issue when people are requesting by RestAPI many data like SCM and JUnit reports ... can I say here the requests from REST is also made once per day? |
| Comment by Maikel vd Hurk [ 01/Jun/14 06:23 PM ] |
| That was current situation, before we were requesting everything every 5 minutes for multiple configurations. Exact numbers I have to distract from all log files. Do you need that? |
| Comment by Steve Luo [ 02/Jun/14 01:17 AM ] |
| You needn't distract from the log files. You can go to QuickBuild Grid -> Active Nodes tab, and choose your server node, in node overview tab, there is REST Visits section, there you can find your requests number. |