Unexpected cache hit ratio is reported for a SELECT with flushCache enabled

[mengxiandong]

My email: 863828874@qq.com

Issue version: mybatis 3.5.1

Phenomenon description:

    declare an SQL, configure flachcache = true, and then use two sessions to query and submit; query and submit, session 2 hits the cache and queries the database（Console print log：Cache Hit Ratio [org.coderead.mybatis.UserMapper]: 0.5）. I think hit cache and database query should be mutually exclusive.
   The execution process of mybatis is as follows:
           Session 1: clear the temporary storage area - > Put in the second level cache
           Session 2: clear the temporary storage area - > get the old value from the cache area - > query the database to get the new value, put in the second level cache - > return the new value

==============Here are the main source code and console logs================

==============The Test Class================

package org.coderead.mybatis.cache;

import org.apache.ibatis.session.SqlSession;
import org.apache.ibatis.session.SqlSessionFactory;
import org.apache.ibatis.session.SqlSessionFactoryBuilder;
import org.coderead.mybatis.StatementHandlerTest;
import org.coderead.mybatis.UserMapper;

/**
 * @since 2020年6月13日20:28:39
 */
public class MySecondCacheTest {

    public static void main(String[] args) {
        SqlSessionFactoryBuilder factoryBuilder = new SqlSessionFactoryBuilder();
        SqlSessionFactory factory = factoryBuilder.build(StatementHandlerTest.class.getResourceAsStream("/mybatis-config.xml"));
        for(int i = 0; i < 2; i++){
            SqlSession session = factory.openSession();
            session.getMapper(UserMapper.class).selectByid3(10);
            session.commit();
        }
    }

}

==============The Mapper================

package org.coderead.mybatis;

import org.apache.ibatis.annotations.CacheNamespace;
import org.apache.ibatis.annotations.Options;
import org.apache.ibatis.annotations.Select;
import org.coderead.mybatis.bean.User;

@CacheNamespace
public interface UserMapper {

    @Select({"select * from users where id=#{1}"})
    @Options(flushCache = Options.FlushCachePolicy.TRUE)
    User selectByid3(Integer id);
}

==============The console logs================

22:02:30,443 DEBUG org.coderead.mybatis.UserMapper:54 - Cache Hit Ratio [org.coderead.mybatis.UserMapper]: 0.0
22:02:30,447 DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction:54 - Opening JDBC Connection
Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
22:02:30,979 DEBUG org.apache.ibatis.datasource.pooled.PooledDataSource:54 - Created connection 1742920067.
22:02:30,980 DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction:54 - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@67e2d983]
22:02:31,034 DEBUG org.coderead.mybatis.UserMapper.selectByid3:54 - ==>  Preparing: select * from users where id=? 
22:02:31,060 DEBUG org.coderead.mybatis.UserMapper.selectByid3:54 - ==> Parameters: 10(Integer)
22:02:31,115 DEBUG org.coderead.mybatis.UserMapper.selectByid3:54 - <==      Total: 1
22:02:31,123 DEBUG org.coderead.mybatis.UserMapper:54 - Cache Hit Ratio [org.coderead.mybatis.UserMapper]: 0.5
22:02:31,123 DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction:54 - Opening JDBC Connection
22:02:31,439 DEBUG org.apache.ibatis.datasource.pooled.PooledDataSource:54 - Created connection 1891502635.
22:02:31,439 DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction:54 - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@70be0a2b]
22:02:31,477 DEBUG org.coderead.mybatis.UserMapper.selectByid3:54 - ==>  Preparing: select * from users where id=? 
22:02:31,477 DEBUG org.coderead.mybatis.UserMapper.selectByid3:54 - ==> Parameters: 10(Integer)
22:02:31,519 DEBUG org.coderead.mybatis.UserMapper.selectByid3:54 - <==      Total: 1

[harawata]

Hello @mengxiandong ,

We may be able to skip cache lookup when flushCache is enabled.
As a result, there will be no "Cache Hit Ratio" output in the log if flushCache is enabled for a SELECT.
Is this the expected behavior?

[mengxiandong]

Yes, I think so. What you said is exactly what I expected. Here is the source code I traced. I hope it can help. The problem may be in this approach: TransactionalCache.getObject Maybe this [ if (clearOnCommit) ] judgment should be placed in the first line of the current method, but I'm not sure what impact it will have, because I'm not sure about the function of the [entriesMissedInCache] set at present ================ TransactionalCache ================== @OverRide public Object getObject(Object key) { // issue #116 Object object = delegate.getObject(key); if (object == null) { entriesMissedInCache.add(key); } // issue #146 if (clearOnCommit) { return null; } else { return object; } }

…

------------------ 原始邮件 ------------------ 发件人:&nbsp;"Iwao AVE!"<notifications@github.com&gt;; 发送时间:&nbsp;2020年6月15日(星期一) 晚上11:56 收件人:&nbsp;"mybatis/mybatis-3"<mybatis-3@noreply.github.com&gt;; 抄送:&nbsp;"枫"<863828874@qq.com&gt;;"Mention"<mention@noreply.github.com&gt;; 主题:&nbsp;Re: [mybatis/mybatis-3] The bug in L2 cache (#1960) Hello @mengxiandong , We may be able to skip cache lookup when flushCache is enabled. As a result, there will be no "Cache Hit Ratio" output in the log if flushCache is enabled for a SELECT. Is this the expected behavior? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[DaveTony]

I think that's the problem：put Object in the entriesToAddOnCommit.put(key, object)，but get Object in delegate.getObject(key)。

@override
public void putObject(Object key, Object object) {
entriesToAddOnCommit.put(key, object);
}


@override
public Object getObject(Object key) {
// issue #116
Object object = delegate.getObject(key);
if (object == null) {
entriesMissedInCache.add(key);
}
// issue #146
if (clearOnCommit) {
return null;
} else {
return object;
}
}

[harawata]

I wrote a patch, but it could cause another problem (BlockingCache, for example, expects getObject() to be invoked before putObject() is invoked).

I'll keep this issue open until someone finds a good solution.

[whq4123]

I think the root cause of the unexpected cache ratio report is flushing cache logic error.
the configuration of flushCache enabled means developer want to flush the L2 cache, but the coding logic is flushing pending entries after clearing L2 cache like this:
public void commit() { if (clearOnCommit) { delegate.clear(); } flushPendingEntries(); reset(); }
so I think we should flush pending entries first or don't flush them when flushCache is enabled.
Is my understanding right? if so, I'm willing to pull a request.

[harawata]

@whq4123 ,
Are you referring to the TransactionalCache#commit() method?
That method is used by other statements than SELECT and changing the implementation could break backward compatibility (but I am not so sure).
Is there any broken test if you made that change?

To all,
Now that I think about the issue again, it might make more sense not to cache the query result when a SELECT statement's flushCache is enabled (the cache will never be used anyway, right?).
I have updated my patch, so please take a look and let me know what you think!