4.12 high CPU usage in hibernate thread (java.util.regex.Pattern$Start.match)

[pathduck]

Hi,

since 4.12 installation I've noticed a steady increase in CPU usage for RHQ. At appears threads started by Hibernate doing some regex matching is locked and will not finish.

This is the stack trace of the threads:

"HttpManagementService-threads - 529" prio=10 tid=0x00007faee836e000 nid=0x2e32 runnable [0x00007faed63de000]
   java.lang.Thread.State: RUNNABLE
    at java.util.regex.Pattern$Start.match(Pattern.java:3408)
    at java.util.regex.Matcher.search(Matcher.java:1199)
    at java.util.regex.Matcher.find(Matcher.java:592)
    at java.util.regex.Matcher.replaceAll(Matcher.java:902)
    at java.lang.String.replace(String.java:2180)
    at org.jboss.as.jpa.hibernate4.management.QueryName.displayable(QueryName.java:174)
    at org.jboss.as.jpa.hibernate4.management.QueryName.<init>(QueryName.java:120)
    at org.jboss.as.jpa.hibernate4.management.QueryName.queryName(QueryName.java:110)
    at org.jboss.as.jpa.hibernate4.management.HibernateStatisticsResource.getQueryNames(HibernateStatisticsResource.java:345)
    at org.jboss.as.jpa.hibernate4.management.HibernateStatisticsResource.hasQuery(HibernateStatisticsResource.java:332)
    at org.jboss.as.jpa.hibernate4.management.HibernateStatisticsResource.hasChild(HibernateStatisticsResource.java:81)
    at org.jboss.as.controller.OperationContextImpl.getAuthorizationResource(OperationContextImpl.java:1171)
    at org.jboss.as.controller.OperationContextImpl.getBasicAuthorizationResponse(OperationContextImpl.java:1129)
    at org.jboss.as.controller.OperationContextImpl.authorize(OperationContextImpl.java:1052)
    at org.jboss.as.controller.OperationContextImpl.authorize(OperationContextImpl.java:848)
    at org.jboss.as.controller.operations.global.ReadResourceHandler.doExecuteInternal(ReadResourceHandler.java:265)
    at org.jboss.as.controller.operations.global.ReadResourceHandler.doExecute(ReadResourceHandler.java:142)
    at org.jboss.as.controller.operations.global.GlobalOperationHandlers$AbstractMultiTargetHandler.execute(GlobalOperationHandlers.java:249)
    at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:601)
    at org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:479)
    at org.jboss.as.controller.AbstractOperationContext.completeStepInternal(AbstractOperationContext.java:283)
    at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:278)
    at org.jboss.as.controller.ModelControllerImpl.internalExecute(ModelControllerImpl.java:230)
    at org.jboss.as.controller.ModelControllerImpl.execute(ModelControllerImpl.java:136)
    at org.jboss.as.controller.ModelControllerImpl$3.execute(ModelControllerImpl.java:436)
    at org.jboss.as.controller.ModelControllerImpl$3.execute(ModelControllerImpl.java:426)
    at org.jboss.as.domain.http.server.DomainApiHandler.processRequest(DomainApiHandler.java:263)
    at org.jboss.as.domain.http.server.DomainApiHandler.doHandle(DomainApiHandler.java:167)
    at org.jboss.as.domain.http.server.DomainApiHandler.handle(DomainApiHandler.java:174)
    at org.jboss.as.domain.http.server.security.SubjectAssociationHandler$1.run(SubjectAssociationHandler.java:69)
    at org.jboss.as.domain.http.server.security.SubjectAssociationHandler$1.run(SubjectAssociationHandler.java:65)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:415)
    at org.jboss.as.controller.AccessAuditContext.doAs(AccessAuditContext.java:94)
    at org.jboss.as.domain.http.server.security.SubjectAssociationHandler.handleRequest(SubjectAssociationHandler.java:65)
    at org.jboss.as.domain.http.server.security.SubjectAssociationHandler.handle(SubjectAssociationHandler.java:59)
    at org.jboss.as.domain.http.server.DomainApiCheckHandler.handle(DomainApiCheckHandler.java:45)
    at org.jboss.com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:78)
    at org.jboss.sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:69)
    at org.jboss.com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:81)
    at org.jboss.sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:710)
    at org.jboss.com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:78)
    at org.jboss.as.domain.http.server.RealmReadinessFilter.doFilter(RealmReadinessFilter.java:47)
    at org.jboss.as.domain.http.server.DmrFailureReadinessFilter.doFilter(DmrFailureReadinessFilter.java:45)
    at org.jboss.com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:81)
    at org.jboss.sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:682)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
    at org.jboss.threads.JBossThread.run(JBossThread.java:122)

This is affecting both or Test RHQ installations, running RHEL 6.5 with Java 1.7_45. They are dual CPU VMs and currently two threads are running at 100% causing almost full load.

The CPU is slowly building over time, see this graph of user load:

Any ideas what might cause this?

Stian

[pathduck]

Apparently these are all related cases, looks like a very heavy query introduced, in Hibernate JPA.

Bug 1116345 – [GSS] (6.3.x) HttpManagementService-threads consumes high cpu on org.jboss.as.jpa.hibernate4.management.Qu…

https://access.redhat.com/solutions/1120463

(no solution as yet)

https://issues.jboss.org/browse/JIPI-32

[pathduck]

I have now tried the following:

- Disable all metric collections for JBoss A7 > Deployment > JPA Runtime > Hibernate Persistance Unit.

- Replace the module jars for jboss-as-jpa-7.4.0.Final-redhat-4 with jboss-as-jpa-7.4.0.Final-redhat-19 from EAP 6.3 final.

Neither of these worked for reducing CPU usage. I let the server run through the weekend and today CPU was through the roof and server unresponsive so I had to terminate it. I does not appear to be a memory/heap issue as GC overhead is very low.

This is CPU usage from friday afternoon through saturday morning.

I really wanted to bring 4.12 into production if no big issues were found, but this is such a major bug that unless a quick fix is found then I will have to wait for the next release.

It would be really surprising if this does not affect any other users of 4.12 since it appears to be a general bug in EAP 6.3.Alpha and not related to OS and such factors.

I can't really think of other things to try now, and I think this needs to be looked at by the devs to see what can be done on short term, if anything apart to wait for code fixes.

Edit; submitted BZ:

https://bugzilla.redhat.com/show_bug.cgi?id=1128614

[tsegismont]

Hi Stian,

Thanks for the report. I'll have a look at the problem and will keep the Bugzilla entry updated.

Thomas

[genman]

I back-ported the fix to 4.12 (basically a branch for 4.12 release) using cherry-pick and it seems to have helped a lot. Load average was around 40-80 for a 24 CPU machine, which was insane. If you want, I can email the fixed version to you.

[pathduck]

Hello Elias!

Thanks for the offer - I already received a build of the AS7 plugin for 4.13 snapshot and installed it, it seems to work. Bit sceptical of "backporting" it now.

It was a bit of mess to import it without errors, and probably it would be best to use one built for 4.12. Could you attach one to this post so others could use it as well?

It looks like Thomas' fix worked and CPU is now down to what's expected, i.e. almost nothing, for one of our installations.

However, I installed it on another RHQ and there the CPU is slowly increasing, so not sure what that's about. I will have to dig a bit there.

I will update the BZ with the results.

Stian

[genman]

I uploaded it to Bugzilla.