yet another ObsoleteVersionException

[Eishay]

Hi,

I'm using voldemort 0.57 with six nodes and multiple stores.
The problematic store has:
<replication-factor>4</replication-factor> \
<required-reads>1</required-reads> \
<preferred-reads>1</preferred-reads> \
<preferred-writes>4</preferred-writes> \
<required-writes>2</required-writes> \
<retention-days>1</retention-days> \
Using String for key, protobuf for value.
Read time average is 2ms, using getAll with 1-10 keys. Happy with that
part.
Writing a fresh key/value (key that was never used) is 5ms.

There is a set of few thousand keys and they are being updated and
read all the time.
My cluster got into a state that when I'm trying to update an existing
key I'm getting something like:
============
voldemort.versioning.ObsoleteVersionException: Key 745f41444749 version
(1:14) is obsolete, it is no greater than the current version of
version(1:2404).
============

The voldemort log looks like this:
============
voldemort.store.routed.RoutedStore$3,Error in PUT on node 2(<snip>)
voldemort.versioning.ObsoleteVersionException: Key 745f41444749 version
(1:17) is obsolete, it is no greater than the current version of
version(1:2404).
...
Error in PUT on node 4(<snip>)
voldemort.versioning.ObsoleteVersionException: Key 745f41444749 version
(1:17) is obsolete, it is no greater than the current version of
version(1:2404).
... <after 15 sec>
voldemort.store.routed.RoutedStore,Timed out waiting for put # 3 of 3
to succeed.
============

The server's log looks clean when I'm doing the transaction but in
some point in time I got few BDB lock exceptions:
===========
Exception in thread "main"
voldemort.store.StorageInitializationException:
com.sleepycat.je.EnvironmentLockedException: (JE 3.3.82) A je.lck file
exists in <snip>/data/bd
b The environment can not be locked for single writer access.
at voldemort.store.bdb.BdbStorageConfiguration.getStore
(BdbStorageConfiguration.java:113)
at voldemort.server.storage.StorageService.getStorageEngine
(StorageService.java:311)
at voldemort.server.storage.StorageService.startInner
(StorageService.java:154)
at voldemort.server.AbstractService.start(AbstractService.java:
63)
at voldemort.server.VoldemortServer.startInner
(VoldemortServer.java:180)
at voldemort.server.AbstractService.start(AbstractService.java:
63)
at com.kaching.supermap.SuperMapServer.start
(SuperMapServer.java:119)
at com.kaching.supermap.SuperMapServer.main
(SuperMapServer.java:194)
Caused by: com.sleepycat.je.EnvironmentLockedException: (JE 3.3.82) A
je.lck file exists in <snip>/data/bdb The environment can not be
locked for single writer access.
at com.sleepycat.je.log.FileManager.lockEnvironment
(FileManager.java:1724)
at com.sleepycat.je.log.FileManager.<init>(FileManager.java:
260)
at com.sleepycat.je.dbi.EnvironmentImpl.<init>
(EnvironmentImpl.java:327)
at com.sleepycat.je.dbi.DbEnvPool.getEnvironment
(DbEnvPool.java:147)
at com.sleepycat.je.Environment.<init>(Environment.java:210)
at com.sleepycat.je.Environment.<init>(Environment.java:150)
at voldemort.store.bdb.BdbStorageConfiguration.getEnvironment
(BdbStorageConfiguration.java:143)
at voldemort.store.bdb.BdbStorageConfiguration.getStore
(BdbStorageConfiguration.java:101)
===========

Any ideas of how to approach it?

[Jay Kreps]

Hey Eishay,

Sorry for the delay, catching up on email.

The lock exception indicates that a writer thread failed to obtain the
lock in a given period of time. This can happen naturally if too many
slow writes occur simultaneously, but it is usually not a problem. One
issue we had was overaggressive locking in previous version of v.
where we acquired a write lock even when reading, which exacerbated
the problem. We fixed this so upgrading will likely ameliorate the
lock timeout issue.

I don't think the obsolete version exception is related to the lock
timeout. An exception about an obsolete version is usually an
application level error--two threads trying to simultaneously
overwrite the same value, loser gets an exception rather than
clobbering the new value, which is the right behavior. However, your
exception gives the version of the write as 17, but the version of the
value in the store as 2404, and it seems unlikely that 2404 - 17
updates occurred in between the read and the update (right?). You
aren't somehow manually setting the version are you?

One suspicion I had was that maybe there was some way that we could
incorrectly deserialize the version number. I tried to reproduce it
with the following test VectorClock.testIncrementAndSerialize():

public void testIncrementAndSerialize() {
int node = 1;
VectorClock vc = getClock(node);
assertEquals(node, vc.getMaxVersion());
int increments = 3000;
for(int i = 0; i < increments; i++) {
vc.incrementVersion(node, 45);
// serialize
vc = new VectorClock(vc.toBytes());
}
assertEquals(increments + 1, vc.getMaxVersion());
}

However this test passes. So I am a bit mystified.

-Jay

> --
>
> You received this message because you are subscribed to the Google Groups "project-voldemort" group.
> To post to this group, send email to project-...@googlegroups.com.
> To unsubscribe from this group, send email to project-voldem...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/project-voldemort?hl=en.
>
>
>

[Eishay Smith]

Thanks Jay, hope you enjoined the vacation :-)

To clarify, I am replicating the errors in a single threaded environment (using Scala REPL ;-) so the error is not related to concurrency.
The issue is reliably repeatable and I can't use my production cluster because of that, very bad to me.

It happens with only a subset of the keys I have in the DB (about 10% of them), I don't know of anything special with these keys.
Example for one of the keys on the client side:
scala>  val ticker = tfClient get "t_NDAQ" ; tfClient put ("t_NDAQ", ticker)
version(3:314)
voldemort.versioning.ObsoleteVersionException: Key 745f4e444151 version(3:315) is obsolete, it is no greater than the current version of version(1:3, 3:445).

So I'm getting version(3:314), trying to set version(3:315) and you see the exception.
The class of ticker is not Voldemort Version but version.getValue.

Any ideas?
Thanks, Eishay

[Jay Kreps]

Hmm, I am a bit useless here as I can't really reproduce this. Two
things would help, I think
1. Can you put a debug in the shell and see where the 315 comes from?
I.e. is it really the case that the client gets 315 or does that get
garbled somewhere...
2. Can you enable trace logging on voldemort.store.routed for the
shell and see which versions are returned from which nodes (should log
something like "GET retrieved the following values: ...").

-Jay

[Eishay Smith]

You know where I am, we're paying house visits with lunch in one of the Palo Alto restaurants, but I'll come over if you think it will help.

The run:
scala>  val n = tfClient get "t_NDAQ" ; tfClient put ("t_NDAQ", n)
Result:
for the get => version(3:353)
for the put => ObsoleteVersionException: Key 745f4e444151 version(3:354) is obsolete, it is no greater than the current version of version(1:3, 3:445).
Log (remove stack traces):
[voldemort-client-thread-1] 20100105144528,TRACE,voldemort.store.routed.RoutedStore$GetCallable,Attempting get operation on node 3 for key '745f4e444151'.
[voldemort-client-thread-1] 20100105144529,DEBUG,voldemort.store.socket.SocketResourceFactory,Created socket 2 for <server>30<domain>:9103 using protocol vp1
[voldemort-client-thread-1] 20100105144529,DEBUG,voldemort.store.logging.LoggingStore,: GET operation on store 'tf-quotes' completed successfully in 30.584901 ms.
[main] 20100105144529,TRACE,voldemort.store.routed.RoutedStore,GET retrieved the following node values: {NodeValue(id=3, key=[116, 95, 78, 68, 65, 81], versioned= [[B@e1f52a, version(3:353)]), }
[voldemort-client-thread-2] 20100105144529,TRACE,voldemort.store.routed.RoutedStore$GetCallable,Attempting get operation on node 3 for key '745f4e444151'.
[voldemort-client-thread-2] 20100105144529,DEBUG,voldemort.store.logging.LoggingStore,: GET operation on store 'tf-quotes' completed successfully in 13.449252 ms.
[main] 20100105144529,TRACE,voldemort.store.routed.RoutedStore,GET retrieved the following node values: {NodeValue(id=3, key=[116, 95, 78, 68, 65, 81], versioned= [[B@ed5b2, version(3:353)]), }
[main] 20100105144529,DEBUG,voldemort.store.logging.LoggingStore,: PUT operation on store 'tf-quotes' completed successfully in 1.244408 ms.
[voldemort-client-thread-3] 20100105144529,DEBUG,voldemort.store.socket.SocketResourceFactory,Created socket 3 for <server>14<domain>:9103 using protocol vp1
[voldemort-client-thread-5] 20100105144529,DEBUG,voldemort.store.socket.SocketResourceFactory,Created socket 4 for <server>8<domain>:9103 using protocol vp1
[voldemort-client-thread-3] 20100105144529,DEBUG,voldemort.store.logging.LoggingStore,: PUT operation on store 'tf-quotes' completed unsuccessfully in 53.189582 ms.
[voldemort-client-thread-3] 20100105144529,WARN,voldemort.store.routed.RoutedStore$3,Error in PUT on node 1(<server>14<domain>)
voldemort.versioning.ObsoleteVersionException: Key 745f4e444151 version(3:354) is obsolete, it is no greater than the current version of version(1:3, 3:445).
[voldemort-client-thread-4] 20100105144529,DEBUG,voldemort.store.logging.LoggingStore,: PUT operation on store 'tf-quotes' completed unsuccessfully in 57.626634 ms.
[voldemort-client-thread-4] 20100105144529,WARN,voldemort.store.routed.RoutedStore$3,Error in PUT on node 2(<server>29<domain>)
voldemort.versioning.ObsoleteVersionException: Key 745f4e444151 version(3:354) is obsolete, it is no greater than the current version of version(1:3, 3:445).
[voldemort-client-thread-5] 20100105144529,DEBUG,voldemort.store.logging.LoggingStore,: PUT operation on store 'tf-quotes' completed unsuccessfully in 57.411697 ms.
[voldemort-client-thread-5] 20100105144529,WARN,voldemort.store.routed.RoutedStore$3,Error in PUT on node 5(<server>8<domain>)
voldemort.versioning.ObsoleteVersionException: Key 745f4e444151 version(3:354) is obsolete, it is no greater than the current version of version(1:3, 3:445).
[main] 20100105144544,WARN,voldemort.store.routed.RoutedStore,Timed out waiting for put # 3 of 3 to succeed.

Thanks!
Eishay

[Jay Kreps]

How many reads are you doing? It looks like the problem is that the
master node has a version less than the other nodes and the version
does not get repaired on read since you are doing only a single read.

[Eishay Smith]

The configs are:

   <replication-factor>4</replication-factor> \

   <required-reads>1</required-reads> \
   <preferred-reads>1</preferred-reads> \
   <preferred-writes>4</preferred-writes> \
   <required-writes>2</required-writes> \
   <retention-days>1</retention-days> \

Since I want it to be highly available for reads and highly reliable for writes.
Does it make sense? Do you think it leads to the bad state I'm in?

If this configuration (does in my case) lead to bad state like this, should it be allowed ?
Should we at least have a very nasty working about it ?

Thanks, Eishay

[Jay Kreps]

Yeah I agree it is a deeper problem we should handle better. I think
Ismael ran into this as well. The issue is that if you have reads=1
and you actually lose writes on one machine then there is no repair
mechanism for those lost writes. In the short term I think you can
just set reads=2, but we really need one of the offline repair
mechanisms in a production-ready state so we don't have this issue.

-Jay

[Eishay Smith]

Great, at least I'll be able to keep on going. I'll updates on the findings.
Thanks,
Eishay

[Eishay Smith]

Yes, looks like it fixed it.
Thanks again,
Eishay

[ijuma]

On Jan 6, 8:58 pm, Jay Kreps <jay.kr...@gmail.com> wrote:
> Yeah I agree it is a deeper problem we should handle better. I think
> Ismael ran into this as well. The issue is that if you have reads=1
> and you actually lose writes on one machine then there is no repair
> mechanism for those lost writes. In the short term I think you can
> just set reads=2, but we really need one of the offline repair
> mechanisms in a production-ready state so we don't have this issue.

Indeed. I've been using preferred reads = 2 since then to avoid such
problems.

Ismael