Sometimes you may see reports in Rhino logs of lock timeouts. For example this may happen under load. The log messages refer to a lock ID. The lock ID contains potentially useful information about the resource Rhino is attempting to lock.
This how-to guide explains how you can decode these lock IDs and relate them to what your application is doing. This is potentially helpful for tuning your application and detecting lock contention.
Application-level (not language-level) locks The locks this guide discusses are application-level locks, which Rhino (2.0 and previous versions) uses to control access to transactional SLEE state. These locks are not related to Java's language-level locks (synchronized) or java.util.concurrent.locks library.
Compare to normal locking activity Locks should only time out as a consequence of an exceptional situation (such as overloading). To see Rhino's normal locking activity, enable debugging for the "memdb.lockmanager" log key:
rhino-console setloglevel memdb.lockmanager DEBUG
This will generate a lot of log output, so only enable it when testing at low call rates.
Investigating distributed locks
Applications need distributed locks when accessing replicated state. These have an inherent cost, because they force Rhino to communicate with other cluster nodes. You can easily see the distributed locks your applications have acquired, by searching the memdb.lockmanager logs for the string "Sending LOCK_ACQUIRE". Here's an example log message:
Rhino writes these particular log messages to the memdb.lockmanager logger when Rhino sends a network message to acquire a distributed lock for the first time in a transaction. By examining these log messages, you can build up a picture of which transactions are acquiring which locks.
Note the hex digits inside "StateKey[...]" — this is a string representation of a byte array. Often this contains an encoded ASCII string that can be decoded easily (for example, with a perl script), to identify the resource that was being locked. (You can ignore the ":" characters between some digits — Rhino just formats these values using colons to make them easier to read.)
Spotting the resource code You can spot the string that identifies the locked resource, encoded in a lock ID, by looking for the byte "01" followed by a 2-byte (short) length in hex. For example: "001f" (31). The remaining bytes are the ASCII characters of the string.
Common Lock ID Types
Below are descriptions, examples, and decoded strings or explanations for the four most common types of lock IDs that Rhino users encounter:
There are other types of lock ID, but these are the ones directly under your control
If you come across a lock that you can't decode, post a question in our Forums — we will tell you what it's used for.
When Rhino delivers an event to an SBB it first acquires the entity tree lock (a lock on the SBB's convergence name) for that SBB entity. This is the first lock acquired by Rhino in an event-processing transaction.
You can tell this is a convergence name by the number of colon characters (sometimes these will have values between them). Rhino just constructs convergence names this way — by concatenating all selected convergence name variables together, with colons in between.
This example is a custom convergence name, based on a SIP Call-ID. Other types of convergence names will have different values, but the signature is the presence of many colons.
Activity context name
When an SBB uses the ActivityContextNamingFacility
to bind, unbind or lookup a named ActivityContext, Rhino acquires a lock on the name. The lock ID is just the encoded ActivityContext name.
This example is an identifier that might be used as an ActivityContext name.
Lock IDs that just contain a string, as in the above examples, are either a convergence name or an ActivityContext name lock.
When an SBB accesses private attributes on an activity context, and Rhino is using the "pessimistic-per-activity" lock strategy, it acquires a lock using this type of lock ID.
This ID contains three 4-byte integer values (0x00000065, 0000005e, 0x47d5be0f) followed by a zero-length string (0x010000). The three integers are a unique activity key that Rhino uses internally. The first integer is the node ID, in this case 0x00000065 (101), which is easy to spot.
When an SBB accesses private attributes on an activity context, and Rhino is using a pessimistic lock strategy for ACI attributes, it acquires a lock using this type of lock ID.