Logger while each call of relationship (association/collection) method of mybatis pojo affecting performance.

[Parag Dhikale]

Hi,

I have lazy loading set to true. Following is my configuration settings:
    <settings>
        <setting name="aggressiveLazyLoading" value="false" />
        <setting name="lazyLoadingEnabled" value="true" />
        <setting name="jdbcTypeForNull" value="VARCHAR" />
        <setting name="defaultExecutorType" value="REUSE"/>
        <setting name="defaultStatementTimeout" value="25000"/>
        <setting name="lazyLoadTriggerMethods" value="clone"/>
    </settings>

I do not have set any specific logger configuration set in mybatis configuration xml. Neither do I have any logger statements in my POJOs, also I do not see any log statements being printed from those POJOs. But still in the each call of 'org.apache.ibatis.executor.loader.CglibProxyFactory$EnhancedResultObjectProxyImpl.intercept(Object, Method, Object[], MethodProxy)' method, during relationship(association/collection) method call, I can see following statement getting called, and which is taking like 70% of the total object load time.
           'org.slf4j.impl.JDK14LoggerAdapter.log(Marker, String, int, String, Object[], Throwable)'

Why is this 'log' method getting called during each call of relationship(association/collection) method of mybatis POJO even if I have no specific configuration set for it? And strange thing is, no logger from that POJO is getting printed in actual log.

That is really degrading the performance. How can I eliminate this call? is there any specific configuration for this?

Thanks,
Parag

[Eduardo Macarron]

Which version are you using?

2013/5/13 Parag Dhikale <paragd...@gmail.com>:

> --
> You received this message because you are subscribed to the Google Groups
> "mybatis-user" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mybatis-user...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>

[Parag Dhikale]

Sorry, I forgot to mention that.
I am using mybatis 3.2.2.

[Eduardo Macarron]

Can you get an stacktrace to know where is it being called from?

2013/5/14 Parag Dhikale <paragd...@gmail.com>:

[Parag Dhikale]

[Parag Dhikale]

Actually I am seeing this in the YJP (yourkit java prifiler) captured snapshot. Even I am still trying to find out in the mybatis source code where exactly it is being called from.
From YJP stacktrace, it is showing "org.slf4j.impl.JDK14LoggerAdapter.log(Marker, String, int, String, Object[], Throwable) 171 0 200" call exactly under "org.apache.ibatis.executor.loader.CglibProxyFactory$EnhancedResultObjectProxyImpl.intercept(Object, Method, Object[], MethodProxy) 7827 6677 25" call.

So YJP stacktrace is like this:

- com.sigma.samp.stm.topology.pojo.LinkPojo$$EnhancerByCGLIB$$5a12dfc0.getFromSubnetworkNode() 5859 0
    - org.apache.ibatis.executor.loader.CglibProxyFactory$EnhancedResultObjectProxyImpl.intercept(Object, Method, Object[], MethodProxy) 7827 6677 25
        + org.slf4j.impl.JDK14LoggerAdapter.log(Marker, String, int, String, Object[], Throwable) 171 0 200
        + oracle.jdbc.driver.OraclePreparedStatementWrapper.execute() 562 64
           oracle.jdbc.driver.OracleResultSetImpl.wasNull() 84 84
           oracle.jdbc.driver.OracleResultSetImpl.getString(int) 59 59
        + net.sf.cglib.proxy.Enhancer.create() 40 0
           oracle.jdbc.driver.OracleResultSetImpl.getMetaData() 39 39
           oracle.jdbc.driver.OracleStatementWrapper.clearWarnings() 21 21

[Eduardo Macarron]

Looks like that call comes from the oracle driver, does't it?

oracle.jdbc.driver.OraclePreparedStatementWrapper.execute() 562 64

[Parag Dhikale]

No, I don't think so. The statement you listed below is at the same level as that of logger statement in stacktrace.
So, this oracle driver call and this logger statement call are at the same level.

[Eduardo Macarron]

Ah, sorry I thought that was an stacktrace. Sorry.

I cannot find any call to log in our code:
https://github.com/mybatis/mybatis-3/blob/mybatis-3.2.2/src/main/java/org/apache/ibatis/executor/loader/CglibProxyFactory.java

Do you have any hint?

[Parag Dhikale]

Even I didn't find it being used anywhere.
But I have found a solution. By default logImpl uses SLF4J, whose log method we could see in the profiler output taking time.

I tried changing logImpl. I set 'logImpl' property in <settings> as:
        <setting name="logImpl" value="LOG4J"/>
And now I do not see that method in the profiller's stacktrace. Also performance is increased significantly.

I think it clearly means that log() of log4J is much faster than SLF4J, as it is not shown in profiller taking time.

Thanks
Parag

[Eduardo Macarron]

In any case there is not any call to a jdbc api (PreparedStatement)
from that code so we can assume that call comes from elsewhere.

The docs about logs are online http://mybatis.github.io/mybatis-3/logging.html

I would first check if log is enabled for any namespace.

2013/5/14 Parag Dhikale <paragd...@gmail.com>:

[Parag Dhikale]

I am still confused, if call is coming from elsewhere, then how come YJP is showing that method being called from intercept() method?
I do not have any logging enabled in my settings for sure.