This discussion is archived
1 2 Previous Next 26 Replies Latest reply: Oct 9, 2012 6:29 PM by greybird RSS

Understanding LockTimeOutExceptions better

vinothchandar Newbie
Currently Being Moderated
Hi,

Background : We use BDB as the storage backend for Voldemort and we run on SSDs, and use a shared cache for multiple environments (upto 25 on a single server). Our writes to a txn with a RMW lock. We use duplicates, and hence use a transactional cursor to perform a get(), delete() , put() cycle. (I am working on making the duplicates go away though and we will be using a simple get put in a txn). Reads use UNCOMMITTED isolation. We don't have secondary indexes or anything.

What I am seeing is that there are heavy locktimeouts sometimes, which drives up the latency very high. Our locktimeout is 500ms. Considering we are SSDs, I would expect any operation to finish much quicker than 500 ms. For example, the following instance shows 10 waiters. Considering a 4 level tree and 1ms access time max for each Node fetch (data / index), all 10 waiters should have been granted access in under 40ms (just guessing).

[BdbStorageEngine] [voldemort-niosocket-server34] [voldemort] com.sleepycat.je.LockTimeoutException: (JE 4.0.92) Lock expired. Locker 1317118982 164639096_voldemort-niosocket-server34_Txn: waited for lock on database=message_sent_history LockAddr:265706381 node=170810678 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1348704310016 endTime=1348704310535
Owners: [<LockInfo locker="606847962 164639091_voldemort-niosocket-server44_Txn" type="WRITE"/>]
Waiters: [<LockInfo locker="893857731 164639092_voldemort-niosocket-server28_Txn" type="WRITE"/>, <LockInfo locker="1826240023 164639093_voldemort-niosocket-server1_Txn" type="WRITE"/>, <LockInfo locker="2142263792 164639094_voldemort-niosocket-server17_Txn" type="WRITE"/>, <LockInfo locker="1710362032 164639095_voldemort-niosocket-server33_Txn" type="WRITE"/>, <LockInfo locker="1317822219 164639098_voldemort-niosocket-server10_Txn" type="WRITE"/>, <LockInfo locker="153266016 164639099_voldemort-niosocket-server35_Txn" type="WRITE"/>, <LockInfo locker="861632969 164639101_voldemort-niosocket-server11_Txn" type="WRITE"/>, <LockInfo locker="1385676009 164639103_voldemort-niosocket-server31_Txn" type="WRITE"/>, <LockInfo locker="1744015195 164639104_voldemort-niosocket-server19_Txn" type="WRITE"/>, <LockInfo locker="1933099921 164639107_voldemort-niosocket-server32_Txn" type="WRITE"/>]

Or in other words, even locking on a node higher up the tree, should be resolved very soon right?

I know lowering the locktimeout could help. But would like to understand why we would get LockTimeoutExceptions in the first place?

Thanks
Vinoth
  • 1. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    Also, EnvironmentConfig.LOCK_N_LOCK_TABLES = 1

    Thanks
    Vinoth
  • 2. Re: Understanding LockTimeOutExceptions better
    greybird Expert
    Currently Being Moderated
    Hi Vinoth,

    There are two reasons for LockTimeoutException: 1) a true deadlock, which won't be resolved no matter how long the timeout, 2) a simple timeout due to contention, where the lock would eventually be granted if the timeout were increased.

    With (1), a true deadlock is caused by two txns that lock the same records but in a different order. It can't happen if each txn only locks a single record, or if txns always lock records in the same order. (With secondaries, deadlocks can happen due to different locking order for reads and writes, but you're not using secondaries.) With true deadlocks, decreasing the timeout is beneficial since waiting has no benefit. If it is not possible to change the order of record locking in the app, then retrying the operation is the only way to handle it.

    With (2), the most common cause is that the txn holds a lock for a long time period, while doing a large number of operations or other work, for example. This is one reason why short txns are always recommended. If the txns cannot be shortened, then increasing the timeout may be beneficial, since less retries will be needed.

    Since you are using duplicates and you're not on JE 5, my first guess is that you're running into the contention problem with duplicate counts; this is the problem that was one of the motivations for the rework of duplicates in JE 5. Pre-JE 5, every time you write to a record that has duplicates (more than one record with the same key), an internal record is also locked that contains the duplicate counter (number of records with the same key). Therefore, two transactions that write records with the same key cannot execute concurrently -- one will wait for the other. This won't cause deadlocks, but will decrease concurrency and could cause timeouts.

    But there is no way to know for certain what's happening in your particular situation without doing some debugging. First, if you send the full stack trace we can see whether the duplicate count is being locked. Second, there are instructions in the FAQ for enabling lock debugging; this will cause more info to be output in the exception message and tell us a lot more about what's happening.

    --mark                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           
  • 3. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    Hi Mark,

    I will try dumping more information and get back to you with the output.

    Coming to the points you mentioned. I am pretty sure 1) cannot happen for us since we just have one "type" of txn, which does a get(), delete() , put() using a cursor walk across the duplicates. 2) is also unlikely. Our transactions cannot span more than 3 operations max. So, again still not clear why it would contend for 500ms, given we are on SSDs and it will be really fast to read stuff in and release the lock for other threads. This really bothers me and any theories here would be really helpful.

    Also, some clarification about the semantics of the locktimeout parameter. Initially, I thought locktimeout is amount of time a thread tries to acquire the lock it needs. Ffrom the gettingstarted guide, it seems like, locktimeout is used by JE to 'timeout' transaction that did not make progress fast enough. So, is it possible somehow that JE delays the timeout longer due to the 500ms? I am asking to see if I can reduce the timeout and put in some retry since the doc says the application is expected to handle these exceptions and we don't as of now.

    Any comments about the locknlocktables parameter? I saw that we had misconfigured it to be 1 with close to 50 application threads. Would that affect anything?

    Thanks
    Vinoth
  • 4. Re: Understanding LockTimeOutExceptions better
    greybird Expert
    Currently Being Moderated
    Since neither a true deadlock nor a long txn make sense to you, the best thing is to collect the additional info from the deadlock debugging mode.

    Lock timeout is the time a thread waits for a lock. There is another timeout called txn timeout that you may be reading about -- it's not very useful IMO, not worth worrying about.

    Increasing the number of lock tables reduces contention on the latch used to access the lock information. That can help, and is worth doing, but I doubt the 500 ms are due to contention on that latch.

    --mark                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                   
  • 5. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    Just to confirm, adding

    je.txn.dumpLocks=true

    to je.properties will do, right?

    Thanks
    Vinoth
  • 6. Re: Understanding LockTimeOutExceptions better
    greybird Expert
    Currently Being Moderated
    That, plus this (from the FAQ):

    Stacktraces can be added to a deadlock message by setting the je.txn.deadlockStackTrace property through your je.properties file or EnvironmentConfig. This should only be set during debugging because of the added memory and processing cost.
  • 7. Re: Understanding LockTimeOutExceptions better
    909806 Newbie
    Currently Being Moderated
    Keep in mind that thread A giving up after 500ms waiting for a lock held by thread B, doesn't mean that thread B actually got 500ms of CPU time. You mentioned that you have 50 application threads. If the application is busy, it's possible that thread A can't acquire the lock after 500ms merely because thread B didn't get much processing time. I'm not sure if GC-ing could cause this.

    (I've seen evidence for this sort of thing in a similar case: I sometimes see InsufficientOperationalNodesException due to the Voldemort client being overloaded.)
  • 8. Re: Understanding LockTimeOutExceptions better
    greybird Expert
    Currently Being Moderated
    Good points, Jeff. Also, the fact that there are 12 threads contending for the same lock (1 timed out, 1 owner, 10 waiters) points to some sort of hot spot.
  • 9. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    I did consider GC, which would explain bursts of these activities. But, we have seen this sustain for a long time (over 10 minutes) where the average shoots up.

    I am pretty sure there is a hot spot. but what I still don't have a direct explanation for is, barring GC why should the lock expire in the first place? Is n't it just blocked on IO (which takes like 0.1ms on SSDs)?

    Let me work on the debug output and update the thread.

    @Jeff, the problem with client is different and is related to how connections are managed. We are fixing it. and its a vold issue entirely.

    Thanks
    Vinoth
  • 10. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    I have some data and it looks like the contention is solely on the LNs (there are < 1% on the dupcountLNs). The stacktrace looks like below.

    ERROR [BdbStorageEngine] [voldemort-niosocket-server14] [voldemort] com.sleepycat.je.LockTimeoutException: (JE 4.0.92) Lock expired. Locker 896966513 49182799_voldemort-niosocket-server14_Txn: waited for lock on database=store1 LockAddr:1192343845 node=39540893 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1349680844662 endTime=1349680845184
    Owners: [<LockInfo locker="1419571514 49182791_voldemort-niosocket-server38_Txn" type="WRITE"/> lock taken at: com.sleepycat.je.txn.LockInfo$StackTraceAtLockTime
    at com.sleepycat.je.txn.LockInfo.<init>(LockInfo.java:56)
    at com.sleepycat.je.txn.ThinLockImpl.lock(ThinLockImpl.java:113)
    at com.sleepycat.je.txn.LockManager.attemptLockInternal(LockManager.java:456)
    at com.sleepycat.je.txn.SyncedLockManager.attemptLock(SyncedLockManager.java:53)
    at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:288)
    at com.sleepycat.je.txn.LockManager.lock(LockManager.java:273)
    at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:474)
    at com.sleepycat.je.txn.Locker.nonBlockingLock(Locker.java:488)
    at com.sleepycat.je.dbi.CursorImpl.lockLNDeletedAllowed(CursorImpl.java:2548)
    at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2486)
    at com.sleepycat.je.dbi.CursorImpl.searchAndPosition(CursorImpl.java:2138)
    at com.sleepycat.je.Cursor.searchInternal(Cursor.java:2088)
    at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2058)
    at com.sleepycat.je.Cursor.search(Cursor.java:1926)
    at com.sleepycat.je.Cursor.getSearchKey(Cursor.java:1351)
    at voldemort.store.bdb.BdbStorageEngine.put(BdbStorageEngine.java:356)
    at voldemort.store.bdb.BdbStorageEngine.put(BdbStorageEngine.java:70)
    at voldemort.store.rebalancing.RedirectingStore.put(RedirectingStore.java:107)
    at voldemort.store.rebalancing.RedirectingStore.put(RedirectingStore.java:60)
    at voldemort.store.invalidmetadata.InvalidMetadataCheckingStore.put(InvalidMetadataCheckingStore.java:95)
    at voldemort.store.invalidmetadata.InvalidMetadataCheckingStore.put(InvalidMetadataCheckingStore.java:41)
    at voldemort.store.DelegatingStore.put(DelegatingStore.java:69)
    at voldemort.store.stats.StatTrackingStore.put(StatTrackingStore.java:128)
    at voldemort.store.stats.StatTrackingStore.put(StatTrackingStore.java:39)
    at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handlePut(VoldemortNativeRequestHandler.java:442)
    at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handleRequest(VoldemortNativeRequestHandler.java:69)
    at voldemort.server.niosocket.AsyncRequestHandler.read(AsyncRequestHandler.java:130)
    at voldemort.utils.SelectorManagerWorker.run(SelectorManagerWorker.java:98)
    at voldemort.utils.SelectorManager.run(SelectorManager.java:194)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
    ]
    Waiters: []


    Note that there are not even waiters in this stackdump. However, in other instances, there are other threads trying to write to the same key and they are blocked. But, I think the stack trace above isolates the problem. The db/env has around 300M cache, 3 cleaners. Does 600 gets/s 400 puts/s . small 10 byte values

    PS : We are testing out a new data format that does not use sortedDuplicates. That seems to be fine. So, may be its related to duplicates?
  • 11. Re: Understanding LockTimeOutExceptions better
    greybird Expert
    Currently Being Moderated
    Could you please post the rest of the stack trace? What you posted is just the exception message, which shows when the owner took the lock, but we aren't seeing where the requester (that timed out) got the exception.

    Thanks,
    --mark                                                                                                                                                                                                                                                                                                                                                                                                                                                                                       
  • 12. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    Hmmm. That was actually, all that it printed (I just added the two parameters mentioned above, in a je.properties under env dir and bounced the server). Anyways, pasting another exception, which shows some waiters.

    2012/10/08 00:35:29.246 ERROR [BdbStorageEngine] [voldemort-niosocket-server14] [voldemort] com.sleepycat.je.LockTim
    eoutException: (JE 4.0.92) Lock expired. Locker 1723973692 124031744_voldemort-niosocket-server14_Txn: waited for lo
    ck on database=store1 LockAddr:924552162 node=87042505 type=WRITE grant=WAIT_NEW timeo
    utMillis=500 startTime=1349656528721 endTime=1349656529221
    Owners: [<LockInfo locker="2146240204 124031745_voldemort-niosocket-server48_Txn" type="WRITE"/> lock taken at: com.
    sleepycat.je.txn.LockInfo$StackTraceAtLockTime
    at com.sleepycat.je.txn.LockInfo.<init>(LockInfo.java:56)
    at com.sleepycat.je.txn.LockImpl.lock(LockImpl.java:349)
    at com.sleepycat.je.txn.LockManager.attemptLockInternal(LockManager.java:456)
    at com.sleepycat.je.txn.SyncedLockManager.attemptLock(SyncedLockManager.java:53)
    at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:288)
    at com.sleepycat.je.txn.LockManager.lock(LockManager.java:273)
    at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:474)
    at com.sleepycat.je.txn.Locker.lock(Locker.java:454)
    at com.sleepycat.je.dbi.CursorImpl.lockLNDeletedAllowed(CursorImpl.java:2566)
    at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2486)
    at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2416)
    at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1418)
    at com.sleepycat.je.dbi.CursorImpl.getNextDuplicate(CursorImpl.java:1737)
    at com.sleepycat.je.Cursor.searchInternal(Cursor.java:2188)
    at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2058)
    at com.sleepycat.je.Cursor.search(Cursor.java:1926)
    at com.sleepycat.je.Cursor.getSearchKey(Cursor.java:1351)
    at voldemort.store.bdb.BdbStorageEngine.put(BdbStorageEngine.java:356)
    at voldemort.store.bdb.BdbStorageEngine.put(BdbStorageEngine.java:70)
    at voldemort.store.rebalancing.RedirectingStore.put(RedirectingStore.java:107)
    at voldemort.store.rebalancing.RedirectingStore.put(RedirectingStore.java:60)
    at voldemort.store.invalidmetadata.InvalidMetadataCheckingStore.put(InvalidMetadataCheckingStore.java:95)
    at voldemort.store.invalidmetadata.InvalidMetadataCheckingStore.put(InvalidMetadataCheckingStore.java:41)
    at voldemort.store.DelegatingStore.put(DelegatingStore.java:69)
    at voldemort.store.stats.StatTrackingStore.put(StatTrackingStore.java:128)
    at voldemort.store.stats.StatTrackingStore.put(StatTrackingStore.java:39)
    at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handlePut(VoldemortNativeRequestHandler.java:442)
    at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handleRequest(VoldemortNativeRequestHandler.java:69)
    at voldemort.server.niosocket.AsyncRequestHandler.read(AsyncRequestHandler.java:130)
    at voldemort.utils.SelectorManagerWorker.run(SelectorManagerWorker.java:98)
    at voldemort.utils.SelectorManager.run(SelectorManager.java:194)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
    ]
    Waiters: [<LockInfo locker="1183627277 124031746_voldemort-niosocket-server30_Txn" type="WRITE"/> lock taken at: com.sleepycat.je.txn.LockInfo$StackTraceAtLockTime
    at com.sleepycat.je.txn.LockInfo.<init>(LockInfo.java:56)
    at com.sleepycat.je.txn.LockImpl.lock(LockImpl.java:349)
    at com.sleepycat.je.txn.LockManager.attemptLockInternal(LockManager.java:456)
    at com.sleepycat.je.txn.SyncedLockManager.attemptLock(SyncedLockManager.java:53)
    at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:288)
    at com.sleepycat.je.txn.LockManager.lock(LockManager.java:273)
    at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:474)
    at com.sleepycat.je.txn.Locker.lock(Locker.java:454)
    at com.sleepycat.je.dbi.CursorImpl.lockLNDeletedAllowed(CursorImpl.java:2566)
    at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2486)
    at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2416)
    at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1418)
    at com.sleepycat.je.dbi.CursorImpl.getNextDuplicate(CursorImpl.java:1737)
    at com.sleepycat.je.Cursor.searchInternal(Cursor.java:2188)
    at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2058)
    at com.sleepycat.je.Cursor.search(Cursor.java:1926)
    at com.sleepycat.je.Cursor.getSearchKey(Cursor.java:1351)
    at voldemort.store.bdb.BdbStorageEngine.put(BdbStorageEngine.java:356)
    at voldemort.store.bdb.BdbStorageEngine.put(BdbStorageEngine.java:70)
    at voldemort.store.rebalancing.RedirectingStore.put(RedirectingStore.java:107)
    at voldemort.store.rebalancing.RedirectingStore.put(RedirectingStore.java:60)
    at voldemort.store.invalidmetadata.InvalidMetadataCheckingStore.put(InvalidMetadataCheckingStore.java:95)
    at voldemort.store.invalidmetadata.InvalidMetadataCheckingStore.put(InvalidMetadataCheckingStore.java:41)
    at voldemort.store.DelegatingStore.put(DelegatingStore.java:69)
    at voldemort.store.stats.StatTrackingStore.put(StatTrackingStore.java:128)
    at voldemort.store.stats.StatTrackingStore.put(StatTrackingStore.java:39)
    at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handlePut(VoldemortNativeRequestHandler.java:442)
    at voldemort.server.protocol.vold.VoldemortNativeRequestHandler.handleRequest(VoldemortNativeRequestHandler.java:69)
    at voldemort.server.niosocket.AsyncRequestHandler.read(AsyncRequestHandler.java:130)
    at voldemort.utils.SelectorManagerWorker.run(SelectorManagerWorker.java:98)
    at voldemort.utils.SelectorManager.run(SelectorManager.java:194)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:619)
    ]

    Hope this helps.
  • 13. Re: Understanding LockTimeOutExceptions better
    greybird Expert
    Currently Being Moderated
    That was actually, all that it printed
    Yes, this is all that will appear in the exception message. But what about the stack trace? Are you calling Exception.printStackTrace? Or just printing Exception.toString or getMessage? It would help to see the entire thing.

    The two cases you posted are completely different. Do you know which one is the common case?

    Yes, the second case is related to duplicates. Is this stack the common case?

    --mark                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               
  • 14. Re: Understanding LockTimeOutExceptions better
    vinothchandar Newbie
    Currently Being Moderated
    The second one is much more common. First one occurs ~10% of the time.

    As I mentioned, I just added a je.properties with the following.
    je.txn.dumpLocks=true
    je.txn.deadlockStackTrace=true

    I did not make any code changes for this. We just catch a DatabaseException and log it using log4j.
    https://github.com/voldemort/voldemort/blob/master/src/java/voldemort/store/bdb/BdbStorageEngine.java#L381

    I guess "com.sleepycat.je.LockTimeoutException: (JE 4.0.92) Lock expired. Locker 1723973692 124031744_voldemort-niosocket-server14_Txn: waited for lock on database=store1 LockAddr:924552162 node=87042505 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1349656528721 endTime=1349656529221" is the exception.toString() ?

    It might be hard to make code changes in production for this. But I can try reproducing this locally and send you more info if it would help

    Thanks Mark!

    - Vinoth
1 2 Previous Next

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points