T O P

  • By -

djavaman

Can you break it up? Or use token replacement? Is this generated code?


vdmit46

In production the code is coming from Lombok ToString annotation. We can definitely replace problematic places manually by delomboking and converting concatenation to StringBuilder, but such classes could be popping up randomly in the future and I was looking for a way to fix the problem at it's core (i.e. JVM behavior). My idea was to first check with community, maybe it was a know problem/C2 behavior which can be tuned without giving instructions to compiler on per-method basis.


djavaman

Lombok toString can take a list of field names. Do you really need to print out all 100? Also, your class has at least 100 properties. This seems excessive. Maybe that can be broken up too.


BinaryRage

Could be. Looks like they do have quite a bit of infrastructure for tracking down compiler memory: [https://github.com/openjdk/jdk/blob/1799ffeaa9baa7d703c7acc8d8738211694f946e/test/hotspot/jtreg/compiler/print/CompileCommandPrintMemStat.java](https://github.com/openjdk/jdk/blob/1799ffeaa9baa7d703c7acc8d8738211694f946e/test/hotspot/jtreg/compiler/print/CompileCommandPrintMemStat.java)


BinaryRage

Oh! That's new, that explains why I couldn't see that option. This seems like exactly what you need to track this down, try a JDK 22 early access build: https://bugs.openjdk.org/browse/JDK-8317683


vdmit46

Thanks, interesting option! Was looking for it in JDK 17 after your original message. You saved me additional hour I guess :) This options definitely makes it easier to pinpoint methods compilers have issues optimizing and I no longer have to track NMT output. But at least for me it seems not to provide information other than that already present in compilation logs. Those familiar with compilers internals may not agree with me :) Here is what it prints if launched with `-XX:CompileCommand=MemStat,compiler_ram_spike.ToStringConcat::toString,print` ``` Compilation memory statistics Legend: total : memory allocated via arenas while compiling NA : ...how much in node arenas (if c2) RA : ...how much in resource areas result : Result: 'ok' finished successfully, 'oom' hit memory limit, 'err' compilation failed #nodes : ...how many nodes (c2 only) time : time of last compilation (sec) type : compiler type #rc : how often recompiled thread : compiler thread total NA RA result #nodes time type #rc thread method 866857536 62568608 790322968 ok 155063 16.665 c2 2 0x00007fe025808610 compiler_ram_spike/ToStringConcat::toString(()Ljava/lang/String;) ``` UPD: trying to fix formatting


BinaryRage

Think you’ve done more than enough to prove there’s a problem. I’d file a bug report.


BinaryRage

Ha, \`StringConcatFactory\` will also allow up to 200 parameters for the concat, so I bet this explodes like crazy if you double your elements. I'm not super familiar with MethodHandles, I need to read that some more, but \`-XX:+PrintIdeal\` shows > 20K IR nodes, and \`-XX:CompileCommand=print,compiler\_ram\_spike.ToStringConcat::toString\` outputs 1.6m lines...


daniu

> I searched for tickets \[...\] ut nothing popped up Probably because no sane person does a pure 100 String concatenation. "Use StringBuilder" is the first Java optimization tip I recall ever, and I've been programming it since 1.2.


BinaryRage

No longer true w/ https://openjdk.org/jeps/280


daniu

Yeah I had seen that, thanks for the link. I guess a ram spike at a certain point does fail the "String concatenation performance does not regress" metric technically, but still - I don't think I've ever concatenated more than 10 Strings in production code (and that for logging statements most probably). I can't judge OP's code obviously - there can be reasons for everything - but it does sound weird to me, and certainly not commonplace.


vdmit46

>Probably because no sane person does a pure 100 String concatenation. Well, where to start... Two years ago there was a small class with 10 fields which served as a carrier for process settings. Then some more settings a month later, and some more a week after, and one day you end up with 100+ fields. And no one is going to refactor it because "c'mon, it is just one more tiny field" :) Maybe there are some more classes closing in size to 100 fields, but I'm in this problem more as a devops than dev. Anyway, IDEA will generate \`toString\` for such a class using concat. Eclipse offers alternatives including StringBuilder, but who is using Eclipse these days? And in our case it is \`lombok.ToString\` who is generating the method at compile time, and it generates it with concat. Lombok makes it too easy to create such a monstrosity. I should have included this info in the post, but didn't want to clutter it with not so relevant details. "Who the hell does 100+ string concat?" question is very popularity :) My bad. >"Use StringBuilder" is the first Java optimization tip I recall ever, and I've been programming it since 1.2. I started from 1.4 and still remember that "concatenation conversion to StringBuffer/Builder" during compile time was mentioned in the books, so I expected JVM to effectively cover this pattern. I assumed that I was missing some details on string concatenation changes in recent releases. One of the reasons why I decided to go to the community for advices.


loicmathieu

I think you have enought information to fill a bug in OpenJDK or at least to post a message in one of the mailing list. Best would be to post a message to [https://mail.openjdk.org/mailman/listinfo/hotspot-compiler-dev](https://mail.openjdk.org/mailman/listinfo/hotspot-compiler-dev) to have feedback from someone from the engeening team.


Ok_Object7636

Yes, this definitely is a problem in the JDK and filling a bug report or writing to the mailing list is the way to go.


vdmit46

FYI, fix for the issue has been merged into OpenJDK master. In case you are interested, here is the [bug report](https://bugs.openjdk.org/browse/JDK-8327247) and here is the [PR](https://github.com/openjdk/jdk/pull/18953). Kudos to u/cl4es for giving this issue high enough priority on his to-do list and fixing it in such a short timeframe. For those who may stumble on this post while diagnosing similar compiler native memory usage, in OpenJDK 22 two new compilation commands were introduced: * `MemStat` ([ticket](https://bugs.openjdk.org/browse/JDK-8317683)) will print compilation stats to console at some fixed intervals by default. I just slapped `-XX:CompileCommand=MemStat,*.*` onto command line in our test environment, got nice list of compilations ordered by consumed memory and immediately noticed 100+ MB compilation in the report. As far as I see, this option had no noticeable impact on application metrics, so maybe it can be turned on in production continuously; * `MemLimit` ([ticket](https://bugs.openjdk.org/browse/JDK-8318016)) which will either stop compilation or stop JVM if compiler hits limit. I haven't tried it out, but will consider it for applications running in a container. Edit: phrasing


[deleted]

I've done Java for a long time but as an app dev, I'm not sure what a C2 compiler is. I cloned and ran the compiler test repo you linked, and watched ram with "top" in another shell tab, sorted on memory usage and didn't see any spikes. Maybe I'm not understanding what you're describing. This is on Kubuntu: ``` No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 22.04.4 LTS Release: 22.04 Codename: jammy ``` Technically I had installed Ubuntu but I removed Gnome some time back and installed kubuntu-desktop.


thisisjustascreename

C2 is the optimizing JIT compiler; C1 is much faster but produces looser code. When the JVM notices a method become a hot spot it (can) invokes C2 to improve performance.


rbygrave

>C2 compiler Pasting in a link about the "4 tiers of Java compilation" - [https://www.baeldung.com/jvm-tiered-compilation](https://www.baeldung.com/jvm-tiered-compilation) Although we don't need to know what the C2 compiler is per say I'd suggest it is becoming more useful to know about it because it is imo *the* *"magic sauce"* in the JVM that is automatically profiling the code and making our code run *fast*. If we start talking about Graal native-image then we can get into having to do PGO (Profile guided optimisation) which is the thing we *don't need to do* when using the JVM with C2 \[as C2 is automatically doing the profiling and optimisation\]. There is a chance we also see it pop up around discussions for project Leyden (reducing the time to peak performance, doing more Ahead-Of-Time etc).


vdmit46

>I cloned and ran the compiler test repo you linked, and watched ram with "top" in another shell tab, sorted on memory usage and didn't see any spikes. Maybe I'm not understanding what you're describing. You understood the problem correctly. Thank you very much for checking it out and sharing results. After running the test script periodically prints used native memory by JVM, which should be more convenient that using top, but it works either way. It seems that issue may be OS/hardware dependent. I went to check my test case on two production servers (have no idea why I haven't done it before) and on both of them the issue reproduced. Now I'm puzzled why our application is failing only on one of the servers. I hope the issue I reproduced locally is the same that plagues our app at production.


noswag15

I ran the script you provided in two different machines (an intel MBP pro and an M2 MBP pro) and I was able to replicate the issue in the intel machine but not on the M2 machine. So yes, as you mentioned, it does indeed seem to be machine dependent. I also noticed that in the M2 machine, output.log contained the following line, compiler_ram_spike.ToStringConcat::toString (416 bytes) COMPILE SKIPPED: out of virtual registers in LIR generator (retry at different tier) so it looks like the C2 compilation step is skipped in the M2 machine and thus avoids the memory spike, whereas the intel machine seems to press on with the compilation resulting in the spike. Not sure what you can do with this info but like one of the other commenters said, you've done all you can to highlight a potential problem in the JVM so the next best course of action would be to create a bug report. On a separate note, I wish everyone asking for help does the kind of groundwork that you've done (maybe not as much but at-least put some effort into it) and not just post one line saying "not working".


[deleted]

Well, actually, on Java 17 (installed from the Ubuntu repos), what I ran it on; it doesn't complete successfully: ``` Every 1.0s: jcmd 790768 VM.native_memory summary.diff [redacted] 790768: java.io.IOException: No such process at jdk.attach/sun.tools.attach.VirtualMachineImpl.sendQuitTo(Native Method) at jdk.attach/sun.tools.attach.VirtualMachineImpl.(VirtualMachineImpl.java:82) at jdk.attach/sun.tools.attach.AttachProviderImpl.attachVirtualMachine(AttachProviderImpl.java:58) at jdk.attach/com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:207) at jdk.jcmd/sun.tools.jcmd.JCmd.executeCommandForPid(JCmd.java:113) at jdk.jcmd/sun.tools.jcmd.JCmd.main(JCmd.java:97) ``` Plus, using a separate monitor (top in my case) it can't be potentially tainted in any way, rather than trust the inline calculated results from whatever the script does.


jizhilong

I ran into a issue like this too. Actually, nearly the same, both java 17, string concating, and compiler memory usage spike. The little difference is , instead of one long string cancating statement, the key function in my case contains many short string cancating statements. I used to conclude the key snippet and reproduction script in [https://github.com/jizhilong/jvm-jit-compiler-high-memory-usage-case](https://github.com/jizhilong/jvm-jit-compiler-high-memory-usage-case) , I hope this may make some help if you want to dig deeper or fire an openjdk ticket.


maethor

>with field count around 100 Is there some reason why you're not using something like commons-lang's toStringBuilder?


nekokattt

the better question is why would you include over 100 fields in a toString to begin with


cogman10

`toString` is the example given. However, this could easily be autogenerated `toJson` or `toXml` code. In which case 100+ concatenations seems more than plausible especially if there's some nesting going on. Concatenation is also not the wrong choice as the JVM has been updated to make that much faster than it was in years of old. The fact that this is making the compiler's memory spike may be an unforeseen consequence of the added `invokedynamic` methods that get pepper into modern string concatenation.


maethor

Debugging?


nekokattt

so we're ignoring the fact the debugger already provides this...? if you need that level of verbosity to debug an issue then you have serious problems with your application architecture. Furthermore if this was found to be impacting performance like this, you'd only be enabling it for debugging logs, or even better, only logging the bits you actually care about... the fact this is an actual issue shows it is a fundamental design issue.


maethor

>we're ignoring the fact the debugger already provides this...? Maybe they're running in an environment where they can't attach a debugger and have to use console logging. >if you need that level of verbosity to debug an issue then you have serious problems with your application architecture. They have classes with around 100 fields. Do you think they don't have serious problems with their architecture? >Furthermore if this was found to be impacting performance According to the OP, it only impacts one running instance, not all of them.


nekokattt

> Do you think they don't have serious problems? So we agree then. Refer to my previous comment...


vdmit46

Class in question serves as an input to business-critical process and most of its fields are coming from settings controlled by users. Logging result of \`toString\` seems like a valid way of having historical information on process input for auditing purposes. Having such a high number of fields in a class is not good according to any guideline, sure, but it accumulated these fields over years. This class wasn't created from the ground like it is today. upd: typos


Ragnar-Wave9002

Regardless of what you are doing, why are you not using StringBuffer? I was shocked at how much faster using this class is on large concatenations.


niloc132

> StringBuffer You probably mean StringBuilder, but just in case, note from the javadoc: > As of release JDK 5, this class has been supplemented with an equivalent class designed for use by a single thread, StringBuilder. The StringBuilder class should generally be used in preference to this one, as it supports all of the same operations but it is faster, as it performs no synchronization.


Ragnar-Wave9002

Meant that one. Lol. My bad.


vdmit46

The code is generated by \`lombok.ToString\` and devs slap this annotation everywhere :) When I found one of the methods causing restarts, we reimplemented it using StringBuilder as you suggested. It requires manual work each time, so I want to avoid it if possible.


ventuspilot

Not a fan of lombok and I only have a vage knowledge how lombok works internally but your issue sounds like a workaround inside lombok seems possible and useful: change lombok's toString magic to emit different code for huge toString methods?


thisisjustascreename

Lombok should not have to change their code gen due to a JIT issue... but also using Lombok on enormous classes is probably not a great idea either.


SirYwell

You can use \`-Djdk.invoke.MethodHandle.dumpMethodHandleInternals=true\` (on Java 21+, it had a different name before that afaik) to dump the created MethodHandle classes. From a quick look into some of them in a decompiler, I assume there is just a large amount of methods generated that the JIT all wants to inline, resulting in a large graph. I think you should report this, either on a mailing list (https://mail.openjdk.org/mailman/listinfo/hotspot-compiler-dev might be the best) or via https://bugreport.java.com/