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

[mengxiandong]

My email: [email protected]

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; } }

------------------ 原始邮件 ------------------ 发件人: "Iwao AVE!"<[email protected]>; 发送时间: 2020年6月15日(星期一) 晚上11:56 收件人: "mybatis/mybatis-3"<[email protected]>; 抄送: "枫"<[email protected]>;"Mention"<[email protected]>; 主题: 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!

[liuyueve]

@harawata . I think you patch can't solve this problem fundamentally. see this code;

public static void main(String[] args) throws IOException {
    InputStream resource = Resources.getResourceAsStream("mybatis/config.xml");
    SqlSessionFactory sqlSessionFactory = new SqlSessionFactoryBuilder().build(resource);

    SqlSession sqlSession = sqlSessionFactory.openSession();
    BasicMapper mapper = sqlSession.getMapper(BasicMapper.class);
    //step one: cache id 1 into L2
    mapper.queryName(1);
    sqlSession.commit();

    sqlSession = sqlSessionFactory.openSession();
    mapper = sqlSession.getMapper(BasicMapper.class);
    //step two: flush cache but not commit
    mapper.updateName(1);

    //step three: query id 1.
    //  because i have flush cache,so i except no cache hit but actually it still log hit.
    mapper.queryName(1);
    sqlSession.commit();
}

log information :

17:41:43.027 [main] DEBUG org.apache.ibatis.datasource.pooled.PooledDataSource - Created connection 1640296160. 17:41:43.030 [main] DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@61c4eee0] 17:41:43.040 [main] DEBUG com.haizhi.template.mapper.BasicMapper.queryName - ==> Preparing: selectcamera_idfromDevicewhere id = ? 17:41:43.149 [main] DEBUG com.haizhi.template.mapper.BasicMapper.queryName - ==> Parameters: 1(Integer) 17:41:43.284 [main] DEBUG com.haizhi.template.mapper.BasicMapper.queryName - <== Total: 1 17:41:43.303 [main] DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction - Opening JDBC Connection 17:41:43.325 [main] DEBUG org.apache.ibatis.datasource.pooled.PooledDataSource - Created connection 837659261. 17:41:43.326 [main] DEBUG org.apache.ibatis.transaction.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@31edaa7d] 17:41:43.328 [main] DEBUG com.haizhi.template.mapper.BasicMapper.updateName - ==> Preparing: updateDevicesetcamera_id=camera_idwhere id = ? 17:41:43.331 [main] DEBUG com.haizhi.template.mapper.BasicMapper.updateName - ==> Parameters: 1(Integer) 17:41:43.337 [main] DEBUG com.haizhi.template.mapper.BasicMapper.updateName - <== Updates: 1 17:41:43.349 [main] DEBUG com.haizhi.template.mapper.BasicMapper - Cache Hit Ratio [com.haizhi.template.mapper.BasicMapper]: 0.5 17:41:43.352 [main] DEBUG com.haizhi.template.mapper.BasicMapper.queryName - ==> Preparing: selectcamera_idfromDevicewhere id = ? 17:41:43.354 [main] DEBUG com.haizhi.template.mapper.BasicMapper.queryName - ==> Parameters: 1(Integer) 17:41:43.363 [main] DEBUG com.haizhi.template.mapper.BasicMapper.queryName - <== Total: 1

============ so i think you method is wrong. @whq4123 and also we can't delete cache at TransactionalCache#clear() .Because if we do that,when session is rollback.nothing has change but cache is clear.so that is still a wrong answer.

============

Ultimately,the reason cause this problem is when cache is flush .we can't get cache from L2 but we do that. So i think we can fix this problem like this . pr #2041

[harawata]

Hello @liuyueve ,

I couldn't understand the first part of your comment. Please provide something executable (i.e. a test case. or demo project).

I'll take a look at the PR later.

[liuyueve]

Hello @harawata , I have push my test code into github mybatis-test Please run this test with mybatis version in your patch,and I believe you will find problem.

[harawata]

@liuyueve ,

The select statement in your test does not have @Options(flushCache = Options.FlushCachePolicy.TRUE), so it is a different issue than this one. I added a comment on #2041 .

[liuyueve]

@harawata , yes yes ! This is where problem in.If we change code follow your patch. When I add @Options(flushCache = Options.FlushCachePolicy.TRUE) in select statement ,there is no problem.but when I don't add flush option in select statement ,the problem is still exist. In my opinion,that is as same as this issue.The root for this two problem is we shouldn't search from cache after cache flushed.

[harawata]

@liuyueve , The symptom looks similar, but your usage (i.e. scenario involving non-select statements) is much more complicated and it is not easy to solve it without breaking backward compatibility, so let's focus on SELECT with flushCache enabled in this issue.

[xbcrh]

I think whether it is possible to clear the real cache when the Clear() method is executed. like this(TransactionCache):

@Override
public void clear() {
     clearOnCommit = true;
     entriesToAddOnCommit.clear();
     delegate.clear(); 
}

if this right, I'm willing to pull a request.

[harawata]

@xbcrh , No, it is not right. The purpose of TransactionalCache is to hold cache changes until commit in case the transaction is rolled back.

[plusmancn]

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!

Agree with it.
The cache key was generated base on Method and QueryParams. If a method that configures flushCache=true will flush the cache every time when it is invoked, therefore the cache will never be used;

Maybe flushCache as a configuration option is meaningless and should be removed in the future release. But flushCache as a method is useful, application can update caches when receiving update events from somewhere(eg: message queue).