History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: QB-2063
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Blocker Blocker
Assignee: Unassigned
Reporter: AlSt
Votes: 1
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
QuickBuild

ChangesResource (RESTful API) seems to block h2 Engine.

Created: 27/May/14 10:07 AM   Updated: 12/Jun/14 04:16 PM
Component/s: None
Affects Version/s: 5.1.22
Fix Version/s: 5.1.29

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: Unknown
File Attachments: None
Image Attachments:

1. cpu_sampling.PNG
(65 kb)

2. Threads.PNG
(94 kb)


 Description  « Hide
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.

 All   Comments   Work Log   Change History      Sort Order:
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

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.

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.

AlSt [27/May/14 11:53 AM]
Also: Wouldn't it be better to use a real database system and not an embedded system?

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.

Steve Luo [27/May/14 12:10 PM]
Sorry, for 100 tests per build, 10K builds should be 1M data, it also very big.

AlSt [27/May/14 12:14 PM]
Ok thanks for the explanation.

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]

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.

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?

Steve Luo [01/Jun/14 03:37 PM]
Then, what is your frequency of REST calls to one report?

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

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?

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?

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.