Getting Started the Hibernate3 Profiling with Spring3

[@Ali_Navab]

Hi All,
I am trying to profile our hibernate 3.6 with Spring 3.0.5 via HProf. and I did this steps:

1- put hibernate3-profiler-1.1.jar from download file into lib folder of our project
2- modify our Spring configuration file according to :  http://hibernateprofiler.com/Learn
adding the namespace and :
<bean id="sessionFactory" class="org.springframework.

orm.hibernate3.LocalSessionFactoryBean" lazy-init="true">
        <property name="entityInterceptor" ref="entityInterceptor"/>
        <property name="dataSource" ref="dataSource"/>
        <property name="configLocation" value="classpath:META-INF/hibernate.cfg.xml"/>
        <property name="configurationClass" value="org.hibernate.cfg.AnnotationConfiguration"/>
        <property name="hibernateProperties">
        <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.Oracle10gDialect</prop>
            <prop key="generate_statistics">true</prop>
        </props>
        </property>
        <hprof:profiler host="REMOTE_IP" port="22897" />
    </bean>
3- put log4j-1.2.15.jar library into our lib folder of our project. - in our project we use logback.

after all above when i run our project, this error is occur :

******
Exception in thread "main" org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'hibernate-profiler-initializer': Invocation of init method failed; nested exception is java.lang.NoSuchMethodError: org.apache.log4j.LogManager.getLoggerRepository()Lorg/apache/log4j/spi/LoggerRepository;
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:563)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:895)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:425)
        at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
        at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:93)
        at com.kishware.ebank.channelmanager.main.Application.start(Application.java:113)
        at com.kishware.ebank.channelmanager.main.Application.doStart(Application.java:84)
        at com.kishware.ebank.channelmanager.main.Application.main(Application.java:74)
Caused by: java.lang.NoSuchMethodError: org.apache.log4j.LogManager.getLoggerRepository()Lorg/apache/log4j/spi/LoggerRepository;
        at hibernatingrhinos.hibernate.profiler.appender.HibernateProfiler.initialize(HibernateProfiler.java:115)
        at hibernatingrhinos.hibernate.profiler.appender.HibernateProfiler.initialize(HibernateProfiler.java:66)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.beans.factory.config.MethodInvokingFactoryBean.doInvoke(MethodInvokingFactoryBean.java:162)
        at org.springframework.beans.factory.config.MethodInvokingFactoryBean.afterPropertiesSet(MethodInvokingFactoryBean.java:152)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1477)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
        ... 14 more

******
could anybody help me?
should i have to create log4j.xml and setting appender and logger explicitly?

hint: the root cause of error is :
Caused by: java.lang.NoSuchMethodError: org.apache.log4j.LogManager.getLoggerRepository()Lorg/apache/log4j/spi/LoggerRepository;
        at hibernatingrhinos.hibernate.profiler.appender.HibernateProfiler.initialize(HibernateProfiler.java:115)
            <HibernateProfiler.java:115 : Hierarchy repository = (Hierarchy)LogManager.getLoggerRepository(); >

Thanks and Regards,
Ali

[Oren Eini (Ayende Rahien)]

It looks like you have a mismatch with log4j.

Can you verify that you don't have any other version of it on your classpath except log4j-1.2.15

[Ali Navab]

Yes, but in our project we use log4j-over-slf4j-1.6.1 to log with logback.
could i use this library to log instead of log4j ?

See this :

SLF4J ship with a module called log4j-over-slf4j. It allows log4j users to migrate existing applications to SLF4J without changing a single line of code but simply by replacing the log4j.jar file with log4j-over-slf4j.jar, as described below.

Could you upgrade HProf to use typical class of log4j that supported in log4j-over-slf4j?
What is your solution for our project?

[Oren Eini (Ayende Rahien)]

Not right now, no.
We are hooking up fairly deeply to the log4j pipeline.

[Ali Navab]

Witch version of log4j is completely suitable ?
 log4j-1.2.15 or  log4j-1.2.17 ?

[Oren Eini (Ayende Rahien)]

log4j-1.2.15

[Ali Navab]

OK, I replace all of log4j-over-slf4j with log4j in our project and it works.
But another question is according to our setting in my first post about "LocalSessionFactoryBean",
HProf Console is showing nothing except <session factory statistics>, nothing about sessions and analysis.
Is it related to <property name="hibernateProperties"> ? what should i set for this tag?
my setting dialog is default setting. (see attachment)
what about connection string ?

Regards,

[Oren Eini (Ayende Rahien)]

It doesn't relate to the connection string, no.

You do see the connection string stats, right?

Can you check that you don't have other logging jars in the path that might intercept with that?

Do you have your own log4j config as well? Can you disable that for now?

[Ali Navab]

Dear Oren,
what is the "connection string stats" ?
no, there is no other logging jars in the path that intercept with log4j.
we use slf4j-api-1.6.1, logback-core-0.9.27, logback-classic-0.9.27 in the path.
there is no intercept in this jar files with log4j. is it ok?
I send you a snapshot of my console .

[Ali Navab]

OK but a question,
I faced to another problem that is when i run the project with HProf, after a while the number of available connections become zero and it Could not open Connection and Hibernate Session for transactions.
We are using BoneCP as our Connection pool. I tested this tool with other Connection pool for our project but nothing changed.
what can i do with this problem?

[Ali Navab]

Logs when it fall into the Errors is :
getTransferInformation Exception:  org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Cannot open connection
        at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:596)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:423)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:347)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:335)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:105)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:621)
        at $$.$$$$$$.$$$$.$$$$.acl.core.ACLServiceImpl$$EnhancerByCGLIB$$60467de5.fail(<generated>)
...
at java.lang.Thread.run(Thread.java:662)
Caused by: org.hibernate.exception.JDBCConnectionException: Cannot open connection
...
Caused by: java.sql.SQLException: Timed out waiting for a free available connection.

[Oren Eini (Ayende Rahien)]

As for first error (exception), it looks that slf4j provides incomplete
replacement of log4j: http://bugzilla.slf4j.org/show_bug.cgi?id=202
so it cannot currently be used.
As for second problem, what is your  hibernate
configuration? Perhaps there's something replacing whole hibernate
logging in client setup? 

[Eric Hauser]

Ali,

Can you place:

HibernateProfilerTrace.setTraceEnabled(true);

somewhere in the startup of your application and send me the output?  Since you are getting SessionFactory stats, that tells me that the connectivity is working between the profiler and your application but something is causing the statements to fail.

Thanks.

[Ali Navab]

Our Hibernate and Spring configuration is:

<bean id="sessionFactory" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean" lazy-init="true">

        <property name="entityInterceptor" ref="entityInterceptor"/>
        <property name="dataSource" ref="dataSource"/>
        <property name="configLocation" value="classpath:META-INF/hibernate.cfg.xml"/>
        <property name="configurationClass" value="org.hibernate.cfg.AnnotationConfiguration"/>

        <!-- Start For HProf:

        <property name="hibernateProperties">
        <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.Oracle10gDialect</prop>
            <prop key="generate_statistics">true</prop>
        </props>
        </property>

        <hprof:profiler host="192.168.121.81" port="22897" />
        End For HProf -->
    </bean>

Also hibernate.cfg.xml:
<hibernate-configuration>
<session-factory>
        <property name="hibernate.dialect">org.hibernate.dialect.Oracle10gDialect</property>
        <property name="hibernate.show_sql">true</property>
        <property name="hibernate.format_sql">true</property>
        <property name="hibernate.bytecode.use_reflection_optimizer">true</property>
        <property name="hibernate.generate_statistics">true</property>

.... Finally i could get information about Statements and Session and analysis by changing our policy for logging. I remove every thing about logback and replace it with log4j. i think java can not work with both of them in the same project. i used "slf4j-log4j12-1.6.6.jar" for mapping slf4j to log4j for third parties like hibernate. after of all above, i could profile our project for a while but after some doing some action in application all of available connection and hibernate session become finish and every thing will be corrupted. I think some thing in the middle do not allow releasing or closing the sessions.
Another question is if i want to profile our project by Configuring the application to be profile without changing the application code by setting a log4j.xml file and using appender like :

(http://hibernateprofiler.com/learn/usage/manual-config)
<appender name="Hibernate.Profiler" 
    class="hibernatingrhinos.hibernate.profiler.appender.HibernateProfilerAppender">
    <layout class="org.apache.log4j.xml.XMLLayout" />
  </appender>

how could i say to it to sink or send log data to our HProf client? something like :
    <sink value="tcp://127.0.0.1:22897" />
and Remove <hprof:profiler host="192.168.121.81" port="22897" /> from spring configuration and sessionFactory

analysis of your profiler tool is great. we are really interested in having this tool.

Regards,

[Eric Hauser]

Ali,

I'm glad you were able to get the profiler working.  I've been running some different tests against Hibernate 4, and I haven't been able to reproduce the problem that you are seeing with the connection leaks.  Based on your configuration, it does not appear that you are using the driver spy which is the only thing that would change the way that connections are being handled.  Are you certain that you do not have a connection leak in your application without the profiler enabled?

As far as configuring the profiler manually, you can certainly do that using the configuration specified on the website.  I'm not really sure that I would recommend you doing that though as it is quite a bit of work to configure all the different elements manually.  You may find different parts of the profiling working while others are failing because you missed certain packages or what not.