Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Eviction causes absence of entry in IMap and MapStore at the same time #12455

Closed
iboar opened this issue Feb 28, 2018 · 19 comments
Closed

Eviction causes absence of entry in IMap and MapStore at the same time #12455

iboar opened this issue Feb 28, 2018 · 19 comments

Comments

@iboar
Copy link

@iboar iboar commented Feb 28, 2018

Hello,

Recently I encountered problem related to eviction.

I have entity with two fields:

class AccountingRule {
    long key;
    String code;
}

Following configuration:

    private static final String ACCOUNTING_RULE_MAP_NAME = AccountingRule.class.getSimpleName();
    private static final ConcurrentHashMap<Long, AccountingRule> store = new ConcurrentHashMap<>();

    private static HazelcastInstance createHazelcastInstance() {
        HazelcastInstance hazelcastInstance = Hazelcast.newHazelcastInstance(configuration());
        log.info("Started Hazelcast Node");
        return hazelcastInstance;
    }

    private static Config configuration() {
        MapConfig mapConfig = new MapConfig(ACCOUNTING_RULE_MAP_NAME)
                .setInMemoryFormat(InMemoryFormat.BINARY)
                .setReadBackupData(true)
                .setBackupCount(1)
                .setMapStoreConfig(storeConf());

        return new ClasspathXmlConfig("hazelcast.xml").addMapConfig(mapConfig);
    }

    private static MapStoreConfig storeConf() {
        return new MapStoreConfig()
                .setWriteBatchSize(50_000)
                .setWriteDelaySeconds(30)
                .setEnabled(true)
                .setImplementation(new SimpleMapStore(store));
    }

SimpleMapStore implementation:

public class SimpleMapStore implements MapStore<Long, AccountingRule> {
    private static final Logger log = LoggerFactory.getLogger(SimpleMapStore.class);
    private final ConcurrentHashMap<Long, AccountingRule> store;

    public SimpleMapStore(ConcurrentHashMap<Long, AccountingRule> store) {
        this.store = store;
    }

    @Override
    public void store(Long key, AccountingRule value) {
        store.put(key, value);
        log.info("stored {} under {} key", value, key);
    }

    @Override
    public void storeAll(Map<Long, AccountingRule> map) {
        store.putAll(map);
        log.info("stored {} accounting rules", map.size());
    }

    @Override
    public void delete(Long key) {
        store.remove(key);
    }

    @Override
    public void deleteAll(Collection<Long> keys) {
        keys.forEach(store::remove);
    }

    @Override
    public AccountingRule load(Long key) {
        return store.get(key);
    }

    @Override
    public Map<Long, AccountingRule> loadAll(Collection<Long> keys) {
        return keys.stream()
                .map(store::get)
                .collect(toMap(AccountingRule::getKey, identity()));
    }

    @Override
    public Iterable<Long> loadAllKeys() {
        return store.keySet();
    }

In main I load 1_000_000 objects and when it's finished I start eviction. Then in a loop I check size of map and store.

    public static void main(String[] args) throws InterruptedException {
        HazelcastInstance hazelcast = createHazelcastInstance();
        IMap<Long, AccountingRule> map = hazelcast.getMap(ACCOUNTING_RULE_MAP_NAME);

        final int quantity = 1_000_000;
        loadAccountingRules(map, quantity);

        log.info("Eviction started");
        map.evictAll();


        while (true) {
            int mapSize = map.size();
            int storeSize = store.size();

            log.info("map size: {}, store size: {}", mapSize, storeSize);
            if (mapSize + storeSize < quantity) {
                log.error("Lost some entries: {} + {} < {}", mapSize, storeSize, quantity);
            }
            Thread.sleep(500);
        }
    }

Results:

14:22:26,559  INFO Test:27 - Started Hazelcast Node
14:22:26,581  INFO Test:75 - Loading 1000000 Accounting Rules
14:22:43,752  INFO Test:80 - Loading finished map size is 1000000
14:22:43,752  INFO Test:56 - Eviction started
14:22:44,137  INFO Test:64 - map size: 0, store size: 0
14:22:44,138 ERROR Test:66 - Lost some entries: 0 + 0 < 1000000
14:22:44,647  INFO Test:64 - map size: 0, store size: 0
14:22:44,647 ERROR Test:66 - Lost some entries: 0 + 0 < 1000000
14:22:45,013  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:45,152  INFO Test:64 - map size: 0, store size: 50000
14:22:45,152 ERROR Test:66 - Lost some entries: 0 + 50000 < 1000000
14:22:45,232  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:45,435  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:45,580  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:45,660  INFO Test:64 - map size: 0, store size: 200000
14:22:45,660 ERROR Test:66 - Lost some entries: 0 + 200000 < 1000000
14:22:45,706  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:45,826  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:45,939  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:46,063  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:46,163  INFO Test:64 - map size: 0, store size: 400000
14:22:46,163 ERROR Test:66 - Lost some entries: 0 + 400000 < 1000000
14:22:46,176  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,084  INFO Test:64 - map size: 0, store size: 450000
14:22:48,085 ERROR Test:66 - Lost some entries: 0 + 450000 < 1000000
14:22:48,133  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,256  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,373  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,483  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,589  INFO Test:64 - map size: 0, store size: 664992
14:22:48,589 ERROR Test:66 - Lost some entries: 0 + 664992 < 1000000
14:22:48,595  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,712  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,864  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:48,972  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:49,082  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:49,095  INFO Test:64 - map size: 0, store size: 900000
14:22:49,095 ERROR Test:66 - Lost some entries: 0 + 900000 < 1000000
14:22:49,205  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:49,318  INFO SimpleMapStore:31 - stored 50000 accounting rules
14:22:49,598  INFO Test:64 - map size: 0, store size: 1000000
14:22:50,100  INFO Test:64 - map size: 0, store size: 1000000
14:22:50,604  INFO Test:64 - map size: 0, store size: 1000000

Comment:

It looks like just after evictAll is invoked map is cleared and eviction is done in different thread. It causes situation when objects are not available in IMap and MapStore at the same time. I cannot start any processing because objects are not available. Of course as it is visible in logs after some time situation is stable and MapStore is full. Problem is I don't know when it happens exactly.

Is it a bug? Does IMap should wait for MapStore and be cleared after everything is available in MapStore? Any suggestions how to avoid mentioned situation?

@mmedenjak mmedenjak added this to the 3.10 milestone Feb 28, 2018
@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Feb 28, 2018

Hi @iboar,

Since it is a write-behind map-store, it sends entries to map-store after some delay. Can you try with write-through map-store? Is it ok to use it in your case?

@iboar
Copy link
Author

@iboar iboar commented Feb 28, 2018

@ahmetmircik,
Thanks for quick reply. Sure write-delay=0 fix the problem but unfortunately we have to use write behind approach. Is it possible somehow to force Hazelcast to check if data was stored in MapStore before removing it from cache?

@TomaszGaweda
Copy link
Contributor

@TomaszGaweda TomaszGaweda commented Feb 28, 2018

In EvictOperation we have possibility to access WriteBehindStore. The only thing to think about is if we should wait with eviction until entry is in write behind queue or just leave every entry that is not saved.

Maybe we can make it configurable? Some new property with values: current behaviour, wait until entry in write behind, don't evict if in write-behind. Then users can keep current behaviour or use one of the new options, that will also help iboar

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 1, 2018

@iboar entries should be available to the map operations independent of they stored or not. Maybe you can share a simple test code that shows your expected behavior?

@iboar
Copy link
Author

@iboar iboar commented Mar 1, 2018

@ahmetmircik I am not sure if we understood each other but my example shows that entries are not available to map operations for some time after eviction process was invoked. And that is my problem.

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 1, 2018

so for example, if you do a map#get after evictAll, it should return the latest write before eviction, because map#get will read not-stored entry from write-behind-queue. I was asking a reproducer over IMap interface, your example is using map-store instance to show it.

@iboar
Copy link
Author

@iboar iboar commented Mar 1, 2018

In loop I am checking map#size and store#size and just after evictAll map is empty and store as well. Store starts to be filled with data after some time.

I have tried map#get just after evictAll and you are right it works (strange is that after calling map#get map#size has changed to 1), my main and logs:

    public static void main(String[] args) throws InterruptedException {
        HazelcastInstance hazelcast = createHazelcastInstance();
        IMap<Long, AccountingRule> map = hazelcast.getMap(ACCOUNTING_RULE_MAP_NAME);

        final int quantity = 1_000_000;
        loadAccountingRules(map, quantity);

        log.info("entry with key=10 {}", map.get(10L));

        log.info("Eviction started");
        map.evictAll();


        while (true) {
            int mapSize = map.size();
            int storeSize = store.size();

            log.info("entry with key=10 {}", map.get(10L));

            log.info("map size: {}, store size: {}", mapSize, storeSize);
            if (mapSize + storeSize < quantity) {
                log.error("Lost some entries: {} + {} < {}", mapSize, storeSize, quantity);
            }
            Thread.sleep(500);
        }
    }
15:45:21,465  INFO Test:28 - Started Hazelcast Node
15:45:21,487  INFO Test:79 - Loading 1000000 Accounting Rules
15:45:38,480  INFO Test:84 - Loading finished map size is 1000000
15:45:38,496  INFO Test:57 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:38,496  INFO Test:59 - Eviction started
15:45:38,859  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:38,859  INFO Test:69 - map size: 0, store size: 0
15:45:38,860 ERROR Test:71 - Lost some entries: 0 + 0 < 1000000
15:45:39,379  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:39,379  INFO Test:69 - map size: 1, store size: 0
15:45:39,379 ERROR Test:71 - Lost some entries: 1 + 0 < 1000000
15:45:39,680  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:39,827  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:39,881  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:39,881  INFO Test:69 - map size: 1, store size: 100000
15:45:39,881 ERROR Test:71 - Lost some entries: 1 + 100000 < 1000000
15:45:39,943  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:41,489  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:41,489  INFO Test:69 - map size: 1, store size: 196608
15:45:41,489 ERROR Test:71 - Lost some entries: 1 + 196608 < 1000000
15:45:41,504  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:41,589  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:41,689  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:41,790  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:41,905  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:41,990  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:41,990  INFO Test:69 - map size: 1, store size: 400000
15:45:41,990 ERROR Test:71 - Lost some entries: 1 + 400000 < 1000000
15:45:41,990  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,089  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,189  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,290  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,390  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,475  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,490  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:42,490  INFO Test:69 - map size: 1, store size: 700000
15:45:42,490 ERROR Test:71 - Lost some entries: 1 + 700000 < 1000000
15:45:42,575  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,691  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,775  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,876  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,960  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:42,992  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:42,992  INFO Test:69 - map size: 1, store size: 950000
15:45:42,992 ERROR Test:71 - Lost some entries: 1 + 950000 < 1000000
15:45:43,238  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:45:43,504  INFO Test:67 - entry with key=10 AccountingRule[key=10,code=uniqueCode10]
15:45:43,504  INFO Test:69 - map size: 1, store size: 1000000

But map#values with predicate does not work (no entries available either in map or store), my main and logs:

    public static void main(String[] args) throws InterruptedException {
        HazelcastInstance hazelcast = createHazelcastInstance();
        IMap<Long, AccountingRule> map = hazelcast.getMap(ACCOUNTING_RULE_MAP_NAME);

        final int quantity = 1_000_000;
        loadAccountingRules(map, quantity);

        log.info("entries with code=%uniqueCode% {}", map.values(like("code", "%uniqueCode%")).size());
        
        log.info("Eviction started");
        map.evictAll();


        while (true) {
            int mapSize = map.size();
            int storeSize = store.size();

            log.info("entries with code=%uniqueCode% {}", map.values(like("code", "%uniqueCode%")).size());

            log.info("map size: {}, store size: {}", mapSize, storeSize);
            if (mapSize + storeSize < quantity) {
                log.error("Lost some entries: {} + {} < {}", mapSize, storeSize, quantity);
            }
            Thread.sleep(500);
        }
    }
15:47:39,054  INFO Test:28 - Started Hazelcast Node
15:47:39,086  INFO Test:79 - Loading 1000000 Accounting Rules
15:47:55,878  INFO Test:84 - Loading finished map size is 1000000
15:47:59,603  INFO Test:57 - entries with code=%uniqueCode% 1000000
15:47:59,603  INFO Test:59 - Eviction started
15:48:00,392  INFO Test:67 - entries with code=%uniqueCode% 0
15:48:00,392  INFO Test:69 - map size: 0, store size: 0
15:48:00,393 ERROR Test:71 - Lost some entries: 0 + 0 < 1000000
15:48:00,719  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:00,850  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:00,900  INFO Test:67 - entries with code=%uniqueCode% 0
15:48:00,901  INFO Test:69 - map size: 0, store size: 100000
15:48:00,901 ERROR Test:71 - Lost some entries: 0 + 100000 < 1000000
15:48:00,982  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,104  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,198  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,282  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,382  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,420  INFO Test:67 - entries with code=%uniqueCode% 0
15:48:01,420  INFO Test:69 - map size: 0, store size: 350000
15:48:01,420 ERROR Test:71 - Lost some entries: 0 + 350000 < 1000000
15:48:01,504  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,605  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,705  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,804  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,883  INFO SimpleMapStore:31 - stored 50000 accounting rules
15:48:01,921  INFO Test:67 - entries with code=%uniqueCode% 0
15:48:01,921  INFO Test:69 - map size: 0, store size: 600000
15:48:01,921 ERROR Test:71 - Lost some entries: 0 + 600000 < 1000000

So conclusion is that map#get returns entry (even if map#size says it's empty) but map#values does not return anything.

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 1, 2018

just trying to clarify the picture, thx.

so after evictAll, which imap methods do you call? for instance, how do you put data into map again? Which operations are you calling?

@iboar
Copy link
Author

@iboar iboar commented Mar 1, 2018

As it was showed in last example I use IMap#values. I don't put data to map again at all.

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 2, 2018

Even you use write-through map-store, after evictAll call, IMap#values will always return empty collection since it never loads entries from map-store to IMap. IMap#values only returns existing entries in memory.

But this is not the case for IMap#get, as can be seen from its documentation, IMap#get loads missing keys from map-store.

According to these, i expect you need to re-populate IMap somehow to continue further processing. This is why i was asking how do you put data into map again? .

@iboar
Copy link
Author

@iboar iboar commented Mar 5, 2018

@ahmetmircik

I will explain exactly what we do in our project.
Let's say that we use in some cases our read-through implementation which looks like that:

  • read some entries from cache, we use IMap#values with predicate method
  • if nothing found in cache then,
  • read some entries from db (we have implemented map store which writes into db), we use jpa

It works well besides one situation. Something is wrong when we use it just after eviction was triggered, what happened:

  • we read from cache and it's empty
  • we read from db and it's also empty

So from our perspective eviction hides entities for a while and we cannot access them either from cache or db.
Probably repopulating map is not an option. I assume we have to wait until eviction is fully finished and this one will a problem.

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 5, 2018

read some entries from db (we have implemented map store which writes into db), we use jpa

is my understanding correct that you are reading from db without using imap api? so this means you directly use map-store implementation to read data?

@iboar
Copy link
Author

@iboar iboar commented Mar 5, 2018

Yes, in this case I read directly db without any hazelcast mechanism.

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 5, 2018

if you want a way without using IMap api to read db data, no support exists for this.

But we can try to find a different way to provide the desired behavior like:

  • by using IMap#getAll(missingKeys) if you know missing ones?
  • or by eliminating evictAll call btw what was the need for this?
@iboar
Copy link
Author

@iboar iboar commented Mar 5, 2018

if I do IMap#getAll(missingKeys) then eviction is not fully done because I will have entries in cache and in store (db). After eviction I should have it only in db.

I need to somehow wait until eviction process is finished to do what I want to do. If processing is done during eviction then entries are unavailable.

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 5, 2018

as an alternative approach did you try IMap#flush before IMap#evictAll?

*please keep in mind that map-store is designed to work behind IMap and all data accesses should be done by using IMap abstraction.

@iboar
Copy link
Author

@iboar iboar commented Mar 5, 2018

Hmmm... thanks it may work :)

@ahmetmircik
Copy link
Member

@ahmetmircik ahmetmircik commented Mar 7, 2018

@iboar can we close this issue?

@iboar
Copy link
Author

@iboar iboar commented Mar 7, 2018

yes, please do it. Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants