search

JMRI / JMRI

JMRI model railroad digital command & control software
https://www.jmri.org
Other
235 stars 331 forks source link

openlcb.PackageTest leaves too many threads #6827

Closed bobjacobsen closed 3 years ago

bobjacobsen commented 5 years ago

When run as part of comprehensive tests,openlcb.PackageTest leaves hundreds of threads running. This overwhelms various diagnostic tools (i.e. from ctrl-\ to NetBeans stack tracer) during later parts of a test run.

image
pabender commented 5 years ago

I would actually go one step further.

I think the JMRI OpenLCB tests start more threads than are required for unit testing. When last I dealt with this, we reduced the number of residual threads from

There also are at least a few OpenLCB test classes that test the pieces of the OpenLCB library. Those really shouldn’t be in the JMRI tests.

( also I just spotted that https://github.com/JMRI/JMRI/blob/master/java/test/jmri/jmrix/openlcb/CanConverterTest.java doesn’t actually test anything in the JMRI.jmrix.openlcb subtree, and one of the things it creates is an object from the library....)

pabender commented 5 years ago

@bobjacobsen that step up between 1:40 and 1:50 is 30 or 40 threads identified as BlockBossLogic. We should probably figure out how to terminate those threads. There are also a couple BlockBossLogic threads created pretty early in the process, before the OpenLCB threads start.

bobjacobsen commented 5 years ago

@pabender I think that group is left over from the XML file loading tests. Those don't really clean up created objects except to re-init the InstanceManager. I'll take a look at making that smarter.

bobjacobsen commented 4 years ago

Somehow, the OpenLCB tests are firing off new threads long after they OLB tests themselves are complete. Perhaps the threads or timers left behind spawn new ones? Some of these are deep enough in other tests that they may be causing intermittent problems.

Can we move this to the "run separately" category? That's a by-test annotation, unfortunately.

Running with these options:

JMRI_OPTIONS=-Duser.country=US -Duser.language=en -Djmri.util.JUnitUtil.checkSetUpTearDownSequence=true -Djmri.util.JUnitUtil.checkRemnantThreads=true -Djmri.util.JUnitUtil.printSetUpTearDownNames=true -Djmri.util.JUnitUtil.checkSequenceDumpsStack=true

gives you a trace of when new threads are present at the end of tests:

>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB Mimic Node Store Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB LoaderClient Timeout Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-3-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-3-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB NIDaAlgorithm Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "Olcb-Pool-4-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-4-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "Olcb-Pool-5-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-5-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "Olcb-Pool-6-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-6-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "Olcb-Pool-7-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-7-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-8-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-8-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
<<   Ending test in jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest
WARN  - Found remnant thread "OpenLCB Memory Configuration Service Retry Timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-9-Thread-1" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "Olcb-Pool-9-Thread-0" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
WARN  - Found remnant thread "OpenLCB-datagram-timer" in group "main" after jmri.jmrix.openlcb.swing.send.OpenLcbCanSendPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrit.vsdecoder.VSDecoderManagerTest
<<   Ending test in jmri.jmrit.vsdecoder.VSDecoderManagerTest
>> Starting test in jmri.jmrit.vsdecoder.VSDecoderManagerTest
<<   Ending test in jmri.jmrit.vsdecoder.VSDecoderManagerTest
>> Starting test in jmri.jmrit.display.layoutEditor.LayoutEditorHorizontalToolBarPanelTest
<<   Ending test in jmri.jmrit.display.layoutEditor.LayoutEditorHorizontalToolBarPanelTest
>> Starting test in jmri.jmrix.loconet.sdfeditor.SdlVersionEditorTest
<<   Ending test in jmri.jmrix.loconet.sdfeditor.SdlVersionEditorTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
WARN  - Found remnant thread "Olcb-Pool-3-Thread-2" in group "main" after jmri.implementation.TripleOutputSignalHeadTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
WARN  - Found remnant thread "Olcb-Pool-4-Thread-2" in group "main" after jmri.implementation.TripleOutputSignalHeadTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
WARN  - Found remnant thread "Olcb-Pool-5-Thread-2" in group "main" after jmri.implementation.TripleOutputSignalHeadTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
WARN  - Found remnant thread "Olcb-Pool-6-Thread-2" in group "main" after jmri.implementation.TripleOutputSignalHeadTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.implementation.TripleOutputSignalHeadTest
<<   Ending test in jmri.implementation.TripleOutputSignalHeadTest
>> Starting test in jmri.jmrix.internal.configurexml.InternalReporterManagerXmlTest
<<   Ending test in jmri.jmrix.internal.configurexml.InternalReporterManagerXmlTest
>> Starting test in jmri.jmrix.loconet.soundloader.EditorPaneTest
<<   Ending test in jmri.jmrix.loconet.soundloader.EditorPaneTest
WARN  - Found remnant thread "Olcb-Pool-7-Thread-2" in group "main" after jmri.jmrix.loconet.soundloader.EditorPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.soundloader.EditorPaneTest
<<   Ending test in jmri.jmrix.loconet.soundloader.EditorPaneTest
>> Starting test in jmri.jmrix.loconet.soundloader.EditorPaneTest
<<   Ending test in jmri.jmrix.loconet.soundloader.EditorPaneTest
WARN  - Found remnant thread "Olcb-Pool-8-Thread-2" in group "main" after jmri.jmrix.loconet.soundloader.EditorPaneTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.soundloader.EditorPaneTest
<<   Ending test in jmri.jmrix.loconet.soundloader.EditorPaneTest
>> Starting test in jmri.jmrit.operations.OperationsTestCase
<<   Ending test in jmri.jmrit.operations.OperationsTestCase
WARN  - Found remnant thread "Olcb-Pool-9-Thread-2" in group "main" after jmri.jmrit.operations.OperationsTestCase [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrit.operations.OperationsTestCase
<<   Ending test in jmri.jmrit.operations.OperationsTestCase
>> Starting test in jmri.jmrit.operations.OperationsTestCase

Note that new Olcb threads were detected after those later TripleOutputSignalHeadTest, EditorPaneTest and OperationsTestCase tests.

Much later, they show up again:

>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
WARN  - Found remnant thread "olcbCanInterface.initialize" in group "main" after jmri.jmrix.loconet.Ib1ThrottleTest [main] jmri.util.JUnitUtil.lambda$checkThreads$4()
>> Starting test in jmri.jmrix.loconet.Ib1ThrottleTest
<<   Ending test in jmri.jmrix.loconet.Ib1ThrottleTest
pabender commented 4 years ago

@bobjacobsen the olcbCanInterface.initialize thread is actually one that is created in jmri.jmrix.openlcb.OlcbConfigurationManager

i.e. it is in our code, not the Olcb library. The ThreadPools are created by the Olcb library.

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. JMRI is governed by a small group of maintainers which means not all opened issues may receive direct feedback.

stale[bot] commented 3 years ago

This issue has been automatically closed due to lack of activity. In an effort to reduce noise, please do not comment any further. Note that the maintainers may elect to reopen this issue at a later date if deemed necessary.