Recent Changes - Search:

edit SideBar

Notes about notifyAll() in DEDirector

We started getting IllegalMonitorStateException when calling DEDirector.fireAt(). Below are details.

Replication from the command line

cd ptolemy/actor/lib/jjs/modules/socket/test/junit
make

Messages like the following will appear:

----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
Dec 24, 2015 12:08:00 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3
2505 ms. Memory: 549888K Free: 198591K (36%)
reloadAllAccessors: .Message3

Note that the problem does not occur when running make in ptolemy/actor/lib/jjs/modules/socket/test/, it only occurs when running in ptolemy/actor/lib/jjs/modules/socket/test/junit.

Replicating In Eclipse

Start a new Java Application configuration

  • Man tab:
    • Project: ptII
    • Main class: org.junit.runner.JUnitCore
  • Arguments tab:
    • Program Arguments: ptolemy.actor.lib.jjs.modules.socket.test.junit.JUnitTclTest
    • Working Directory. Check Other and fill in: ${workspace_loc:ptII}/ptolemy/actor/lib/jjs/modules/socket/test

Edit DEDirector and change:

            _eventQueue.notifyAll();
        }
        return result;
to

         try {
                _eventQueue.notifyAll();
            } catch (IllegalMonitorStateException ex) {
                throw ex;
            }
        }
        return result;

and set a breakpoint at the throw ex; line

Below is the stack trace that I get:

junit jjs socket [Java Application]    
        org.junit.runner.JUnitCore at localhost:54100  
                Thread [main] (Running)
                Daemon Thread [vertx-blocked-thread-checker] (Running) 
                Thread [vert.x-eventloop-thread-1] (Suspended (breakpoint at line 685 in DEDirector))  
                        owns: DECQEventQueue  (id=337) 
                        owns: NetSocketImpl  (id=338)  
                        DEDirector.fireAt(Actor, Time, int) line: 685  
                        DEDirector.fireAt(Actor, Time) line: 562       
                        DEDirector.fireAtCurrentTime(Actor) line: 711  
                        JavaScript.invokeCallback(Runnable) line: 1264 
                        SocketHelper(HelperBase)._issueResponse(Runnable) line: 177    
                        SocketHelper.access$1(SocketHelper, Runnable) line: 1  
                        SocketHelper$SocketWrapper.lambda$4(Void) line: 491    
                        1050898636.handle(Object) line: not available  
                        NetSocketImpl(ConnectionBase).handleClosed() line: 175 
                        NetSocketImpl.handleClosed() line: 287 
                        169939665.run() line: not available    
                        EventLoopContext(ContextImpl).lambda$wrapTask$61(boolean, ContextTask, Handler) line: 333      
                        1440459972.run() line: not available   
                        EventLoopContext(ContextImpl).executeFromIO(ContextTask) line: 225     
                        VertxNetHandler(VertxHandler<C>).channelInactive(ChannelHandlerContext) line: 99       
                        DefaultChannelHandlerContext(AbstractChannelHandlerContext).invokeChannelInactive() line: 208  
                        DefaultChannelPipeline$HeadContext(AbstractChannelHandlerContext).fireChannelInactive() line: 194      
                        DefaultChannelPipeline.fireChannelInactive() line: 828 
                        AbstractChannel$AbstractUnsafe$7.run() line: 621       
                        NioEventLoop(SingleThreadEventExecutor).runAllTasks(long) line: 358    
                        NioEventLoop.run() line: 357   
                        SingleThreadEventExecutor$2.run() line: 112    
                        VertxThread(Thread).run() line: 745    
                Thread [vert.x-eventloop-thread-0] (Running)   
                Thread [vert.x-eventloop-thread-3] (Running)   
                Thread [vert.x-eventloop-thread-2] (Running)   
                Daemon Thread [threadDeathWatcher-2-1] (Running)       
                Thread [vert.x-eventloop-thread-9] (Running)   
                Thread [vert.x-eventloop-thread-8] (Running)   
                Thread [vert.x-eventloop-thread-10] (Running)  
                Thread [vert.x-eventloop-thread-11] (Running)  
                Thread [Thread-16] (Running)   
                Thread [vert.x-eventloop-thread-15] (Running)  
        /Library/Java/JavaVirtualMachines/jdk1.8.0_65.jdk/Contents/Home/bin/java (Dec 24, 2015, 10:02:40 AM)   

FindBugs notifyAll() Warning

FindBugs does complain about notifyAll() at that location:

DEDirector.java:682, MWN_MISMATCHED_NOTIFY, Priority: Normal

MWN: Mismatched notify() in ptolemy.domains.de.kernel.DEDirector.fireAt(Actor, Time, int)

This method calls Object.notify() or Object.notifyAll() without obviously holding a lock on the object. Calling notify() or notifyAll() without a lock held will result in an IllegalMonitorStateException being thrown.

The call to notifyAll() appears in DEDirector.fireAt():

        synchronized (_eventQueue) {
            if (!_delegateFireAt) {
                // If we have not made a request to the executive director,                                                              
                // then we can modify time here. If we have, then we can't,                                                              
                // but if the time of that request is now in the past,                                                                  
                // we will throw an exception with an attempt to post                                                                    
                // an event in the past.                                                                                                
                if (result.compareTo(getModelTime()) < 0) {
                    // NOTE: There is no assurance in a multithreaded situation                                                          
                    // that time will not advance prior to the posting of                                                                
                    // this returned time on the local event queue, so                                                                  
                    // an exception can still occur reporting an attempt                                                                
                    // to post an event in the past.                                                                                    
                    result = getModelTime();
                }
            }
            if (result.compareTo(getModelTime()) == 0 && index <= _microstep
                    && !_isInitializing) {
                // NOTE: Incrementing the microstep here is wrong if we are in initialize().                                            
                index = _microstep + 1;

                if (index == Integer.MAX_VALUE) {
                    throw new IllegalActionException(
                            this,
                            actor,
                            "Microstep has hit the maximum while scheduling a firing of "
                                    + actor.getFullName()
                                    + ". Perhaps the model has a stuttering Zeno Condition?");
                }
            }

            _enqueueEvent(actor, result, index);

            // Findbugs: Multithreaded correctness,                                                                                      
            // [M M MWN] Mismatched notify() [MWN_MISMATCHED_NOTIFY]                                                                    
            //    This method calls Object.notify() or Object.notifyAll()                                                                
            //    without obviously holding a lock on the object.                                                                        
            //    Calling notify() or notifyAll() without a lock                                                                        
            //    held will result in an IllegalMonitorStateException                                                                    
            //    being thrown.                                                                                                          
            // Actually, this seems to be Find Bugs error since the                                                                      
            // statement is within a synchronized (_eventQueue) block.
 ------>    _eventQueue.notifyAll();
        }
        return result;
    }
 

The call to _enqueueEvent(actor, result, index); also does:

        synchronized (_eventQueue) {
            _eventQueue.put(newEvent);
        }

So, fireAt() gets the lock, then calls _enqueueEvent() which also gets the lock.

Coverity Scan Warnings

Summary: Checking the Coverity Scan Warnings at http://scan.coverity.com shows two other warnings for DEDirector, but they are probably not relevant.

Details: There are two warnings

One warning is:

 CID 1250909 (#1 of 1): Unguarded write (GUARDED_BY_VIOLATION)63. missing_lock: Accessing _exceedStopTime without holding lock DEDirector._eventQueue. lsewhere, "ptolemy.domains.de.kernel.DEDirector._exceedStopTime" is accessed with DEDirector._eventQueue held 3 out of 4 times.

The offending line in DEDirector._getNextActorToFire() is marked below:

                // Exceeding stop time means the current time is strictly                                                                
                // bigger than the model stop time.                                                                                      
                if (currentTime.compareTo(getModelStopTime()) > 0) {
                    if (_debugging) {
                        _debug("Current time has passed the stop time.");
                    }

------>            _exceedStopTime = true;
                    return null;
                }

_getNextActorToFire() is called at the top of fire(), so this is probably not the issue.

Another Coverity Scan warning is:

  CID 1250851 (#1 of 1): Check of thread-shared field evades lock acquisition (LOCK_EVASION)9. thread1_overwrites_value_in_field: Thread1 sets _microstep to a new value. Now the two threads have an inconsistent view of _microstep and updates to fields correlated with _microstep may be lost.

The above also occurs in _getNextActorToFire(), so it is probably also not the issue here.

JUnit

Oddly, running make in ptolemy/actor/lib/jjs/modules/socket/test does not cause the problem,

but running make in in ptolemy/actor/lib/jjs/modules/socket/test/junit does.

Summary: The problem occurs with the second junit run of Message2.xml Message3.xml, Socket3.xml

Details below.

JUnit Failure #1

A typical failure is

----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
Dec 24, 2015 12:08:00 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3
2505 ms. Memory: 549888K Free: 198591K (36%)
reloadAllAccessors: .Message3

JUnit Failure #2

.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Socket3.xml
Client: Discarding because socket is not open: a
3441 ms. Memory: 821760K Free: 470260K (57%)
----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Socket3.xml
Dec 23, 2015 12:44:49 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Discarding because socket is not open: a
3500 ms. Memory: 821760K Free: 267336K (33%)
reloadAllAccessors: .Socket3
.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/SocketByte.xml
Client: Sending data: -1,0,1,128,256
Client3: Sending data: 127
2751 ms. Memory: 827904K Free: 258013K (31%)
 

JUnit Failure #3

----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message2.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5
2580 ms. Memory: 411136K Free: 370859K (90%)
----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message2.xml
Dec 23, 2015 12:51:26 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Sending data: 5,1,2,3
Client: Sending data: 4,5
2573 ms. Memory: 413184K Free: 362581K (88%)
reloadAllAccessors: .Message2
.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
2588 ms. Memory: 481280K Free: 309069K (64%)
java.lang.RuntimeException: Execution failed
        at ptolemy.moml.MoMLSimpleApplication$UnloadThread.run(MoMLSimpleApplication.java:367)
Caused by: ptolemy.kernel.util.IllegalActionException: Exceptions occurred during wrapup:
ptolemy.kernel.util.IllegalActionException: The fire() method of this actor was never called. Usually, this is an error indicating that \
starvation is occurring.
  in .Message3.Test

JUnit Failure #4

----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message2.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5
2561 ms. Memory: 408064K Free: 339288K (83%)
reloadAllAccessors: .Message2
.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3
2532 ms. Memory: 476160K Free: 272887K (57%)
----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
Dec 23, 2015 12:58:05 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3
2542 ms. Memory: 478720K Free: 313006K (65%)
reloadAllAccessors: .Message3
.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message4.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3,2,1
2523 ms. Memory: 546816K Free: 307313K (56%)

JUnit Failure #5

.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message2.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5
2600 ms. Memory: 410624K Free: 362291K (88%)
----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message2.xml
Dec 23, 2015 1:01:51 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Sending data: 5,1,2,3
Client: Sending data: 4,5
2558 ms. Memory: 412160K Free: 338015K (82%)
reloadAllAccessors: .Message2
.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3
2510 ms. Memory: 471040K Free: 255755K (54%)
----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Message3.xml
Client: Sending data: 5,1,2,3
Client: Sending data: 4,5,3,1,2,3
2535 ms. Memory: 477696K Free: 284158K (59%)
reloadAllAccessors: .Message3

Later, in the same run:

.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Socket3.xml
Client: Discarding because socket is not open: a
3444 ms. Memory: 794624K Free: 364136K (46%)
----------------- testing again /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/Socket3.xml
Dec 23, 2015 1:02:18 PM io.vertx.core.impl.ContextImpl
SEVERE: Unhandled exception
java.lang.IllegalMonitorStateException
        at java.lang.Object.notifyAll(Native Method)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:682)
        at ptolemy.domains.de.kernel.DEDirector.fireAt(DEDirector.java:562)
        at ptolemy.domains.de.kernel.DEDirector.fireAtCurrentTime(DEDirector.java:707)
        at ptolemy.actor.lib.jjs.JavaScript.invokeCallback(JavaScript.java:1264)
        at ptolemy.actor.lib.jjs.HelperBase._issueResponse(HelperBase.java:177)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper.access$1900(SocketHelper.java:95)
        at ptolemy.actor.lib.jjs.modules.socket.SocketHelper$SocketWrapper.lambda$null$12(SocketHelper.java:491)
        at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:175)
        at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:287)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$16(ContextImpl.java:333)
        at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:225)
        at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:99)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
        at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
        at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
        at java.lang.Thread.run(Thread.java:745)

Client: Discarding because socket is not open: a
3586 ms. Memory: 799232K Free: 597774K (75%)
reloadAllAccessors: .Socket3
.----------------- testing /Users/cxh/ptII/ptolemy/actor/lib/jjs/modules/socket/test/auto/SocketByte.xml
Client: Sending data: -1,0,1,128,256
Client3: Sending data: 127
2801 ms. Memory: 876032K Free: 619395K (71%)

Possible Solution

Edward wrote:

This is a really weird one...

The only reason I can think of for the findBugs warning is that findBugs may believe that the _eventQueue field could change between when the synchronization lock is acquired and when notifyAll is called.

This would only occur if a second execution of the model actually overlaps in time with the first... I guess this is theoretically possible, and may in fact be happening in the test mechanism that is triggering the bug.

One possible fix might be in preinitialize. Instead of:

    public void preinitialize() throws IllegalActionException {
        _isInitializing = true;
        // Initialize an event queue.
        _eventQueue = new DECQEventQueue(
                ((IntToken) minBinCount.getToken()).intValue(),
                ((IntToken) binCountFactor.getToken()).intValue(),
                ((BooleanToken) isCQAdaptive.getToken()).booleanValue());
 

we could do:

    public void preinitialize() throws IllegalActionException {
        if (_eventQueue != null) {
            // This execution may be overlapped with the previous.
            synchronized(_eventQueue) {
                _isInitializing = true;
                // Initialize an event queue.
                _eventQueue = new DECQEventQueue(
                        ((IntToken) minBinCount.getToken()).intValue(),
                        ((IntToken) binCountFactor.getToken()).intValue(),
                        ((BooleanToken) isCQAdaptive.getToken()).booleanValue());
            }
        } else {
            _isInitializing = true;
            // Initialize an event queue.
            _eventQueue = new DECQEventQueue(
                ((IntToken) minBinCount.getToken()).intValue(),
                ((IntToken) binCountFactor.getToken()).intValue(),
                ((BooleanToken) isCQAdaptive.getToken()).booleanValue());
        }

Another alternative would be to build a mechanism for the second execution to wait until the first has completely wrapped up. That could be tricky, however, as there may be external threads attempting to queue events even after wrapup is called.

Possible Solution Continued

Unfortunately, that means that we are changing the value of the lock while holding the lock. FindBugs warns:

DEDirector.java:1309, ML_SYNC_ON_FIELD_TO_GUARD_CHANGING_THAT_FIELD, Priority: High

ML: Synchronization on DEDirector._eventQueue in futile attempt to guard it

This method synchronizes on a field in what appears to be an attempt to guard against simultaneous updates to that field. But guarding a field gets a lock on the referenced object, not on the field. This may not provide the mutual exclusion you need, and other threads might be obtaining locks on the referenced objects (for other purposes). An example of this pattern would be:

private Long myNtfSeqNbrCounter = new Long(0);
private Long getNotificationSequenceNumber() {
     Long result = null;
     synchronized(myNtfSeqNbrCounter) {
         result = new Long(myNtfSeqNbrCounter.longValue() + 1);
         myNtfSeqNbrCounter = new Long(result.longValue());
     }
     return result;
 }

Even worse, PtidesDirector.preinitialize() looks like:

public class PtidesDirector extends DEDirector implements Decorator {
...
public void preinitialize() throws IllegalActionException {
    super.preinitialize();
        _eventQueue = new PtidesListEventQueue();

PtidesDirector should be using synchronized() in many places...

I see these options:

  1. Use a different object to lock the _eventQueue
  2. Make _eventQueue final. This fails because DEDirector.clone() and PtidesDirectory.preinitialize() set _eventQueue
  3. In DEDirector.preinitialize(), add a method that would update the fields of _eventQueue without changing _eventQueue itself.

The problem with #3 is that _eventQueue() is declared as a DEEventQueue, but we instantiate a DECQEventQueue(). So we can't just create DECQEventQueue.initialize(int minBinCount, int binCountFactor, boolean isAdaptive) and invoke it in DEDirector.preinitialize() because _eventQueue is declared as a DEEventQueue().

In DEDirector.preinitialize(), we could do an instanceof check, but this seems wrong, especially because PtidesDirector.preinitialize() is setting _eventQueue to a new PtidesListEventQueue after the call to DEDirector.preinitialize()

So, I'm thinking that we need to add a lock, which I've done, which solves the FindBugs warnings and passes the test in ptolemy/actor/lib/jjs/modules/socket/test/junit

See Also

Edit - History - Print - Recent Changes - Search
Page last modified on January 05, 2016, at 06:19 PM