Odd putback when a cluster is restarted, resulting in double stores

kjko...@gmail.com

unread,

Oct 28, 2013, 5:29:02 PM10/28/13

to haze...@googlegroups.com

Dear All,

I have observed some odd behaviour during development. When I do a full cluster restart and then clear a map, data gets stored twice via the associated map store I implemented. This leads to (in my case) duplicate keys on the database.

Restarting a single node in the cluster does not lead to this behaviour. It only happens when I shut down all nodes and then bring the cluster back.

Steps to reproduce:

1) have a map with an associated mapstore that writes all values into a MySQL database using the map key as primary key on the database.

2) put some data in the map, observe the data persisted in the database.

3) Stop all nodes in the cluster until none are running.

4) Start all nodes in the cluster.

5) Call map.clear() on the map: observe duplicate key exceptions as the map entries are loaded and stored in the database in seemingly random order.

I am not 100% sure that it is necessary to call map.clear() to trigger this behaviour, but that is my use case. ;)

When I trace the behaviour I see the following calls on the map store (lines with … indicate dozens of repeats of the line before it):

XXX UUID loadAllKeys()

(system is now idle, and I use a JSP to call map.clear())

XXX UUID loadAll({})

...

XXX UUID loadAll({})

XXX UUID deleteAll({})

...

XXX UUID deleteAll({})

XXX UUID store(45e9209e-04a8-4f21-bf8b-d8170e1b4b0d, ...)

XXX UUID deleteAll({})

...

XXX UUID deleteAll({})

XXX MAP clear(...)

XXX UUID loadAll({a4a9a11f-25d0-43b7-bd48-8542c317d54e,d075b5fa-4007-410a-a67b-f7c11fa62813})

XXX UUID loadAll({})

...

XXX UUID loadAll({})

XXX UUID loadAll({8fe6bee0-1d52-49eb-9795-9f0a6a24e6bb})

XXX UUID loadAll({1be66882-c278-42aa-923f-72c30de4b8d8,b6903f8e-2f91-4109-8014-99a28deb6155})

XXX UUID loadAll({73d5eeb8-c32b-4ff8-bb54-bd115098bbc9})

XXX UUID loadAll({b3523fdc-5a85-4e2f-9863-20f56e71ea1a})

XXX UUID loadAll({})

XXX UUID loadAll({6ec5684a-f1cd-437e-8487-e9fbde2369ba})

XXX UUID loadAll({1effbb93-2df3-409c-9d89-aa06b675b58c})

XXX UUID loadAll({})

…

XXX UUID loadAll({c702d12e-4117-488c-98e4-4563e572e85a})

XXX UUID store(1da27a60-4e77-4ba4-95c8-231d31c84667, ...)

...

Note that even though I do not actually change the contents of the map, the map still calls store(…) on its values as the data is being brought in from the database. Then once we get to the stage where the map is being cleared (after the XXX MAP clear(…) call), loading and storing just keeps happening for a while.

A typical SQL exception looks like this:

20131028 220635,466 org.kjkoster.foo mysql.RWDataSource ERROR - SQL error: Duplicate entry '45e9209e-04a8-4f21-bf8b-d8170e1b4b0d' for key 'PRIMARY' caused by: INSERT INTO stadium (uuid, name) VALUES (?,?)

Oct 28, 2013 10:06:35 PM com.hazelcast.map.operation.PutAllBackupOperation

SEVERE: [185.18.11.26]:5701 [dev] Duplicate entry '45e9209e-04a8-4f21-bf8b-d8170e1b4b0d' for key 'PRIMARY'

com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '45e9209e-04a8-4f21-bf8b-d8170e1b4b0d' for key 'PRIMARY'

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

at java.lang.reflect.Constructor.newInstance(Constructor.java:526)

at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)

at com.mysql.jdbc.Util.getInstance(Util.java:386)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1040)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4096)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4028)

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)

at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2458)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2375)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2359)

at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)

at org.kjkoster.foo.mysql.RWDataSource.insert(RWDataSource.java:47)

at org.kjkoster.foo.entities.Stadium$1.insert(Stadium.java:87)

at org.kjkoster.foo.entities.Stadium$1.insert(Stadium.java:1)

at org.kjkoster.foo.mysql.UUIDObjectStore.store(UUIDObjectStore.java:122)

at org.kjkoster.foo.mysql.UUIDObjectStore.store(UUIDObjectStore.java:1)

at com.hazelcast.map.MapStoreWrapper.store(MapStoreWrapper.java:87)

at com.hazelcast.map.DefaultRecordStore.mapStoreWrite(DefaultRecordStore.java:848)

at com.hazelcast.map.DefaultRecordStore.set(DefaultRecordStore.java:645)

at com.hazelcast.map.operation.PutAllBackupOperation.run(PutAllBackupOperation.java:48)

at com.hazelcast.spi.impl.OperationServiceImpl.doRunOperation(OperationServiceImpl.java:274)

at com.hazelcast.spi.impl.OperationServiceImpl.runOperation(OperationServiceImpl.java:184)

at com.hazelcast.spi.impl.Backup.run(Backup.java:87)

at com.hazelcast.spi.impl.OperationServiceImpl.doRunOperation(OperationServiceImpl.java:274)

at com.hazelcast.spi.impl.OperationServiceImpl.access$800(OperationServiceImpl.java:52)

at com.hazelcast.spi.impl.OperationServiceImpl$RemoteOperationProcessor.run(OperationServiceImpl.java:744)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

at java.lang.Thread.run(Thread.java:724)

at com.hazelcast.spi.impl.OperationServiceImpl$OperationThread.run(OperationServiceImpl.java:791)

Kees Jan

PS. And yes, it makes sense to persist the data and then call map.clear() as it's brought back in, because the clear happens only when I reset the system manually just after a restart, so my use-case is fine ok? :)

PPS. Why is XXX UUID loadAllKeys() called three times on startup? I only have one map.

Ali Gürbüz

unread,

Oct 28, 2013, 6:38:22 PM10/28/13

to haze...@googlegroups.com

and which version of hazel cast do you use?

--
You received this message because you are subscribed to the Google Groups "Hazelcast" group.
To unsubscribe from this group and stop receiving emails from it, send an email to hazelcast+...@googlegroups.com.
To post to this group, send email to haze...@googlegroups.com.
Visit this group at http://groups.google.com/group/hazelcast.
For more options, visit https://groups.google.com/groups/opt_out.

kjko...@gmail.com

unread,

Oct 29, 2013, 7:23:15 AM10/29/13

to haze...@googlegroups.com

Dear All,

Ugh, I botched the traces in the report. I was actually tracing more than one map when I thought I was tracing only a single map.

Sorry to cause confusion.

Here is a trace that is proper, taken using Hazelcast 3.1. This only traces a single map (really this time) and its associated store. Note that the store is initiated without any call to map.put(). I only call map.clear(). Again, this only happens after a fresh restart of the cluster.

XXX org.kjkoster.foo.mysql.CopyOfUUIDObjectStore.loadAllKeys()

XXX com.hazelcast.map.proxy.MapProxyImpl.clear(...)