[BUG] Eclipse lombok is extremely slow on big projects changes.. cpu consuming on LombokConfiguration.read

[Arnaud-Nauwynck]

Describe the bug From eclipse, remove one maven project dependency out of several big imported projects (for example import apache-hive projects) Notice that none of these projects were actually using any lombok annotations. Eclipse looks completely frozen, and lock all user actions, even after 20 minutes... could not wait, so killed it. Eclipse looks not dead-locked, as it continuously consume lot of CPU, in several threads: "Compiler Processing Task,"Java indexing", and "Worker" This is shown by comparing several thread dumps : stack.txt stack2.txt stack3.txt stack4.txt stack5.txt

It seems that there are many system calls to files, performed recursively for each LombokConfiguration reloaded for east AST node.

at java.io.File.getParentFile(File.java:499) at lombok.core.configuration.FileSystemSourceCache$2$1.findNext(FileSystemSourceCache.java:133) at lombok.core.configuration.FileSystemSourceCache$2$1.hasNext(FileSystemSourceCache.java:118) at lombok.core.configuration.BubblingConfigurationResolver.resolve(BubblingConfigurationResolver.java:44) at lombok.core.LombokConfiguration.read(LombokConfiguration.java:67) at lombok.core.AST.readConfiguration(AST.java:436) at lombok.eclipse.handlers.HandleFieldDefaults.visitType(HandleFieldDefaults.java:165) at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:72) at lombok.eclipse.EclipseAST.traverseChildren(EclipseAST.java:233) at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:73) at lombok.eclipse.EclipseAST.traverseChildren(EclipseAST.java:233) at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:73)

To Reproduce import some big maven projects, then close or remove then

Expected behavior expecting eclipse to be not taking 100% cpu for so long

Version info (please complete the following information):

• Lombok version: latest 1.18.10
• Platform : eclipse... tested same behavior with several eclipse versions (2019-03 and latest 2020-06).

Additional context

[Rawi01]

The lombok configuration system caches the file content and only reads it again if the last modified timestamp changes. It also skips the timestamp check if the last one happens in the last two seconds. It might be possible to rework this cache to stop checking the parents and applying the config building logic over and over again if this turns out to be a real problem.

I also did some profiling to see how much time the configuration system takes and it seems to be a minor factor. It might be possible that there are other things that leads to these problems e.g. slow HDD, slow antivirus software, ...

Can you try to compile it using

• Eclipse without lombok
• Eclipse with disabled config system (add lombok.disableConfig=true as environment variable)
• Maven/Gradle/Ant with and without lombok

and write down the time it needs to finish?

[randakar]

Feels very much like a death by a thousand cuts problem though. The configuration system may be relatively quick but it's still accessing the disk and if it gets called a billion times in a row..

On Sun, Jun 14, 2020, 11:58 Rawi01 notifications@github.com wrote:

The lombok configuration system caches the file content and only reads it again if the last modified timestamp changes. It also skips the timestamp check if the last one happens in the last two seconds. It might be possible to rework this cache to stop checking the parents and applying the config building logic over and over again if this turns out to be a real problem.

I also did some profiling to see how much time the configuration system takes and it seems to be a minor factor. It might be possible that there are other things that leads to these problems e.g. slow HDD, slow antivirus software, ...

Can you try to compile it using

• Eclipse without lombok
• Eclipse with disabled config system (add lombok.disableConfig=true as environment variable)
• Maven/Gradle/Ant with and without lombok

and write down the time it needs to finish?

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/2489#issuecomment-643744448, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABIERKRMB3Z5FUNRDBGO7TRWSNK3ANCNFSM4N2WBPDA .

[Rawi01]

I did some more profiling on a different slower windows machine with anti virus software and disk encryption and noticed some things that could be optimized. I will create a PR soon. Unfortunately they are only important during a normal javac compilation. The eclipse build works as expected. I might have missed something and will continue working on it tomorrow.

[randakar]

There are other bug reports that show a very similar thread stack.

In that case it was eclipse doing some recursive search through the entire ast tree multiple times in parallel as part of codemining. The eclipse folks are solving that in codemining by reducing the number of tree traversals.

It does feel like that config lookup could use a cache or two but so far most of the cases involve eclipse doing far too many tree traversals in parallel.

On Mon, Jun 15, 2020, 21:22 Rawi01 notifications@github.com wrote:

I did some more profiling on a different slower windows machine with anti virus software and disk encryption and noticed some things that could be optimized. I will create a PR soon. Unfortunately they are only important during a normal javac compilation. The eclipse build works as expected. I might have missed something and will continue working on it tomorrow.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/2489#issuecomment-644329417, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABIERNW2NS3WIZVRAPOBNTRWZYF7ANCNFSM4N2WBPDA .

[Arnaud-Nauwynck]

I confirm that it has nothing to do with maven/gradle/javac/eclipse compilation. It is only in eclipse+lombok, and NOT in eclipse alone.

Modifying some projects(open/close) causes eclipse to rescan lots (millions) of AST tree nodes, which is supposed to be "very" fast, because it is all in memory, and without excessive locks or cpu consumed. (Indeed, when Eclipse is used without Lombok, it IS acceptabily fast)

However, when lombok is enabled in eclipse, traversing the AST cause Lombok to refresh billions of time its configuration, by performing Filesystem calls for each node traversal. Clearly, the configuration caching of Lombok does not work (and why would you need to reload such config anyway? If I change a config, I can stop+restart my eclipse myself)

I am really found of Lombok, so I really hope this explanation will help you understanding this problem (not only my problem) and fix it. Personally, If I had to do a PR for this, I would simply disable the config cache loading, by loading it only ONCE and put it in a static final immutable thing, without even checking for file system date timestamp ever.

Regards, Arnaud

[Maaartinus]

Personally, If I had to do a PR for this, I would simply disable the config cache loading, by loading it only ONCE and put it in a static final immutable thing, without even checking for file system date timestamp ever.

I don't think this is a good idea. According to @Rawi01 above, It also skips the timestamp check if the last one happens in the last two seconds. So it can't really help as checking every two seconds must already solve the problem. If it doesn't, it must be broken, maybe a bug, maybe some classloader magic effectively disabling any global places.

(part removed as I was wrong)

[Rawi01]

@Maaartinus I think the current check is correct, if it is true it returns the cached version and do not perform an io operation.

@Arnaud-Nauwynck Can you update to the latest lombok version? I just noticed that you use an old version. If that doesn't help, please provide some more data. For example you can create and share a sampling snapshot using visualvm.

[randakar]

Here's a thought.

If Eclipse fires up the AST compilation in parallel, that check may not be enough. I mean, sure, lombok keeps the 'did we read this recently' state cached, but in what memory? Is that memory even shared with the other threads? Even if it's a static volatile field somewhere it may not even be in the same VM..

This kind of thing can be extremely fiddly, it's easy to get wrong in regular java code, and this definitely isn't regular code..

On Sun, Jun 21, 2020, 14:23 Rawi01 notifications@github.com wrote:

@Maaartinus https://github.com/Maaartinus I think the current check is correct, if it is true it returns the cached version and do not perform an io operation.

@Arnaud-Nauwynck https://github.com/Arnaud-Nauwynck Can you update to the latest lombok version? I just noticed that you use an old version. If that doesn't help, please provide some more data. For example you can create and share a sampling snapshot using visualvm.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/2489#issuecomment-647121082, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABIERMOW3HUSSRA3ZZC56TRXX3T5ANCNFSM4N2WBPDA .

[randakar]

Time for me to take a bit of a deeper look here.

For starters, a quick check of FileSystemSourceCache.java  - maybe that one isn't doing it's job.

Doesn't seem to contain a smoking gun though. Concurrent datastructures, the "lastCacheClear" field is properly volatile... on the surface, it looks decent enough. But, we do have those 5 thread dumps. Maybe that will tell us what the real problem is.

The first observation is that everything currently in eclipse code is either in WAITING state or TIMED_WAIT state. With the exception of "Compiler Processing Task" and "Java indexing", nothing is currently in lombok code, and everything not currently in either of those two threads is waiting for those two threads to finish. Including the worker threads mentioned by the OP. Looking at just those two threads - they are in lombok's eclipse tree traversal path in both threads in all 5 dumps.Note that that codepath is eclipse specific, so it wouldn't show up in other IDE's, maven builds, or what have you.

But the 5 stacks show that lombok in most of the cases involving reading files is doing something different each time.We do see the file cache show up a lot - that should not be the case, unless reading the config file takes > 2 seconds. Which .. is not impossible, honestly. This is on windows, and if the underlying filesystem is secretly being shunted off across the network, it could be very slow.

Anyway, each of the stacks:

1. stack "Compiler Processing Task" at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:131)

"Java indexing" at Arrays.copyOfRange(Arrays.java:3664) ... at lombok.core.configuration.FileSystemSourceCache$2$1.findNext(FileSystemSourceCache.java:133)

The compiler processing task is currently traversing nodes. The other one is actually busy copying data off the filesystem.

2. stack2 "Compiler Processing Task" at java.util.Arrays.copyOfRange(Arrays.java:3664) ... at lombok.core.configuration.FileSystemSourceCache$2$1.findNext(FileSystemSourceCache.java:133)   "Java indexing" at java.io.File.getParentFile(File.java:499) ... at lombok.core.configuration.FileSystemSourceCache$2$1.findNext(FileSystemSourceCache.java:133)

One thread reading a file, the other getting a file from the cache. That may not be the same file. Hard to say.

3. stack3 "Compiler Processing Task" at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:88)

"Java indexing" at java.io.WinNTFileSystem.compare(WinNTFileSystem.java:634) .. at java.io.File.equals(File.java:2112) at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:940) at lombok.core.configuration.FileSystemSourceCache.ensureContent(FileSystemSourceCache.java:169) at lombok.core.configuration.FileSystemSourceCache.getSourceForDirectory(FileSystemSourceCache.java:155) at lombok.core.configuration.FileSystemSourceCache$2$1.findNext(FileSystemSourceCache.java:132) at lombok.core.configuration.FileSystemSourceCache$2$1.hasNext(FileSystemSourceCache.java:118)

Interesting one. File.equals implies File objects are actually keys in the map. Doubt if this will actually hit the disk, but still..

4. stack4 "Compiler Processing Task" at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:88)

"Java indexing" at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:90)

Neither of the threads is doing anything related to the file cache, for once. One thing to remark though is that traverseChildren() is being called 3-4 times in all of the stack traces, so we're doing a lot of work here.

5. stack5 "Compiler Processing Task" at java.io.File.(File.java:368) at lombok.core.configuration.FileSystemSourceCache.getSourceForDirectory(FileSystemSourceCache.java:153) at lombok.core.configuration.FileSystemSourceCache$2$1.findNext(FileSystemSourceCache.java:132) at lombok.core.configuration.FileSystemSourceCache$2$1.hasNext(FileSystemSourceCache.java:118)

"Java indexing" at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:88)

Does constructing a File object cause a hit on the filesystem? I wonder ..

Looking at this, that filesystem cache definitely is playing a role.

... heh, ok, I'm having a bit of a laugh now. Apparently, @rspilker has been modifying that filecache back in january. The version I looked at was the master version, but the line numbers don't match - this was 1.18.10, and apparently things changed since then.

edit: Affected by commit https://github.com/rzwitserloot/lombok/commit/f2d49a89ecc09dc30fc03102254c9ffc62b7659e

[randakar]

@Arnaud-Nauwynck Could you please try this with lombok 1.18.12 ? Thanks.

[Rawi01]

I think this might be the line that causes the problems:

at java.io.WinNTFileSystem.compare(WinNTFileSystem.java:634)
..
at java.io.File.equals(File.java:2112)

If WinNTFileSystem is involved it most likely access the disk. I also noticed that it is an old version and I only profiled using the latest one, thats why I already asked him to update lombok.

What baffled me the most during profiling was that File.toURI() requires a disk access. That actually slow downs javac compilation a lot. I have already prepared a PR to fix that one (its not send because I broke some test/found another bug in eclipse)

[rspilker]

Good find.

When I wrote the code, I was under the impression that File.equals only used the string path. This really surprised me, since it is possible to have file objects that don't have something on the backing filesystem at all. Why would is access the filesystem?

It does make sense to rewrite the code so it cannot.

On Mon, Jun 22, 2020, 12:12 Rawi01 notifications@github.com wrote:

I think this might be the line that causes the problems:

at java.io.WinNTFileSystem.compare(WinNTFileSystem.java:634) .. at java.io.File.equals(File.java:2112)

If WinNTFileSystem is involved it most likely access the disk. I also noticed that it is an old version and I only profiled using the latest one, thats why I already asked him to update lombok.

What baffled me the most during profiling was that File.toURI() requires a disk access. That actually slow downs javac compilation a lot. I have already prepared a PR to fix that one (its not send because I broke some test/found another bug in eclipse)

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/2489#issuecomment-647422431, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAWZBSM6G3QKNYNTF6NEGDRX4VBPANCNFSM4N2WBPDA .

[randakar]

Which is probably why @rspilker already changed that class to stop referring to File objects in https://github.com/rzwitserloot/lombok/commit/f2d49a89ecc09dc30fc03102254c9ffc62b7659e :)

[randakar]

And yeah, I know that is you .. ;)

Nonetheless I am curious what this does in 1.18.12, since it seems those maps no longer refer to File objects, that particular problem may be gone.

but .. that equals method only shows up in one stack dump.

All of the others show other things going on. To the point that I wonder if this isn't secretly a problem with the eclipse tree traversal code in lombok, rather than the configuration system itself.

[Arnaud-Nauwynck]

Hi, sorry I did not read your message since 20 days, asking me to try the latest version I have just retryed with 1.18.12 ( I have also retryed with snapshot version "lombok-edge.jar", giving same result)

I still see slow stack traces like the following:

"Java indexing" #31 daemon prio=4 os_prio=-1 tid=0x00000000209ac000 nid=0x4808 runnable [0x00000000201fe000]
   java.lang.Thread.State: RUNNABLE
    at java.util.HashMap.putVal(HashMap.java:631)
    at java.util.HashMap.put(HashMap.java:612)
    at java.util.HashSet.add(HashSet.java:220)
    at lombok.core.configuration.BubblingConfigurationResolver.resolve(BubblingConfigurationResolver.java:62)
    at lombok.core.LombokConfiguration.read(LombokConfiguration.java:73)
    at lombok.core.LombokConfiguration.read(LombokConfiguration.java:69)
    at lombok.core.AST.readConfiguration(AST.java:436)
    at lombok.eclipse.handlers.HandleFieldDefaults.visitType(HandleFieldDefaults.java:166)

and

"Compiler Processing Task" #95 daemon prio=5 os_prio=0 tid=0x0000000024e4a000 nid=0x46e0 runnable [0x000000002234e000]
   java.lang.Thread.State: RUNNABLE
    at lombok.core.configuration.FileSystemSourceCache.access$0(FileSystemSourceCache.java:92)
    at lombok.core.configuration.FileSystemSourceCache$1.parsed(FileSystemSourceCache.java:57)
    at lombok.core.configuration.BubblingConfigurationResolver.resolve(BubblingConfigurationResolver.java:64)
    at lombok.core.LombokConfiguration.read(LombokConfiguration.java:73)
    at lombok.core.LombokConfiguration.read(LombokConfiguration.java:69)
    at lombok.core.AST.readConfiguration(AST.java:436)

and

"Compiler Processing Task" #95 daemon prio=5 os_prio=0 tid=0x0000000024e4a000 nid=0x46e0 runnable [0x000000002234e000]
   java.lang.Thread.State: RUNNABLE
    at java.io.File.<init>(File.java:368)
    at lombok.core.configuration.ConfigurationFile.forDirectory(ConfigurationFile.java:61)
    at lombok.core.configuration.ConfigurationFile$RegularConfigurationFile.parent(ConfigurationFile.java:177)
    at lombok.core.configuration.BubblingConfigurationResolver.resolve(BubblingConfigurationResolver.java:85)
    at lombok.core.LombokConfiguration.read(LombokConfiguration.java:73)
    at lombok.core.LombokConfiguration.read(LombokConfiguration.java:69)
    at lombok.core.AST.readConfiguration(AST.java:436)
    at lombok.eclipse.handlers.HandleFieldDefaults.visitType(HandleFieldDefaults.java:165)
    at lombok.eclipse.EclipseNode.traverse(EclipseNode.java:72)

I have taken many different stack traces, using "jstack$pid > stack.txt" Most of them are consuming cpu in this location: lombok.core.configuration.ConfigurationFile.forDirectory(ConfigurationFile.java:61)

Apparently, these are not exactly the same stack traces as when opening this issue one month ago, but still a big overhead in the class LombokConfiguration

You asked me to measure time with different configurations.. But unfortunatly, it never finished, so the time is more than 15mn, then "give up" I did not see any change after adding the environment variable "set lombok.disableConfig=true"

Regards, Arnaud

[Rawi01]

Thanks for the response.

Unfortunately, as long as I am unable to reproduce this problem it is hard for me to really help you to solve it. Nevertheless I noticed these calls during sampling for a memory related lombok issue too. If I remember correctly that happens if there is not enough available memory and the garbage collector is busy. That would also cause eclipse to get really slow. Can you try to increase the available memory for eclipse? It could also help if you can use VisualVM to create a CPU and Memory sampling snapshot and upload them here.

In general, the lombok configuration system creates a lot of objects and wastes some CPU cycles but compared to the regular compilation stuff it is only a minor factor (at least for my samples). This can be solved by refactoring it but if no one else have the same problem it might not be worth the effort.

[Rawi01]

Just stumbled over this comment (https://github.com/rzwitserloot/lombok/issues/1717#issuecomment-498162337) and importing this project breaks eclipse :tada:. It seems to be stuck in a loop somewhere, handling the same file over and over again. The most time consuming action in this loop is reading the config files, thats why you see them in your stack traces. Finding the root cause should be possible now.

[Rawi01]

Pubished a potential fix (https://github.com/Rawi01/lombok/tree/ast-transformed-check). I also pre-build a lombok jar for you (lombok-1.18.13.zip), would be great if you could verify that this change solves the problem.

About the problem: The example project contains a 9.5MB/273k lines java file with a lot of methods. For every method the eclipse compiler invokes the parse method with a limited source range. Lombok hooks into the endParse method for every call and tries to perform the AST transformation every time. If there is a huge file like in this example this actually takes a lot of time. My fix stores which file was already transformed and skip the lombok task if the AST is already fine.

[randakar]

Damn. 9.5 MB? I guess we'd better support that but ouch.

Autogenerated code, I take it.

I have this test data generator somewhere that would produce a class containing a single field containing a map of filename to map of enum to string.. in a single field initializer.

The interesting thing was that initializing the whole thing in one go (with Map.ofEntries) was excruciatingly slow. Initializing the same map as a series of individual map fields and then initializing the mega map with those was just fine. Same field, same content, just less work in a single field initializer.

Is it possible that this was related to the same problem? Because maybe I should dig up the example..

On Tue, Jul 14, 2020, 11:31 Rawi01 notifications@github.com wrote:

Pubished a potential fix ( https://github.com/Rawi01/lombok/tree/ast-transformed-check). I also pre-build a lombok jar for you (lombok-1.18.13.zip https://github.com/rzwitserloot/lombok/files/4917803/lombok-1.18.13.zip), would be great if you could verify that this change solves the problem.

About the problem: The example project contains a 9.5MB/273k lines java file with a lot of methods. For every method the eclipse compiler invokes the parse method with a limited source range. Lombok hooks into the endParse method for every call and tries to perform the AST transformation every time. If there is a huge file like in this example this actually takes a lot of time. My fix stores which file was already transformed and skip the lombok task if the AST is already fine.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/2489#issuecomment-658078015, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABIEROAUA6ESHEUVNOBQL3R3QQWXANCNFSM4N2WBPDA .

[Rawi01]

@randakar That does not sound like the same problem but feel free to test it using the provided patch. If it does not help, please share that code (I think a new issue would be better) and I can check why it is that slow.

[randakar]

Tiny example project attached. Took me a little to extract this bit from the rest.

mapconstructorstress.zip

Note that it seems to be mostly IntelliJ that has issues. Maven compilation, with just three files, seems to be fast enough. About 0.8 seconds.

Increasing the size of SlowMap through a little copy-pasting to inflate it to roughtly 3000 lines does make IntelliJ slow down, until it starts complaining about running low on memory. But it can be a lot of things there - the SONAR plugin, for example.

Not convinced this is worth opening a new issue for.

[Rawi01]

@randakar Can confirm that this is extremly slow in eclipse. To verify that it is not related to lombok I started eclipse without it and that does not change anything. Seems like there is something wrong with dependencies :smile:

[randakar]

I didn't even test it in Eclipse - I use IntelliJ ;-)

No surprise that it's slow in Eclipse too though, field initializers aren't supposed to exceed 750 lines apparently ;-)

[randakar]

https://youtrack.jetbrains.com/issue/IDEA-245963

[rspilker]

Regarding the field initializers, we've discovered earlier that the type inference is problematic there as well. Those problems were resolved by moving the initialization code to a static private method.

[Arnaud-Nauwynck]

Hi,

Here is a recording of 2mn using "java flight recorder" (java mission control) Click on "Method Profiling", and you will see that most of the sampled calls are "lombok.eclipse.EclipseNode.traverse" (x8093) which is normal during project compilation of big AST, but the overhead of "lombok.core.configuration" (x1033) is unexpectedly important, in particular calling "new java.io.File()" (x2096)

flight_recording_180202Eclipse19352.zip

regards, Arnaud

[Arnaud-Nauwynck]

For comparision, here is the exactly same "java flight recorder" scenario without lombok... the project get 100% compiled in less than 2mn, while it was stuck at 7% when lombok was enabled.

flight_recording_eclipse_noLombok.zip

[Rawi01]

@Arnaud-Nauwynck can you try if my fix solves the problem? (https://github.com/rzwitserloot/lombok/issues/2489#issuecomment-658078015)

[Arnaud-Nauwynck]

@Rawi01 : I have tried your patched version. Indeed, it solves the problem!! I am now able to load all hive projects in my eclipse workspace...not only few 4-5 projects as before.

Thanks!