RUNNABLE thread - has it moved?

Question

I'm investigating a high CPU usage issue we're experiencing with a Glassfish 3.1.2.2 hosted application running on Java 7

CPU usage will start to rise from 'normal' levels, around 5-10% to 100% over the course of 20 minutes then stay between 90-100 and not drop, a restart of the app restores normality.

The 2 excerpts below were taken from 2 thread dumps with 10 minutes between them.

Cross referencing the entire dump with visualvm CPU profiler snapshots shows there are around 10 threads executing this area of code which seem to have spent the entire time in the method seen below.

The entire stack (which is huge & abbreviated below) is the same from both thread dumps for all 10 threads apart from the locked object reference.

I'd like to know what is going on here. Including why has the locked object reference changed?

Is the code stuck in a loop or is there a lock somewhere?

thread dump 1

"http-thread-pool-8080(3)" - Thread t@112
   java.lang.Thread.State: RUNNABLE
    at java.lang.Throwable.fillInStackTrace(Native Method)
    at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
    - locked <2328e584> (a java.lang.InterruptedException)
    at java.lang.Throwable.<init>(Throwable.java:250)
    at java.lang.Exception.<init>(Exception.java:54)
    at java.lang.InterruptedException.<init>(InterruptedException.java:57)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1325)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.tryLock(ReentrantReadWriteLock.java:873)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.acquireLock(POAImpl.java:390)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.readLock(POAImpl.java:422)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.enter(POAImpl.java:1743)
    at com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.getServantWithPI(CorbaServerRequestDispatcherImpl.java:302)
    at com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:196)
    at com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1624)
    at com.sun.corba.ee.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:126)
    at com.sun.corba.ee.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:273)
    at com.sun.corba.ee.impl.protocol.CorbaClientDelegateImpl.is_a(CorbaClientDelegateImpl.java:395)
    at org.omg.CORBA.portable.ObjectImpl._is_a(ObjectImpl.java:130)
...

thread dump 2

"http-thread-pool-8080(3)" - Thread t@112
   java.lang.Thread.State: RUNNABLE
    at java.lang.Throwable.fillInStackTrace(Native Method)
    at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
    - locked <83c9c3a> (a java.lang.InterruptedException)
    at java.lang.Throwable.<init>(Throwable.java:250)
    at java.lang.Exception.<init>(Exception.java:54)
    at java.lang.InterruptedException.<init>(InterruptedException.java:57)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1325)
    at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.tryLock(ReentrantReadWriteLock.java:873)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.acquireLock(POAImpl.java:390)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.readLock(POAImpl.java:422)
    at com.sun.corba.ee.impl.oa.poa.POAImpl.enter(POAImpl.java:1743)
    at com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.getServantWithPI(CorbaServerRequestDispatcherImpl.java:302)
    at com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:196)
    at com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1624)
    at com.sun.corba.ee.impl.protocol.SharedCDRClientRequestDispatcherImpl.marshalingComplete(SharedCDRClientRequestDispatcherImpl.java:126)
    at com.sun.corba.ee.impl.protocol.CorbaClientDelegateImpl.invoke(CorbaClientDelegateImpl.java:273)
    at com.sun.corba.ee.impl.protocol.CorbaClientDelegateImpl.is_a(CorbaClientDelegateImpl.java:395)
    at org.omg.CORBA.portable.ObjectImpl._is_a(ObjectImpl.java:130)
...

UPDATE

This is the POAImpl acquireLock method that may be causing the issue...

private void acquireLock(Lock lock) {
        MethodMonitor __$mm$__ = (MethodMonitor)__$mm$__0.content();
        if (__$mm$__ != null) {
            __$mm$__.enter(1, new Object[]{lock});
        }

        try {
            long timeout = 1L;
            boolean locked = false;
            boolean interrupted = false;
            int count = 0;
            int reportingThreshhold = 1;

            while(!locked) {
                if (count >= reportingThreshhold) {
                    this.acquireLockWaiting(count, __$mm$__, 1);
                    if (reportingThreshhold < 1073741823) {
                        reportingThreshhold *= 2;
                    }
                }

                try {
                    locked = lock.tryLock(1L, TimeUnit.SECONDS);
                    ++count;
                } catch (InterruptedException var13) {
                    interrupted = true;
                }

                if (interrupted) {
                    Thread.currentThread().interrupt();
                }
            }

            if (__$mm$__ != null) {
                __$mm$__.exit(1);
            }

        } finally {
            if (__$mm$__ != null) {
                __$mm$__.exit(1);
            }

        }
    }

Answer 1

One option is that something like that happens in code:

public void doTheJob(){

     try{
       .... // fail fast for whatever reason
     }catch(Exception e){
        doTheJob();
     }
}

Exception occures - thats why we are seeing stacktracke. You got yourself an infinite loop.

What is very interesting is that there is an InterruptedException in the stacktrace, so it looks alike that you might try to kill some pending (timing out) tasks - and maybe reschedule them.

Answer 2

As for provided code. Its essentially doing something like this:

public static void main(String[] args) throws InterruptedException {
    ReentrantLock lock = new ReentrantLock();
    Thread t=new Thread(()->lock.lock()); //lets simulate that Lock is locked
    t.start();
    t.join();
    int times = 0;
    Thread.currentThread().interrupt(); //and for whatever reasons - thread was interrupted from outside
    boolean locked=false;
    while (!locked) {
        try {
            boolean gotLock=lock.tryLock(1, TimeUnit.SECONDS);
            System.out.println("Got lock?: "+gotLock);
        } catch (InterruptedException e) {
            System.out.println("Thrown times:" + times++);
            Thread.currentThread().interrupt(); // iterrupts again - will throw on getLock no matter what now
        }
    }
}

So basicly having interuption once - you will dive into limbo of infinite loop - without delays - which hogs the CPU. I would suggest adding diagnostic logging around that interuption handling to see what is happening.