Perplexing behavior working with ReentrantReadWriteLock

[Aron Daburn]

I am trying to use ReentrantReadWriteLock. I am getting some strange behavior that I can not figure out what is going on or how to remedy it.

The basic psudo code is as follows:

getToken()
{
  ReentrantReadWriteLock lock = new ReentrantReadWriteLock();
  
  if (requestLimitReached)
  {
    try
    {
      lock.writeLock().lock();
      reinit();
    }
    finally
    {
      lock.writeLock().unlock();
    } 
  }
  try
  {
    // log("Thread[" + + "] getting lock");   <-- Line in question
    lock.readLock().lock();
    getRequest();
  }
  finally
  {
    lock.readLock().unlock();
  }
}

The code seemed to be running serially, with one thread entering the getRequest() at a time. I then added logging (basically a System.out.println) to try to debug where the unnecessary locking was occurring. When I added the debug line, it worked properly... ?

When I run the above with the log line commented out, it appears to run in a serial manner, as if getting the read lock locked out another thread from getting the read lock. When I uncomment the log line (have it log) it then works and all threads run the getRequest simultaneously. How could adding in the log line possibly effect the process!?


Output without the log line:
START TIME RTS| START INITIALIZATION : 1267116081402
RTS| DONE INITIALIZATION (0) : 2062
RTS| START GET VALUES : 0
Thread[9] GetValue
RTS| START GET VALUES : 0
RTS| START GET VALUES : 0
RTS| START GET VALUES : 0
RTS| START GET VALUES : 0
Thread[9] DoneGetValue
Thread[8] GetValue
RTS| DONE GET VALUES : 579
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[8] DoneGetValue
Thread[10] GetValue
RTS| DONE GET VALUES : 593
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[10] DoneGetValue
RTS| DONE GET VALUES : 594
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[11] GetValue
Thread[11] DoneGetValue
Thread[7] GetValue
RTS| DONE GET VALUES : 594
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[7] DoneGetValue
RTS| DONE GET VALUES : 781
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;


Output with the log line (desired behavior):
START TIME RTS| START INITIALIZATION : 1267116802941
RTS| DONE INITIALIZATION (0) : 2266
RTS| START GET VALUES : 31
Thread[10] Getting READ lock
Thread[10] GetValue
RTS| START GET VALUES : 0
RTS| START GET VALUES : 0
RTS| START GET VALUES : 0
RTS| START GET VALUES : 0
Thread[10] DoneGetValue
RTS| DONE GET VALUES : 750
RTS| DONE PROCESSING VALUES : 0
Thread[11] Getting READ lock
Thread[8] Getting READ lock
Thread[7] Getting READ lock
Thread[9] Getting READ lock
test: 1;0001118143060001=1111234567000001;
Thread[11] GetValue
Thread[7] GetValue
Thread[8] GetValue
Thread[9] GetValue

Thread[8] DoneGetValue
RTS| DONE GET VALUES : 797
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[7] DoneGetValue
RTS| DONE GET VALUES : 47
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[9] DoneGetValue
RTS| DONE GET VALUES : 31
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

Thread[11] DoneGetValue
RTS| DONE GET VALUES : 2031
RTS| DONE PROCESSING VALUES : 0
test: 1;0001118143060001=1111234567000001;

[Aron Daburn]

Note: When I add

Thread.sleep(20);

right before getting the lock

Thread.sleep(20);
lock.readLock().lock();

it works fine.


What is going on requiring a pause prior to getting the read lock? Am I not implementing ReentrantReadWriteLock properly?

How could this effect the behavior of getting the readLock? I'm at a loss here. Can I rely on this Thread.sleep() to always work? How do I respond when this goes through code review and am asked why the sleep is there? "Uh, it just made it work"