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

MapStore.storeAll() never called when objects updated with delay #7464

Closed
dmitrymz opened this issue Feb 4, 2016 · 18 comments

Comments

Projects
None yet
5 participants
@dmitrymz
Copy link

commented Feb 4, 2016

I am implementing MapStore.storeAll() for our cluster to periodically backup the maps.
I configured the cluster nodes for write-behind feature, ie put 60sec for testing.
Ran the test, where updated one, two, three map values within a minute.
However, only store() method got called (3 times)
Expected behavior: storeAll() called once per minute with the full map contents.
please, advise.

   Hazelcast version: 3.5.5
   Cluster size: 2 nodes
   Number of the clients: 1
   Version of Java: 1.8.0_20
   Operating system: 3.13.0-77-generic #121-Ubuntu SMP Wed Jan 20 10:50:42 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux


@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

hazelcast.xml (partial)

   <properties>
        <property name="hazelcast.logging.type">slf4j</property>
        <property name="hazelcast.icmp.enabled">true</property>
    </properties>

    <network>
        <port auto-increment="false">5701</port>
        <join>
            <multicast enabled="false"/>
            <tcp-ip enabled="false"/>
            <aws enabled="true">
                <region>us-west-2</region>
                ...
            </aws>
        </join>
    </network>

    <serialization>
        <portable-version>0</portable-version>
        <portable-factories>
            <portable-factory factory-id="1">
                com.mz.retail.view.datagrid.model.MyPortableFactory
            </portable-factory>
        </portable-factories>
    </serialization>

    <map name="cont_*">
        <map-store enabled="true">
            <factory-class-name>com.mz.retail.view.datagrid.backup.MyMapStoreFactory</factory-class-name>
            <write-delay-seconds>60</write-delay-seconds>
        </map-store>
    </map>
</hazelcast>

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

called to update 3 different values multiple times within a minute, here are the logs:

2016-02-04 18:55:35,629 INFO  [com.mz.retail.view.datagrid.backup.MyMapStore] ======== store
2016-02-04 18:55:39,629 INFO  [com.mz.retail.view.datagrid.backup.MyMapStore] ======== store
2016-02-04 18:55:42,629 INFO  [com.mz.retail.view.datagrid.backup.MyMapStore] ======== store
@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

this is a part of MapStore implementation:

public class MyMapStore implements MapStore<String, MZTypeDo> {

private String mapName;
private MapStoreDao mapStoreDao;

public MyMapStore(String mapName, MapStoreDao mapStoreDao) {
    this.mapName = mapName;
    this.mapStoreDao = mapStoreDao;
    log.info("======== initialized");
}

@Override
public void store(String key, MZTypeDo c) {
    log.info("======== store");
}

@Override
public void storeAll(Map<String, MZTypeDo> org) {
    log.info("======== storeAll");

    mapStoreDao.store(mapName, org);
}

...
}

@noctarius

This comment has been minimized.

Copy link
Contributor

commented Feb 4, 2016

As far as I'm aware of MapStore::storeAll is only used whenever you call IMap::putAll.

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

from the hazelcast.xml doc:
or http://docs.hazelcast.org/docs/3.5/manual/html/mapconfiguration.html
http://docs.hazelcast.org/docs/3.5/manual/html/map-persistence.html

  <!--
    Number of seconds to delay to call the MapStore.store(key, value).
    If the value is zero then it is write-through so MapStore.store(key, value)
    will be called as soon as the entry is updated.
    Otherwise it is write-behind so updates will be stored after write-delay-seconds
    value by calling Hazelcast.storeAll(map). Default value is 0.
  -->

from MapStore class doc:
http://docs.hazelcast.org/docs/3.5/javadoc/com/hazelcast/core/MapStore.html

/**
 * Stores multiple entries. Implementation of this method can optimize the
 * store operation by storing all entries in one database connection.
 * storeAll is used when writeDelaySeconds is positive (write-behind).
 * If an exception is thrown, the entries will try to be stored one by one using the store() method.
 *
 * @param map map of entries to store
 */
void storeAll(Map<K, V> map);
@noctarius

This comment has been minimized.

Copy link
Contributor

commented Feb 4, 2016

Hm good catch, @ahmetmircik any idea about that?

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

is it possible that write-batch-size parameter is affecting this?

"The number of operations to be included in each batch processing round. Default value is 1."

however, per documentation, that shouldn't be needed:
http://docs.hazelcast.org/docs/3.5/manual/html/mapconfiguration.html

write-delay-seconds: Number of seconds to delay to call the MapStore.store(key, value). If the value is zero then it is write-through so MapStore.store(key, value) will be called as soon as the entry is updated. Otherwise it is write-behind so updates will be stored after write-delay-seconds value by calling Hazelcast.storeAll(map). Default value is 0.
write-batch-size: Used to create batch chunks when writing map store. In default mode, all map entries will be tried to be written in one go. To create batch chunks, the minimum meaningful value for write-batch-size is 2. For values smaller than 2, it works as in default mode.

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

answering my question above: no write-batch-size has no effect.
tried the same test with write-batch-size=100000 - still singe store() method was called 3 times

@ahmetmircik

This comment has been minimized.

Copy link
Member

commented Feb 4, 2016

Hi @dmitrymz,

Could you please share a simple reproducer test? It will be easier to talk on that.

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

I don't have much of a test.
Our setup is a simple webservice storing values in Hazelcast.
On the cluster side we attached the MapStore with configuration mentioned above.

You can simply reproduce the issue just by having these 2 components.

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 4, 2016

I did some basic debugging using setup above and hazelcast source code, and found that DefaultWriteBehindProcessor.callHandler() is always called with just one delayedEntry, therefore this check

        if (size == 1 || !writeCoalescing) {
            return processEntriesOneByOne(delayedEntries, operationType);
        }

is always true - here is one by one call to store().

Expected: WriteBehindProcessor should accumulate updated records over period of time specified in
write-delay-seconds, then flush them with storeAll() method or deleteAll() method.
basically, we should never expect single store(), delete() methods to be invoked in write-behind mode in my understanding

@gurbuzali

This comment has been minimized.

Copy link
Member

commented Feb 5, 2016

I've tried to reproduce your case here (with the latest master) but couldn't
https://gist.github.com/gurbuzali/34589488f6b5352d92be

@ahmetmircik

This comment has been minimized.

Copy link
Member

commented Feb 5, 2016

@dmitrymz I see your point this is a bug. Batching should take place where it is possible. Thanks for reporting this.

@ahmetmircik ahmetmircik added this to the 3.6.1 milestone Feb 5, 2016

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 5, 2016

@gurbuzali I used 3.5.5 release from here https://github.com/hazelcast/hazelcast/releases/tag/v3.5.5

also just tried with https://github.com/hazelcast/hazelcast/releases/tag/v3.6
still same

in your example you are not using any delays between puts, that's why it works. see my comments below

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 5, 2016

@ahmetmircik seems like I found an issue, and a way to reproduce it:
add a simple delay of 1sec between updating the the objects, ie

while (true) {
 put(key, value);
 sleep(1000);
}

the problem is the way hazelcast server does the aggregates for puts. if they all come instantly in bulk then storeAll() is called. this explains why putAll() is working and put() is not

when puts are called with delays then, store() is called. the longer the delay - the more chance single store() to be called.

try experiment with delays 50ms, 100ms, 300ms, 500ms, and so on

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 5, 2016

there is another subproblem that I found experimenting a loop above with no delays - storeAll() is split in multiple calls.

try this scenario: update 100 elements with no delay.
you will see most likely two storeAll() calls within write-delay-seconds period, ie

storeAll(29 elements)
storeAll(71 elements)

next time

storeAll(23 elements)
storeAll(77 elements)

looks like aggregation logic should be fixed:

  1. to consolidate all single updates within write-delay-seconds
  2. make just one call to storeAll() with consolidated values
  3. never call single store(), and single delete() methods as per contract, even just one item is updated withing write-delay period

@dmitrymz dmitrymz changed the title MapStore.storeAll() never called if just several objects updated MapStore.storeAll() never called objects updated with delay Feb 5, 2016

@dmitrymz dmitrymz changed the title MapStore.storeAll() never called objects updated with delay MapStore.storeAll() never called when objects updated with delay Feb 5, 2016

@ahmetmircik ahmetmircik self-assigned this Feb 15, 2016

@ahmetmircik

This comment has been minimized.

Copy link
Member

commented Feb 15, 2016

seems the reason behind storeAll split is member-count and it is expected in this situation, since every member handles its own data.

@dmitrymz

This comment has been minimized.

Copy link
Author

commented Feb 16, 2016

hmm. however, only one cluster node actually calls MapStore.storeAll(), isn't it?
if that's true, there is a consolidation of all updates within the cluster at this node - which make sense.
In my example above only one node calls storeAll() with split batches of updates

Because updates have to be done in intervals of write-delay-seconds. Otherwise, write-delay-seconds don't make sense if all the nodes start storing updates in their different intervals, invoking local MapStore.storeAll() at different times...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.