ConcurrentModificationException in EventDispatcher

[NicklasWallgren]

I received the following stacktrace using 1.4.1 and jbr_dcevm-17-osx-x64-b135.1

Exception in thread "HotSwap Dispatcher" java.util.ConcurrentModificationException
	at java.base/java.util.ArrayList$Itr.checkForComodification(ArrayList.java:1013)
	at java.base/java.util.ArrayList$Itr.next(ArrayList.java:967)
	at org.hotswap.agent.watch.nio.EventDispatcher.run(EventDispatcher.java:124)

Seems related to #155

[skybber]

Could you send please java arguments?

[skybber]

Optionally could you please add a file hotswap-agent.properties to your resources containing:

LOGGER.org.hotswap.agent.config.PluginManager=debug

and check if you see (org.hotswap.agent.config.PluginManager) - Registering transformer in logs multiple times ?

[NicklasWallgren]

Thanks for the reply.

As you might already figured out the plugins/hotswap agent was loaded/initiated twice. After I disabled the HotSwapAgent plugin in Intellij it worked somewhat, but the hotswapping breaks after the first re-compilation.

HOTSWAP AGENT: 21:18:06.683 ERROR (org.hotswap.agent.plugin.jdk.JdkPlugin) - classReload() exception No such field java.beans.Introspector.declaredMethodCache on null.

Arguments
-XX:HotswapAgent=fatjar

Loaded plugins

HOTSWAP AGENT: 21:23:06.243 INFO (org.hotswap.agent.plugin.spring.SpringPlugin) - Registering basePackage <removed>
HOTSWAP AGENT: 21:23:08.339 INFO (org.hotswap.agent.plugin.tomcat.TomcatPlugin) - Tomcat plugin initialized - Tomcat version '9.0.46.0'
HOTSWAP AGENT: 21:23:09.880 INFO (org.hotswap.agent.plugin.hibernate.HibernatePlugin) - Hibernate plugin initialized - Hibernate Core version '5.4.32.Final'

[NicklasWallgren]

It seems as declaredMethodCache no longer is available in Java 17.

https://bugs.openjdk.java.net/browse/JDK-8222799

Affected code

HotswapAgent/hotswap-agent-core/src/main/java/org/hotswap/agent/plugin/jdk/JdkPlugin.java

Line 65 in ae419ff

Object declaredMethodCache = ReflectionHelper.get(null, introspectorClass, "declaredMethodCache");

[skybber]

You can ignore the error message for now, it should not affect hotswap or does it?

[NicklasWallgren]

You are correct, it doesn't seem to affect the actual hotswapping. I tried disabling theJdkPlugin and the error message disappeared, but the issue with the hotswapping still remains.

The problem is that the hotswapping only seems to work during the first re-compilation, any further changes isn't hotswapped. I tried changing the response of an endpoint in a Spring Boot controller, and it worked as expected for the first recompilation, but any further re-compilations didn't get applied.

I don't know if it's related to the SpringPlugin.

[skybber]

Could you try -XX:+AllowEnhancedClassRedefinition -Xlog:redefine+class*=info to turn on dcevm logs? You should see how the hotswap is processed in the JVM.

[NicklasWallgren]

The first recompilation went fine.

[19.534s][info][redefine,class,load] redefined name=com.example.hexagonalarchitecture.domain.service.BookServiceImpl, count=1 (avail_mem=40156K)
[19.634s][info][redefine,class,timer] vm_op: all=111  prologue=12  doit=99
[19.634s][info][redefine,class,timer] doit: heap iterate=51  fullgc=0

The second didn't "include" the recompiled file.

[35.669s][info][redefine,class,timer] vm_op: all=95  prologue=1  doit=94
[35.669s][info][redefine,class,timer] doit: heap iterate=43  fullgc=0

And the third complained about the path

HOTSWAP AGENT: 11:52:18.931 WARNING (org.hotswap.agent.watch.nio.WatcherNIO2) - Watcher on <PATH REMOVED>/hexagonal-architecture/build/classes/java/main/com/example/hexagonalarchitecture/domain/service not valid, removing path=
[64.054s][info][redefine,class,timer] vm_op: all=83  prologue=1  doit=82
[64.054s][info][redefine,class,timer] doit: heap iterate=41  fullgc=0

[NicklasWallgren]

Seems as the classes only can be hotswapped once.

-- Hotswap works, first time encountering TestController
[23.959s][debug][redefine,class,load] loading name=com.example.hexagonalarchitecture.adapter.driver.api.TestController kind=102 (avail_mem=27232K)
[23.991s][debug][redefine,class,load] Comparing different class versions of class com/example/hexagonalarchitecture/adapter/driver/api/TestController
[23.991s][debug][redefine,class,load] loaded name=com.example.hexagonalarchitecture.adapter.driver.api.TestController (avail_mem=27232K)
[23.991s][info ][redefine,class,load] redefined name=com.example.hexagonalarchitecture.adapter.driver.api.TestController, count=1 (avail_mem=27232K)
[24.122s][info ][redefine,class,timer] vm_op: all=163  prologue=33  doit=130
[24.122s][info ][redefine,class,timer] doit: heap iterate=55  fullgc=0
HOTSWAP AGENT: 17:10:34.829 WARNING (org.hotswap.agent.watch.nio.WatcherNIO2) - Watcher on /<REMOVED>/hexagonal-architecture/build/classes/java/main/com/example/hexagonalarchitecture/domain/service not valid, removing path=
-- Hotswap works, first time encountering BookServiceImpl
[42.151s][debug][redefine,class,load ] loading name=com.example.hexagonalarchitecture.domain.service.BookServiceImpl kind=102 (avail_mem=33648K)
[42.169s][debug][redefine,class,load ] Comparing different class versions of class com/example/hexagonalarchitecture/domain/service/BookServiceImpl
[42.169s][debug][redefine,class,load ] loaded name=com.example.hexagonalarchitecture.domain.service.BookServiceImpl (avail_mem=33648K)
[42.169s][info ][redefine,class,load ] redefined name=com.example.hexagonalarchitecture.domain.service.BookServiceImpl, count=1 (avail_mem=33648K)
[42.259s][info ][redefine,class,timer] vm_op: all=109  prologue=19  doit=90
[42.259s][info ][redefine,class,timer] doit: heap iterate=41  fullgc=0
HOTSWAP AGENT: 17:10:50.835 WARNING (org.hotswap.agent.watch.nio.WatcherNIO2) - Watcher on /<REMOVED>/hexagonal-architecture/build/classes/java/main/com/example/hexagonalarchitecture/domain/service not valid, removing path=
---- No longer hotswaps on rebuild 
[58.342s][info ][redefine,class,timer] vm_op: all=92  prologue=3  doit=89
[58.342s][info ][redefine,class,timer] doit: heap iterate=50  fullgc=0
---- No longer hotswaps on rebuild 
[73.388s][info ][redefine,class,timer] vm_op: all=92  prologue=1  doit=91
[73.388s][info ][redefine,class,timer] doit: heap iterate=51  fullgc=0
---- No longer hotswaps on rebuild 
[103.926s][info ][redefine,class,timer] vm_op: all=217  prologue=31  doit=186
[103.926s][info ][redefine,class,timer] doit: heap iterate=88  fullgc=0

[skybber]

It seems more like problem of IDE not dcevm. Could you check if you have fresh recompiled class in target/ directory? Is the hotswap initialized from debugger or are you using autoHotswap=true from HotswapAgent?

[NicklasWallgren]

The application is running in debug mode, and the compiled classes gets updated in build directory. Intellij states that re-compiled classes has been reloaded via the "n class reloaded" tooltip.

Here you got a short screen recording.
https://drive.google.com/file/d/1kMsgmm3aa5UtUOCdOQEnxup2_zR69YDO/view?usp=sharing

[skybber]

What idea version are you using ?

[NicklasWallgren]

I'm running 2021.1.2, but I have also tried with the latest version which is 2021.1.3.

I have also tried building using Gradle (the default option) as well as the Intellij option. I didn't make any difference.

[skybber]

Is dcevm11 working?

[NicklasWallgren]

It does! I tried with jbr_dcevm-11_0_13-osx-x64-b1751.16.tar.gz and it worked as expected. Seems to be some issues with jbr_dcevm-17-osx-x64-b135.1.tar.gz

The changes is picked up on every re-compilation.

[19.380s][debug][redefine,class,load] loading name=com.example.hexagonalarchitecture.adapter.driver.api.TestController kind=102 (avail_mem=21648K)
[19.403s][debug][redefine,class,load] Comparing different class versions of class com/example/hexagonalarchitecture/adapter/driver/api/TestController
[19.403s][debug][redefine,class,load] loaded name=com.example.hexagonalarchitecture.adapter.driver.api.TestController (avail_mem=21648K)
[19.406s][info ][redefine,class,load] redefined name=com.example.hexagonalarchitecture.adapter.driver.api.TestController, count=1 (avail_mem=21648K)
[19.569s][info ][redefine,class,timer] vm_op: all=194  prologue=32  doit=162
[19.569s][info ][redefine,class,timer] doit: heap iterate=79  fullgc=0
-- Works
[30.204s][debug][redefine,class,load ] loading name=com.example.hexagonalarchitecture.adapter.driver.api.TestController kind=102 (avail_mem=32652K)
[30.229s][debug][redefine,class,load ] Comparing different class versions of class com/example/hexagonalarchitecture/adapter/driver/api/TestController
[30.229s][debug][redefine,class,load ] loaded name=com.example.hexagonalarchitecture.adapter.driver.api.TestController (avail_mem=32652K)
[30.229s][info ][redefine,class,load ] redefined name=com.example.hexagonalarchitecture.adapter.driver.api.TestController, count=2 (avail_mem=32652K)
[30.348s][info ][redefine,class,timer] vm_op: all=146  prologue=27  doit=119
[30.348s][info ][redefine,class,timer] doit: heap iterate=67  fullgc=0
-- Works
[52.235s][debug][redefine,class,load ] loading name=com.example.hexagonalarchitecture.adapter.driver.api.TestController kind=102 (avail_mem=43708K)
[52.262s][debug][redefine,class,load ] Comparing different class versions of class com/example/hexagonalarchitecture/adapter/driver/api/TestController
[52.262s][debug][redefine,class,load ] loaded name=com.example.hexagonalarchitecture.adapter.driver.api.TestController (avail_mem=43708K)
[52.262s][info ][redefine,class,load ] redefined name=com.example.hexagonalarchitecture.adapter.driver.api.TestController, count=3 (avail_mem=43708K)
[52.383s][info ][redefine,class,timer] vm_op: all=150  prologue=30  doit=120
[52.383s][info ][redefine,class,timer] doit: heap iterate=60  fullgc=0

[skybber]

You can disable dcevm using -XX:-AllowEnhancedClassRedefinition and use only standard redefinition, what happens?

[NicklasWallgren]

dcevm-11
Works with and without -XX:-AllowEnhancedClassRedefinition

dcevm-17
Same issue as before, with and without -XX:-AllowEnhancedClassRedefinition

[skybber]

You can try plain jbr-runtime17 without dcevm, what happens? It seems strange since -XX:-AllowEnhancedClassRedefinition turn JVM to standard mode - using this option, there must be no difference between dcevm a standard jvm.

[NicklasWallgren]

The default jbr-17-osx-x64-b135.1 seems to work for this test purpose, the changes are hot reloaded for each re-compilation.

152.044s][debug][redefine,class,load        ] loaded name=com.example.hexagonalarchitecture.adapter.driver.api.TestController (avail_mem=57500K)
[152.049s][info ][redefine,class,load        ] redefined name=com.example.hexagonalarchitecture.adapter.driver.api.TestController, count=6 (avail_mem=57500K)
[152.053s][debug][redefine,class,nmethod     ] Marked 0 dependent nmethods for deopt
[152.061s][info ][redefine,class,timer       ] vm_op: all=0  prologue=0  doit=0
[152.061s][info ][redefine,class,timer       ] redefine_single_class: phase1=0  phase2=0

[skybber]

Jbr should have fixed this issue https://github.com/JetBrains/JetBrainsRuntime/releases/tag/jbr17_0_1b164.8

[NicklasWallgren]

Great. Thanks for the help @skybber.