[Bug]: Severe Performance Regression in toString

[hunterpayne]

Describe the bug

So apparently, the PrettyPrinter can now change the contents of an element. Ignoring if this is a good idea or not (seems pretty bad at first glance), this means that the toString method now clones itself before passing itself to the PrettyPrinter. This results in significantly reduced performance when turning an element back into code.

Perhaps a different, faster method for producing code or perhaps rethink allowing the PrettyPrinter to change an Element's contents.

Either way, please make the toString method faster and cause it not to use so much memory. Perhaps even make it not use String but instead take a StringBuilder so the strings don't get internalized and consume so much memory.

Source code you are trying to analyze/transform

// The biggest Java file you can find

Source code for your Spoon processing

Launcher l = new Launcher();
l.addInputResource(new FileSystemFile("ReallyBig.java"));
CtType tpe = l.buildModel().getAllTypes().get(0);
System.out.println("time to start the profiler");
Thread.sleep(15000);
tpe.toString();

Actual output

N/A

Expected output

N/A

Spoon Version

11.2.1

JVM Version

java 17

What operating system are you using?

Ubuntu

[SirYwell]

Hi, do you have any profiling information you can share? Also, is this a regression from a previous version, and if so, which one?

[hunterpayne]

7.5 doesn't have the problem. CtElement.toString has seemed to get slower a few times over the last couple of years. The clone call was introduced in 8.x so that's part of the problem. But it has gotten even worse lately.

As for profiling, just do any stress testing of printing out large blocks of code. When the compiler I am writing (which uses Spoon) hits the part to output the code as a string (calling CtElement.toString) the heap size triples and the time to do a single toString calls goes into the multiple seconds for really large classes. Looking at the code, I see you are using a StringBuffer when you should probably be using a StringBuilder in PrintHelper (which should be created per toString call I think). And of course calling clone seems really really wasteful. I just don't see how a print printer should be altering an AST. It just breaks expectations so significantly.

I have to go to a conference this week. I can answer more of your questions on Friday and give you more profiling data.

Thanks for the quick reply

[SirYwell]

7.5 doesn't have the problem. CtElement.toString has seemed to get slower a few times over the last couple of years. The clone call was introduced in 8.x so that's part of the problem.

Okay, that predates my work on the project.

But it has gotten even worse lately.

This sounds more interesting. Can you pinpoint such regressions to more specific versions?

We've done a couple of significant rewrites of some parts of spoon to improve performance, including printing, with no observable regressions on our performance infrastructure (which isn't running currently, I really have to set it up again...).
There are more bottlenecks we encountered, but they aren't exactly low-hanging fruit and would require significant work.

And of course calling clone seems really really wasteful. I just don't see how a print printer should be altering an AST. It just breaks expectations so significantly.

It's cloned because just altering would break expectations, but it just turns out that altering is necessary (or at least the most straightforward way) for some things to work properly with the current structure. Some of it also depends on the printer configuration.

Replacing StringBuffer usages should be simple though, that's clearly something we can look into.

We'd definitely appreciate more profiling information!

[hunterpayne]

I think its gotten worse on my side because the class getting generated is getting bigger. I haven't measured a significant regression other than the cloning added in 8.x. So perhaps the performance hasn't changed recently, but instead I'm just noticing the number of Strings being created.

Based on the number of Strings being created, perhaps there are some performance impacts of Java Strings that you are not aware of. If you care about the performance of a block of code, it shouldn't be using Strings that are not constants. The fact that 10s of millions of Strings are generated during the call to toString is the problem. And as Spoon handles more use cases, it creates more Strings which impacts performance.

If you look at projects like Apache Spark, they don't use Strings in inner loops. Instead they have their own UTFString class that wraps a byte[]. Spoon doesn't need to go that far, but perhaps using a ByteBuffer or ByteArrayOutputStream inside the pretty printer would be a good idea. Or perhaps just something that holds a char[] or character stream of some kind.

I really like your project, but if you are telling me that code that generates 10s of millions of Strings inside of toString is performant...well...I think your team can do better on that front. This video explains of what happens in the JVM when strings are created. This isn't the best description of how the JVM works but its good enough here. Why that's bad for performance when you have lots of unique Strings being generated should be obvious. If you want more detail, maybe we can have a video chat where I can go over why you don't use String if you care about performance (it has to do with Strings in the JVM being intern'ed which is great for a small number of small strings but terrible when you are generating lots of text). I really don't think that is necessary though, the point you will care about is don't use Strings when you care about performance. StringBuffer and StringBuilder exist because of this fact.

It's cloned because just altering would break expectations

Why does the pretty printer alter the AST in the first place? I really don't see how that's a reasonable behavior. And its clearly the source of much of the problems here. Cloning in toString is just papering over the real problem. What does Spoon achieve by having the pretty printer alter the AST? Unless its earthshaking, I just don't see how its a good trade-off.

[hunterpayne]

[SirYwell]

Based on the number of Strings being created, perhaps there are some performance impacts of Java Strings that you are not aware of. If you care about the performance of a block of code, it shouldn't be using Strings that are not constants. The fact that 10s of millions of Strings are generated during the call to toString is the problem. And as Spoon handles more use cases, it creates more Strings which impacts performance.

Note that the heap histogram you showed before shows how much of the live memory is taken up by strings, not how many strings are created. Both JFR and async-profiler have the ability to do allocation sampling, so if you are concerned about that, it would be helpful to see where these strings (or rather, the underlying byte arrays) are allocated. It also looks like VisualVM exposes that functionality directly.

The number of live strings in your application is still somewhat concerning, and probably something we can improve too, but for that we would need a better understanding of where these strings are referenced, and if e.g., they are insufficiently deduplicated (we have a deduplication mechanism already, but it doesn't deduplicate everything).

If you look at projects like Apache Spark, they don't use Strings in inner loops. Instead they have their own UTFString class that wraps a byte[]. Spoon doesn't need to go that far, but perhaps using a ByteBuffer or ByteArrayOutputStream inside the pretty printer would be a good idea. Or perhaps just something that holds a char[] or character stream of some kind.

Again, allocation sampling would be insightful here. You already mentioned the StringBuffer, which is what currently avoids unnecessary string concatenations. ByteBuffer wouldn't solve the problem beyond avoiding synchronization (which should be avoided using StringBuilder instead). ByteArrayOutputStream also is synchronized and extremely slow from my experience.

Why does the pretty printer alter the AST in the first place? I really don't see how that's a reasonable behavior. And its clearly the source of much of the problems here. Cloning in toString is just papering over the real problem. What does Spoon achieve by having the pretty printer alter the AST? Unless its earthshaking, I just don't see how its a good trade-off.

The printer can arbitrarily preprocess the model. Normally, this is mostly used to properly print imports (or fully-qualified names, or both), depending on how the printer is configured.

[hunterpayne]

Both JFR and async-profiler have the ability to do allocation sampling, so if you are concerned about that, it would be helpful to see where these strings (or rather, the underlying byte arrays) are allocated.

I tried to attach a .hprof file containing the per allocation data but github doesn't support that. Its probably easier for you to just take a really big .java file, load/parse it with spoon and profile calling toString on the resulting CtType instance. That is going to give you a cleaner look. There is way too much data in a per allocation view to show in a single screenshot. For my app, it looks to be lots and lots of CtTypeReferences which hold most of the strings.

(we have a deduplication mechanism already, but it doesn't deduplicate everything).

Wait, what?! Spoon has its own deduplication mechanism for Strings? Am I understanding that correctly? If that is the case, please remove it. The JVM already does that for you and the second implementation will just make Spoon slower.

You already mentioned the StringBuffer, which is what currently avoids unnecessary string concatenations.

StringBuffer is synchronized. StringBuilder is not, that's why I recommended switching to it. Also, both of these are things that hold a char[].

The printer can arbitrarily preprocess the model. Normally, this is mostly used to properly print imports (or fully-qualified names, or both), depending on how the printer is configured.

Look at the 2nd screenshot I posted. It shows that the clone takes 2x the time as the scan itself. So caching the list of imports isn't a good trade-off. Just compute the imports on each toString call. That would be far faster than cloning according to what I am seeing.

[SirYwell]

I tried to attach a .hprof file containing the per allocation data but github doesn't support that. Its probably easier for you to just take a really big .java file, load/parse it with spoon and profile calling toString on the resulting CtType instance. That is going to give you a cleaner look. There is way too much data in a per allocation view to show in a single screenshot. For my app, it looks to be lots and lots of CtTypeReferences which hold most of the strings.

I probably won't find enough time for the next few months to deep-dive into that, sadly. So I can't make any promise, but I'm certainly interested in taking a closer look.

Wait, what?! Spoon has its own deduplication mechanism for Strings? Am I understanding that correctly? If that is the case, please remove it. The JVM already does that for you and the second implementation will just make Spoon slower.

The HotSpot-specific string deduplication mechanism that deduplicates the underlying byte arrays is disabled by default, to get string deduplication (or rather interning) on the Java side for non-constant strings requires calling String#intern(). There is a chapter in https://shipilev.net/talks/joker-Oct2014-string-catechism.pdf. I have played around with that before and the last time I checked the performance benefits were still there.

StringBuffer is synchronized. StringBuilder is not, that's why I recommended switching to it. Also, both of these are things that hold a char[].

Yes, switching there is definitely something we should consider. Both are byte array-backed nowadays btw.

Look at the 2nd screenshot I posted. It shows that the clone takes 2x the time as the scan itself. So caching the list of imports isn't a good trade-off. Just compute the imports on each toString call. That would be far faster than cloning according to what I am seeing.

This is basically what's happening already. But calculating imports also means that all the references need to be updated to either make their packages implicit or explicit. This is one of the things that could probably be improved by rewriting (potentially large) parts of spoon. But even then, the preprocessing step is part of the public API, which can't just be removed.

[hunterpayne]

The HotSpot-specific string deduplication mechanism that deduplicates the underlying byte arrays is disabled by default, to get string deduplication (or rather interning) on the Java side for non-constant strings requires calling String#intern(). There is a chapter in https://shipilev.net/talks/joker-Oct2014-string-catechism.pdf. I have played around with that before and the last time I checked the performance benefits were still there.

So, just to be clear, Spoon turns on that deduplication feature? Is this correct because it seems like it is off for CtTypeReference's fields. Also, it seems that the Strings inside of CtTypeReference aren't deduplicated. That would explain what I'm seeing. The majority of the String objects appeared to contain classnames and there were plenty of duplicate names. I would guess that perhaps the best place for deduplication could be CtTypeReference's String fields.

[hunterpayne]

all the references need to be updated to either make their packages implicit or explicit.

Or the CtTypeReference could generate fqcn or not based upon a map stored in the pretty printer.

[SirYwell]

So, just to be clear, Spoon turns on that deduplication feature?

No, the String deduplication feature (actually it deduplicates the underyling arrays, not the String instances) provided by HotSpot are an implementation detail that can't be controlled from Java code. Spoon uses its own deduplication mechanism that works by randomly inserting 20% of the Strings not already deduplicated. This is a space-time tradeoff. If we missed a place to call into our deduplication mechanism, it might be worth to change that.

[hunterpayne]

It is very likely there are some missed deduplication calls in CtTypeReferenceImpl.java.

PS I ended up working around this issue by using an implicit Class in my code to use my own toString implementation.