Performance issue in Validator

johnLavoie · **Joined:** Thu Jun 09, 2016 2:51 pm **Posts:** 3

We have been doing some aggressive profiling and tuning of our application and we have noticed that the highest amount of processing time is spent doing validation. We push a lot of data through, so this isn't a big surprise. But we are surprised when we look at what it appears to be doing during this time.

Depending on the type of workload we are testing, we are seeing 8-50% of execution time spent in this stack trace.

Code:

rank   self  accum   count trace method
   1  8.76%  8.76%     352 302193 java.lang.Class.getInterfaces

Code:

TRACE 302193: (thread=200001)
   java.lang.Class.getInterfaces(Class.java:Unknown line)
   org.hibernate.bytecode.instrumentation.internal.FieldInterceptionHelper$JavassistDelegate.isInstrumented(FieldInterceptionHelper.java:115)
   org.hibernate.bytecode.instrumentation.internal.FieldInterceptionHelper.isInstrumented(FieldInterceptionHelper.java:59)
   org.hibernate.bytecode.instrumentation.internal.FieldInterceptionHelper.isInstrumented(FieldInterceptionHelper.java:67)
   org.hibernate.ejb.util.PersistenceUtilHelper.isLoadedWithoutReference(PersistenceUtilHelper.java:47)
   org.hibernate.ejb.HibernatePersistence$1.isLoadedWithoutReference(HibernatePersistence.java:90)
   javax.persistence.Persistence$1.isLoaded(Persistence.java:93)
   org.hibernate.validator.engine.resolver.JPATraversableResolver.isReachable(JPATraversableResolver.java:61)
   org.hibernate.validator.engine.resolver.DefaultTraversableResolver.isReachable(DefaultTraversableResolver.java:131)
   org.hibernate.validator.engine.resolver.SingleThreadCachedTraversableResolver.isReachable(SingleThreadCachedTraversableResolver.java:46)
   org.hibernate.validator.engine.ValidatorImpl.isValidationRequired(ValidatorImpl.java:1242)
   org.hibernate.validator.engine.ValidatorImpl.validateConstraint(ValidatorImpl.java:448)

Can someone help us understand what might be going on here? Our validation is defined through static xml files that are bundled into our jars, and the java classes are created through Thrift schema definitions and code generation.

This stack trace seems to be on some boundary between Hibernate Validator and other libraries such as ejb and bytecode enablement. But it doesn't look right to us that the app is spending so much time just checking isLoaded and other methods in this stack trace over and over again for the same few classes that we are validating.

Could we be doing something wrong?

johnLavoie · **Joined:** Thu Jun 09, 2016 2:51 pm **Posts:** 3

Some additional information

Code:

[INFO] --- maven-dependency-plugin:2.10:tree (default-cli) @ myapp-batch ---
[INFO] com.mycompany.acc:myapp-batch:jar:3.0.0-SNAPSHOT
[INFO] +- org.slf4j:slf4j-log4j12:jar:1.7.5:provided
[INFO] |  +- org.slf4j:slf4j-api:jar:1.7.5:compile
[INFO] |  \- log4j:log4j:jar:1.2.17:compile
[INFO] +- com.mycompany.acc:sdk-batch:jar:3.0.0-SNAPSHOT:compile
[INFO] |  +- org.apache.curator:curator-recipes:jar:2.4.0:compile
[INFO] |  |  +- org.apache.curator:curator-framework:jar:2.4.0:compile
[INFO] |  |  |  \- org.apache.curator:curator-client:jar:2.4.0:compile
[INFO] |  |  \- org.apache.zookeeper:zookeeper:jar:3.4.5:compile
[INFO] |  |     +- jline:jline:jar:0.9.94:compile
[INFO] |  |     \- org.jboss.netty:netty:jar:3.2.2.Final:compile
[INFO] |  +- org.apache.curator:curator-test:jar:2.4.0:compile
[INFO] |  |  +- org.javassist:javassist:jar:3.15.0-GA:compile
[INFO] |  |  \- org.apache.commons:commons-math:jar:2.2:compile
[INFO] |  +- org.jgrapht:jgrapht-jdk1.5:jar:0.7.3:compile
[INFO] |  +- backtype:cascading-thrift:jar:0.2.3:compile
[INFO] |  +- joda-time:joda-time:jar:2.2:compile
[INFO] |  +- com.mycompany.acc:analytic-config-client:jar:3.0.0-SNAPSHOT:compile
[INFO] |  |  \- com.mycompany.acc:core-platform-api:jar:3.0.0-SNAPSHOT:compile
[INFO] |  +- org.springframework:spring-test:jar:3.2.4.RELEASE:compile
[INFO] |  \- com.mycompany.acc:analytic-jobhistory-client:jar:3.0.0-SNAPSHOT:compile
[INFO] +- org.apache.hadoop:hadoop-core:jar:1.0.3-mapr-3.0.1:provided
[INFO] +- cascading:cascading-core:jar:2.7.1:compile
[INFO] |  +- riffle:riffle:jar:1.0.0:compile
[INFO] |  +- thirdparty:jgrapht-jdk1.6:jar:0.8.1:compile
[INFO] |  \- org.codehaus.janino:janino:jar:2.7.5:compile
[INFO] |     \- org.codehaus.janino:commons-compiler:jar:2.7.5:compile
[INFO] +- cascading:cascading-core:jar:tests:2.7.1:test
[INFO] +- cascading:cascading-hadoop:jar:2.7.1:compile
[INFO] +- cascading:cascading-local:jar:2.7.1:compile
[INFO] +- junit:junit:jar:4.11:test
[INFO] |  \- org.hamcrest:hamcrest-core:jar:1.3:test
[INFO] +- com.mycompany.acc:analytics-model:jar:3.0.0-SNAPSHOT:compile
[INFO] |  \- org.apache.thrift:libthrift:jar:0.9.2:compile
[INFO] +- org.springframework:spring-core:jar:3.2.4.RELEASE:compile
[INFO] |  \- commons-logging:commons-logging:jar:1.1.1:compile
[INFO] +- org.springframework:spring-context:jar:3.2.4.RELEASE:compile
[INFO] |  +- org.springframework:spring-aop:jar:3.2.4.RELEASE:compile
[INFO] |  |  \- aopalliance:aopalliance:jar:1.0:compile
[INFO] |  +- org.springframework:spring-beans:jar:3.2.4.RELEASE:compile
[INFO] |  \- org.springframework:spring-expression:jar:3.2.4.RELEASE:compile
[INFO] +- org.springframework:spring-context-support:jar:3.2.4.RELEASE:compile
[INFO] +- com.mycompany.acc:core-platform-util:jar:3.0.0-SNAPSHOT:compile
[INFO] |  +- org.jasypt:jasypt:jar:1.9.2:compile
[INFO] |  +- org.apache.commons:commons-lang3:jar:3.1:compile
[INFO] |  \- org.hibernate:hibernate-validator:jar:4.2.0.Final:compile
[INFO] |     \- javax.validation:validation-api:jar:1.0.0.GA:compile
[INFO] +- org.beanio:beanio:jar:2.1.0.M1:compile
[INFO] +- com.mycompany.myapp:myapp-wrapper:jar:5.0.0-SNAPSHOT:provided
[INFO] |  \- org.springframework:spring-tx:jar:3.1.1.RELEASE:compile
[INFO] +- com.mycompany.acc:analytic-logging-client:jar:3.0.0-SNAPSHOT:compile
[INFO] |  \- org.apache.cxf:cxf-rt-transports-http:jar:2.6.1:compile
[INFO] |     +- org.apache.cxf:cxf-api:jar:2.6.1:compile
[INFO] |     |  +- org.codehaus.woodstox:woodstox-core-asl:jar:4.1.2:runtime
[INFO] |     |  |  \- org.codehaus.woodstox:stax2-api:jar:3.1.1:runtime
[INFO] |     |  +- org.apache.ws.xmlschema:xmlschema-core:jar:2.0.2:compile
[INFO] |     |  +- org.apache.geronimo.specs:geronimo-javamail_1.4_spec:jar:1.7.1:compile
[INFO] |     |  \- wsdl4j:wsdl4j:jar:1.6.2:compile
[INFO] |     \- org.apache.cxf:cxf-rt-core:jar:2.6.1:compile
[INFO] +- com.mycompany.acc:acc-configuration:jar:3.0.0-SNAPSHOT:compile
[INFO] |  \- com.mycompany.cloudsdk:cloudsdk-crypto:jar:3.8.0-RELEASE:compile
[INFO] |     +- org.bouncycastle:bcprov-jdk16:jar:1.46:compile
[INFO] |     +- commons-codec:commons-codec:jar:1.3:compile
[INFO] |     \- commons-lang:commons-lang:jar:2.6:compile
[INFO] +- com.mycompany.acc:core-platform-model:jar:3.0.0-SNAPSHOT:compile
[INFO] |  +- org.hibernate:hibernate-tools:jar:3.2.4.GA:compile
[INFO] |  |  +- org.beanshell:bsh:jar:2.0b4:compile
[INFO] |  |  +- freemarker:freemarker:jar:2.3.8:compile
[INFO] |  |  \- org.hibernate:jtidy:jar:r8-20060801:compile
[INFO] |  +- com.mycompany.cloudsdk:cloudsdk-persistence:pom:3.8.0-RELEASE:compile
[INFO] |  |  +- cglib:cglib:jar:2.2.2:compile
[INFO] |  |  |  \- asm:asm:jar:3.3.1:compile
[INFO] |  |  +- commons-collections:commons-collections:jar:3.2.1:compile
[INFO] |  |  \- org.springframework:spring-orm:jar:3.2.4.RELEASE:compile
[INFO] |  |     \- org.springframework:spring-jdbc:jar:3.2.4.RELEASE:compile
[INFO] |  \- org.hibernate:hibernate-entitymanager:jar:4.1.6.Final:compile
[INFO] |     +- org.jboss.logging:jboss-logging:jar:3.1.0.GA:compile
[INFO] |     +- org.hibernate:hibernate-core:jar:4.1.6.Final:compile
[INFO] |     |  \- antlr:antlr:jar:2.7.7:compile
[INFO] |     +- org.jboss.spec.javax.transaction:jboss-transaction-api_1.1_spec:jar:1.0.0.Final:compile
[INFO] |     +- dom4j:dom4j:jar:1.6.1:compile
[INFO] |     +- org.hibernate.javax.persistence:hibernate-jpa-2.0-api:jar:1.0.1.Final:compile
[INFO] |     \- org.hibernate.common:hibernate-commons-annotations:jar:4.0.1.Final:compile
[INFO] +- com.mycompany.myapp:myapp-install:jar:lookups:5.0.0-SNAPSHOT:test
[INFO] |  \- org.mockito:mockito-core:jar:1.9.5:test
[INFO] |     \- org.objenesis:objenesis:jar:1.0:test
[INFO] +- com.mycompany.myapp:myapp-install:jar:lookups-sample:5.0.0-SNAPSHOT:test
[INFO] +- com.mycompany.myapp:myapp-service:war:5.0.0-SNAPSHOT:test
[INFO] +- commons-io:commons-io:jar:2.1:test
[INFO] +- com.google.guava:guava:jar:14.0.1:compile
[INFO] \- org.apache.commons:commons-compress:jar:1.4.1:provided
[INFO]    \- org.tukaani:xz:jar:1.0:provided

Gunnar · **Joined:** Sat Jan 24, 2009 12:46 pm **Posts:** 388

Hi John,

I don't think you are doing something wrong, apart from using a very old version of Hibernate :)

Any chance you could try with a current release (5.1/5.2)? The bits around bytecode enhancement have been largely reworked since then, so chances are that this issue is gone by now. Also many bug fixes and performance improvements have been done since then, so I highly recommend that upgrade.

If you can't do that for whatever reason, it's a bit trickier because Hibernate ORM 4.1 isn't maintained anymore. If you are on a supported platform (JBoss EAP), we could look into a fix in the supported 4.x version. Otherwise you might open an issue in the community tracker (https://hibernate.atlassian.net/browse/HHH) and discuss with the maintainers of Hibernate ORM whether they'd be willing a fix of yours for this issue in 4.x.

One other option I can see is that you plug in a custom TraversableResolver implementation which essentially is a copy of the existing implementation and those bits around instrumentation state detection but keeps a cache of instrumentation state by class, avoiding the repeated calls to getInterfaces().

Hth,

--Gunnar

johnLavoie · **Joined:** Thu Jun 09, 2016 2:51 pm **Posts:** 3

Thanks for the feedback. Are you suggesting we only update Hibernate Validator to a recent version? Or would we need to update all hibernate libraries such as core and tool too?

Gunnar · **Joined:** Sat Jan 24, 2009 12:46 pm **Posts:** 388

Hi,

I suggest trying to update Hibernate ORM to a recent version, as that's where the repeated calls to Class#getInterfaces() originate from in the version you are using.

--Gunnar

sanne.grinovero · **Posted:** Fri Jun 17, 2016 7:08 am

Right, this was highly improved in Hibernate ORM after version 5.

Especially bytecode instrumented classes are now extremely efficient, and it keeps improving a bit on every release.