Performance degression on Upgrade from 1.10.19 to current 3.6.28

[keiki85]

Hello Mockito team,

Quick stats:
Java 11
Mockito 1.10.19 to 3.6.28
1:30 minutes to 9 minutes

in our company we still use Mockito 1.10.19, which includes cglib.

In our unit tests we kind of have our own testing framework that encapsulates e.g. the persistence layer. And in the actual unit tests we don't need to actual mock. With that in mind the framework is already a lot of preparations which is not be needed for every test.
We use mainly mock creations and methodinterceptors as far as I can tell.

At the moment an upgrade wouldn't make sense for us. As the duration of the tests would increase from 1 minute and 30 sec to roughly 9 minutes so 6 times worse.

I had a first look what's taking so long. In my opinion there are two things:
1.
org/mockito/internal/creation/bytebuddy/MockMethodInterceptor.java:55
In return doIntercept(mock, invokedMethod, arguments, realMethod, new LocationImpl()) you construct and initliaise a new LocationImpl, which is quite expensive according to my CPU profiling (IntelliJ profiler)

After replacing that part with a dummy Locationimpl, which does nothing and is a static instance I got down to something like 5 min from 9.

I dunno exactly what the stacktrace information is being used for. It seems in 1.x this is not being done.

2. the mock creation itself

Here it seems to me that bytebuddy is doing way more complicated and of course as I understand more feature rich type traversal, which is making things go slow, but on the other hand work .

Here I'm wondering, if there is a global config switch to do just simple mocking like cglib has done previously.

I know that in general the architecture has changed significantly from version 1 to 2/3 to have features/bugfixes that were impossible beforehand. So I'm not sure what performance wise is feasible without going completely a different way.

Thank you in advance for your help ;)

[TimvdLippe]

Thanks for filing this issue! We are aware that Mockito 2 is slower at creating mocks, but this is mostly due to the fact that the old CGLib mockmaker was not spec-compliant and was creating classes that violated numerous JVM semantics. As such, CGLib was sometimes flat out wrong and was producing invalid results in tests. We made the trade-off to value correctness over performance in this specific instance, given that tests are used to ensure correctness of production code.

That said, if there are opportunities to improve the situation, we are definitely open for that. Could you let us know how many mocks you create as part of your test suite and maybe how many interactions you perform with these mocks?

With regards to point 1, I have made improvements to stacktrace filtering to reduce memory consumption and computational performance: #1683 Could you let me know if you are using the fast path as implemented in https://github.com/mockito/mockito/pull/1683/files#diff-07e4c695f9c72d318aae811112aed91402c79c724cd8338e9a60a8153435d6dd ? For what is worth, we need to collect the stacktrace information on method invocation, as we show that during verification. E.g. the information for the "was invoked here" message.

With regards to point 2, I don't think we will revert back to violating the specification. @raphw do you have any thoughts on that? I know you have made numerous performance improvements to ByteBuddy already, but I am not sure if there are other avenues we could explore.

[keiki85]

Thank you for your detailed answer.

It sadly was not using the fastpath you implemented. I dunno why this sun class is missing. I'm using linux x86_64 and I tried different versions.

How can I easily give you the stats about the mock creation/interaction? As the IntelliJ profiler only gives me how many samples were taken from my understanding.

[TimvdLippe]

I am not sure which JVMs ship the required classes, as it might be that OpenJDK no longer includes them. I do see some references in OpenJDK8 for example: http://hg.openjdk.java.net/jdk8/jdk8/jdk/file/tip/src/share/classes/sun/misc/SharedSecrets.java You might have to test a couple of JVMs to see which one would be compatible.

You can use MockitoFramework.addListener to attach a MockCreationListener where you could implement a simple static counter for example.

[raphw]

The majority of the performance decrease comes from processing generics data and annotations which cglib ignores. This data is resolved lazily by the JVM and rather expensive, what does of course generate overhead.

That your runtime goes up to 9 minutes from 1.30 sounds strange anyways. Byte Buddy's test suite generates and loads many thousand classes - among other things - and runs in less then 40 seconds. Are you creating many JVMs in your tests or mock some form of code generation? Few users of Mockito really noticed a difference when we introduced the additional functionality and the few that did ran rather corner-casy test sets.

[arivaldh]

Hello Mockito Team,

My team is experiencing similar (or fairly identical issue). We are upgrading from 2.23.4 to 3.7.0. Java 8 (8u202 to be precise).
Normally our tests run in about 2.5 minutes.
Once we have migrated to 3.7.0 our tests require about 3 times more time (about 8 minutes).

We have tried several things to pinpoint the problem:

• changed fork mode for test execution to "class" fixed this issue.
  This points to "cluttered" JVM, or that Mockito doesn't "clean" up after a test(s).
• Once we remove several (actually 3 of them) JUnit5 tests that use Mockito, tests after those 3, speed up considerably.
  Our guess is that those tests mock one of the most used classes, so every performance loss in here will be multiplied later.
  Once again this points to a bad "cleanup" after test(s).
• changing tests "after" to JUnit4 doesn't fix the issue.

Tests that are experiencing performance loss the most are E2E scenarios, and we have 5 batches of them. 2 batches are run at the beginning of UT (they take about 35s each), and 3 batches are run later in the "All in package" run. Those even though they should take more or less the same amount of time take about 2minutes each. That's a significant slowdown.

They perform a lot of calculations, they do rely on JIT for performance and they don't use mockito at all.

This is really bothering us and we would be glad for assistance.

[TimvdLippe]

@arivaldh Thanks for your detailed analysis. A couple of questions:

1. Which mockmaker are you using?
2. Could you share more details about some of the classes you mock, particularly in how large/complex they are?
3. Would it maybe be possible to share a JVM performance trace that we can analyze? You can use any tool you want, but if you don't typically use any, I can recommend https://visualvm.github.io/

Since the reported performance regressions happen after Mockito 2, this is not related to our CGLib -> ByteBuddy change. Hence, I regard this is a regression we should definitely tackle, as this is not intentional. Apologies for the performance impact and let's hope we can figure out solutions soon!

[arivaldh]

@TimvdLippe

I can add additional info:
* mockStatic calls do slow things down. But only marginally - when we have removed those tests (not just @ Disable'd them) and removed mockito-inline dependency, slowness related to other tests stayed the same.

Answers for questions:

1. We have added dependency to mockito-inline. If you require more detailed answer I would need some guidance on how to get it.
2. Most problematic is rather simple class. Really.
3. I have used VisualVM 2.0.6 and used "Sampler" to sample CPU.
   Significant amount of time (75% or a little more) is spent in org.mockito.internal.creation.bytebuddy.MockMethodAdvice.isMocked() and org.mockito.internal.creation.bytebuddy.MockMethodAdvice.isMock() function calls.

Every call on any method of any instance of the class that was previously mocked at any point during JVM life seems to be prone to this problem.

[arivaldh]

Wouldn't it be possible to "cleanup" those interceptors after test/suite/on demand?

[TimvdLippe]

Interesting, that is a surprising finding. These methods and the corresponding WeakConcurrentMap is not supposed to have such a big performance impact. This leads me to believe we are incorrectly holding references to mocks in some place.

@raphw Since you have the most domain knowledge here, does anything immediately stand out given the above datapoints?

[arivaldh]

@TimvdLippe
Impact isn't that significant, but considering the cost of a getter (easy to inline, etc), vs isMocked + isMock this makes it 3 times more complicated. Multiply it by millions of calls and you get this issue.
Problem is that even though there's no mock of type X, we constantly check if particular instance of X is a mock - on each and every method call. This makes it slow.

Solution from my perspective would be to have the ability to "reset" Mockito state to the start of JVM. I'd probably call it before those suites, or call it at the end of every Mockito powered test class. Whatever would be considered "cleaner" by the team.

[TimvdLippe]

@arivaldh Could you by any chance let us know what the size of the interceptors map is? Is it growing excessively large at the end of the test suite or does the size stay roughly the same?

[raphw]

Well, if a class is mocked once by the inline mock macker, it remaines "prepped" for future usage. We could certainly introduce a mechanism to rewind this prepping. It does of course bring plenty of overhead to introduce these checks into every single method (I am assuming that you are using the inline mock maker), this is very expected, especially in concurrently running code, and not quite avoidable since the weak concurrent map requires volatile reads. I still don't expect that many people would notice the difference, it is likely happening when mocking classes with many methods that are used thoroughly as non-mocks in other places.

I suggest that we introduce Mockito.reset(Class<?>...) and Mockito.resetAll() methods that undo the instrumentation. With these methods users that run into this issue have a chance to clean up themselves. I don't suggest that we undo mocks once the mocking is over, the reinstrumentation would be overly costly for the majority of users.

[arivaldh]

@raphw @TimvdLippe
I can confirm (and I have edited earlier comments) that mockito-inline (thus InlineMockMaker) is the culprit.

My previous attempts at pinpointing this issue only removed mockito-inline dependency, but I didn't remove properties file that define used MockMaker (org.mockito.plugins.MockMaker file with "mock-maker-inline" contents). I don't really know if both are necessary or just one of those (file OR dependency).

I suggest that we introduce Mockito.reset(Class<?>...) and Mockito.resetAll() methods that undo the instrumentation. With these methods users that run into this issue have a chance to clean up themselves. I don't suggest that we undo mocks once the mocking is over, the reinstrumentation would be overly costly for the majority of users.

Such a solution from my perspective is totally enough :)

I think that this discussion should be moved to a different issue as it's most likely unrelated to 2178. Although, not sure.

[raphw]

@keiki85 You can try the -Dnet.bytebuddy.raw=true property where Byte Buddy does not resolve some generic data, maybe it cuts off the minutes you are looking for. Otherwise, it's certainly an issue with the method graph resolver which are however not currently possible to trivialise at the cost of accuracy.

[arivaldh]

@raphw @TimvdLippe
I'd like to ask when (for which milestone/version) is the reset/resetAll function scheduled?

[TimvdLippe]

We would welcome a PR that would implement that function. I am not sure either Raphael or me have free cycles to work on that at the moment.

[keiki85]

@keiki85 You can try the -Dnet.bytebuddy.raw=true property where Byte Buddy does not resolve some generic data, maybe it cuts off the minutes you are looking for. Otherwise, it's certainly an issue with the method graph resolver which are however not currently possible to trivialise at the cost of accuracy.

Sorry for the late reply.

Thank you for that hint. It helped to cut down half a minute. So instead of 9 minutes coming down to 8:30 roughly.

I'm guessing to significantly increase the performance there are only three options:

• As you said trivialize the generation of the mocks itself, which I guess is not an easy task and may be not worth it
• Check why the LocationImpl performance optimization isn't kicking in. I guess the Sun class is not available. I check my VMs.
• Completely overhaul our current way of mocking to mock only where necessary. E.g. at the moment you wanna mock User Database access. You use the mocking "helper" of the UserDAO, which prepares everything, but you only may need to mock one method or so.

[keiki85]

In Java 9 sun.misc.JavaLangAccess and sun.misc.SharedSecrets were moved to jdk.internal.misc package. Also jigsaw took place.

jdk.internal.misc.JavaLangAccess does not provide the getStackTraceElement method anymore. At least in Java 11.

In Java 9 they provide the Stackwalker interface instead, which is probably more expensive.

https://docs.oracle.com/javase/9/docs/api/java/lang/StackWalker.html
http://openjdk.java.net/jeps/259

[TimvdLippe]

I would have to follow up internally as to what JVM we are using and why these symbols are available. Not sure when I know more about that.

[TimvdLippe]

I followed up internally and the relevant classes have been moved. I will prepare a PR to update the references.

In the mean time, @arivaldh could you please take a look at #2194 and let us know if it helps in your situation?

[raphw]

This should address the instrumentation issue: #2194

As for the other performance regression, if the mocking takes so much time, there must be thousands of VMs being forked for mocks being recreated over and over again, otherwise, I cannot see how this accumulates to so much. I'd say this is best addressed in the test infrastructure, I cannot see how we can make so many significant changes to match the old time without giving up on all progress we have made otherwise.

Also, from Java 16 on, you will need to use the inline mock maker to be compliant which is based on instrumentation. Bootstrap costs will increase even more in this mock maker, unfortunately, so there is no real way to overcome this need.

JavaLangAccess is no longer available in Java 9 but we should add a fallback to using the stack walker API.

[arivaldh]

@TimvdLippe #2194 fixes my issue.
I'd be happy if this would be merged and released.

[TimvdLippe]

I merged #2194. I will try to find some time tomorrow to fix the stackwalking API usage to include that in the Maven Central release

[arivaldh]

@TimvdLippe @raphw
Thanks for merge of #2194 and Mockito release.
I'm pleased to inform that we have started to use Mockito 3.8 and we have enabled previously disabled tests.
Performance is now as expected.

Many thanks again!

[TimvdLippe]

@arivaldh That's great to hear, thank you for your message!

[keiki85]

Thank you for the great support. I don't have any performance issues anymore. Yet I'm not sure yet what's causing it. Could be some independent changes of a colleague. I don't know.

Yet the performance is at least very similar to 1.x performance ;-) :-)

If I find the cause I will keep you posted.