Severe performance regression in JavaPackage

[danstooamerican]

We use the verify and documentation test. In version 1.3.2 it takes around 15s and passes without problems. When upgrading to version 1.3.3, the test never finishes (>5min). Nothing else changed.

Our test:

private final Set<String> coreModules = Set.of("Module A", "Module B", "Module C");

@Test
void createModuleDocumentation() {
    new Documenter(ApplicationModules.of(Application.class).verify()).writeDocumentation(
            Documenter.DiagramOptions.defaults()
                    .withComponentFilter(component -> !coreModules.contains(component.getName())),
            Documenter.CanvasOptions.defaults()
    );
}

[odrotbohm]

Just to clarify: is it the call to ….verify() that's taking the time here? Or is it the ApplicationModules instance creation or the work done by Documenter?

[cpy-xcend]

#We faced same issue after upgraded to 1.3.3

public class ModulesTest {

  private final ApplicationModules modules = ApplicationModules.of(Application.class);

  @Test
  @DisplayName("Should structure modules correctly")
  void moduleStructure() {
    modules.verify();
  }

  @Test
  @Disabled(
      "this needs to be investigated, after spring modulith upgrade to 1.3.3 it is running forever")
  void documentModules() {
    new Documenter(modules).writeModulesAsPlantUml(Documenter.DiagramOptions.defaults());
  }
}

modules.verify() test passed

but writeModulesAsPlantUml runs endlessly.

[odrotbohm]

That would be a significantly different starting point for the analysis. The only thing we changed in the documentation generation is removing the dependency to Commons Logging that Structurizr pulled in (GH-1069). Would you mind trying to add it back (basically logically revert what we did in 8d3fcfb) and see whether that makes a difference?

The only other thing that I could remotely think of affecting this is the change we made to the sub-package detection, but that should be triggered during the ApplicationModules instance creation already.

Could you run the problematic test case in debug mode, pause the JVM at some point while it's running unexpectedly long, and inspect the stack trace for Spring Modulith related stack frames? Alternatively, a reproducing project would be very nice, but I can see that it might be difficult to prepare one. The test cases don't reveal any obvious problems, and I've checked a couple of medium size projects that we usually use as smoke tests, but they all generate docs just fine.

[danstooamerican]

I can confirm, that the Documenter has a problem.

I manually added the commons-logging dependency but it had no effect.

[danstooamerican]

This is a stack trace multiple minutes into the test. It takes 4s to complete using 1.3.2.

match:1794, Matcher (java.util.regex)
matches:754, Matcher (java.util.regex)
matches:167, PackageMatcher (com.tngtech.archunit.core.domain)
lambda$test$0:2596, JavaClass$Predicates$PackageMatchesPredicate (com.tngtech.archunit.core.domain)
test:-1, JavaClass$Predicates$PackageMatchesPredicate$$Lambda/0x00000004012be9b0 (com.tngtech.archunit.core.domain)
accept:90, MatchOps$1MatchSink (java.util.stream)
tryAdvance:1736, HashMap$KeySpliterator (java.util)
forEachWithCancel:129, ReferencePipeline (java.util.stream)
copyIntoWithCancel:527, AbstractPipeline (java.util.stream)
copyInto:513, AbstractPipeline (java.util.stream)
wrapAndCopyInto:499, AbstractPipeline (java.util.stream)
evaluateSequential:230, MatchOps$MatchOp (java.util.stream)
evaluateSequential:196, MatchOps$MatchOp (java.util.stream)
evaluate:234, AbstractPipeline (java.util.stream)
anyMatch:632, ReferencePipeline (java.util.stream)
test:2596, JavaClass$Predicates$PackageMatchesPredicate (com.tngtech.archunit.core.domain)
test:2586, JavaClass$Predicates$PackageMatchesPredicate (com.tngtech.archunit.core.domain)
lambda$that$0:109, Classes (org.springframework.modulith.core)
test:-1, Classes$$Lambda/0x00000004012be528 (org.springframework.modulith.core)
accept:178, ReferencePipeline$2$1 (java.util.stream)
forEachRemaining:722, AbstractList$RandomAccessSpliterator (java.util)
copyInto:509, AbstractPipeline (java.util.stream)
wrapAndCopyInto:499, AbstractPipeline (java.util.stream)
evaluateSequential:921, ReduceOps$ReduceOp (java.util.stream)
evaluate:234, AbstractPipeline (java.util.stream)
collect:682, ReferencePipeline (java.util.stream)
that:110, Classes (org.springframework.modulith.core)
<init>:77, JavaPackage (org.springframework.modulith.core)
lambda$detectSubPackages$8:420, JavaPackage (org.springframework.modulith.core)
apply:-1, JavaPackage$$Lambda/0x00000004012c4d70 (org.springframework.modulith.core)
accept:197, ReferencePipeline$3$1 (java.util.stream) [4]
accept:174, DistinctOps$1$2 (java.util.stream)
forEachRemaining:411, Streams$StreamBuilderImpl (java.util.stream)
forEachRemaining:735, Streams$ConcatSpliterator (java.util.stream)
forEach:762, ReferencePipeline$Head (java.util.stream)
accept:276, ReferencePipeline$7$1 (java.util.stream)
accept:197, ReferencePipeline$3$1 (java.util.stream) [3]
accept:179, ReferencePipeline$2$1 (java.util.stream)
accept:197, ReferencePipeline$3$1 (java.util.stream) [2]
forEachRemaining:722, AbstractList$RandomAccessSpliterator (java.util)
copyInto:509, AbstractPipeline (java.util.stream)
wrapAndCopyInto:499, AbstractPipeline (java.util.stream)
evaluateSequential:921, ReduceOps$ReduceOp (java.util.stream)
evaluate:234, AbstractPipeline (java.util.stream)
collect:682, ReferencePipeline (java.util.stream)
lambda$new$0:82, JavaPackage (org.springframework.modulith.core)
get:-1, JavaPackage$$Lambda/0x00000004012bec00 (org.springframework.modulith.core)
hashCode:482, JavaPackage (org.springframework.modulith.core)
hashCode:4599, Arrays (java.util)
hash:133, Objects (java.util)
hashCode:630, ApplicationModule (org.springframework.modulith.core)
hash:338, HashMap (java.util)
put:618, HashMap (java.util)
add:229, HashSet (java.util)
accept:173, DistinctOps$1$2 (java.util.stream)
accept:197, ReferencePipeline$3$1 (java.util.stream) [1]
forEachRemaining:1708, ArrayList$ArrayListSpliterator (java.util)
copyInto:509, AbstractPipeline (java.util.stream)
wrapAndCopyInto:499, AbstractPipeline (java.util.stream)
evaluate:575, AbstractPipeline (java.util.stream)
evaluateToArrayNode:260, AbstractPipeline (java.util.stream)
toArray:616, ReferencePipeline (java.util.stream)
toArray:622, ReferencePipeline (java.util.stream)
toList:627, ReferencePipeline (java.util.stream)
<init>:50, ApplicationModuleDependencies (org.springframework.modulith.core)
of:61, ApplicationModuleDependencies (org.springframework.modulith.core)
apply:-1, ApplicationModule$$Lambda/0x00000004013186e8 (org.springframework.modulith.core)
lambda$andThen$1:88, Function (java.util.function)
apply:-1, Function$$Lambda/0x00000004010ea268 (java.util.function)
collect:686, ReferencePipeline (java.util.stream)
getDependencies:596, ApplicationModule (org.springframework.modulith.core)
getDirectDependencies:193, ApplicationModule (org.springframework.modulith.core)
lambda$addDependencies$7:446, Documenter (org.springframework.modulith.docs)
accept:-1, Documenter$$Lambda/0x0000000401317b08 (org.springframework.modulith.docs)
forEachRemaining:133, Iterator (java.util)
forEachRemaining:1939, Spliterators$IteratorSpliterator (java.util)
forEach:762, ReferencePipeline$Head (java.util.stream)
addDependencies:444, Documenter (org.springframework.modulith.docs)
lambda$getComponents$12:467, Documenter (org.springframework.modulith.docs)
accept:-1, Documenter$$Lambda/0x00000004013178d8 (org.springframework.modulith.docs)
forEach:1429, HashMap (java.util)
getComponents:467, Documenter (org.springframework.modulith.docs)
addComponentsToView:491, Documenter (org.springframework.modulith.docs)
createPlantUml:579, Documenter (org.springframework.modulith.docs)
writeModulesAsPlantUml:298, Documenter (org.springframework.modulith.docs)
writeDocumentation:195, Documenter (org.springframework.modulith.docs)
createModuleDocumentation:25, DocumentationTest (de.tailord.tailordplan)
invokeVirtual:-1, LambdaForm$DMH/0x0000000401218000 (java.lang.invoke)
invoke:-1, LambdaForm$MH/0x00000004012d8800 (java.lang.invoke)
invokeExact_MT:-1, Invokers$Holder (java.lang.invoke)
invokeImpl:153, DirectMethodHandleAccessor (jdk.internal.reflect)
invoke:103, DirectMethodHandleAccessor (jdk.internal.reflect)
invoke:580, Method (java.lang.reflect)
invokeMethod:767, ReflectionUtils (org.junit.platform.commons.util)
proceed:60, MethodInvocation (org.junit.jupiter.engine.execution)
proceed:131, InvocationInterceptorChain$ValidatingInvocation (org.junit.jupiter.engine.execution)
intercept:156, TimeoutExtension (org.junit.jupiter.engine.extension)
interceptTestableMethod:147, TimeoutExtension (org.junit.jupiter.engine.extension)
interceptTestMethod:86, TimeoutExtension (org.junit.jupiter.engine.extension)
apply:-1, TestMethodTestDescriptor$$Lambda/0x000000040110d970 (org.junit.jupiter.engine.descriptor)
lambda$ofVoidMethod$0:103, InterceptingExecutableInvoker$ReflectiveInterceptorCall (org.junit.jupiter.engine.execution)
apply:-1, InterceptingExecutableInvoker$ReflectiveInterceptorCall$$Lambda/0x000000040110dd80 (org.junit.jupiter.engine.execution)
lambda$invoke$0:93, InterceptingExecutableInvoker (org.junit.jupiter.engine.execution)
apply:-1, InterceptingExecutableInvoker$$Lambda/0x000000040114c290 (org.junit.jupiter.engine.execution)
proceed:106, InvocationInterceptorChain$InterceptedInvocation (org.junit.jupiter.engine.execution)
proceed:64, InvocationInterceptorChain (org.junit.jupiter.engine.execution)
chainAndInvoke:45, InvocationInterceptorChain (org.junit.jupiter.engine.execution)
invoke:37, InvocationInterceptorChain (org.junit.jupiter.engine.execution)
invoke:92, InterceptingExecutableInvoker (org.junit.jupiter.engine.execution)
invoke:86, InterceptingExecutableInvoker (org.junit.jupiter.engine.execution)
lambda$invokeTestMethod$8:217, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
execute:-1, TestMethodTestDescriptor$$Lambda/0x00000004012d71c0 (org.junit.jupiter.engine.descriptor)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
invokeTestMethod:213, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
execute:138, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
execute:68, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
lambda$executeRecursively$6:156, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, NodeTestTask$$Lambda/0x0000000401138a70 (org.junit.platform.engine.support.hierarchical)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$8:146, NodeTestTask (org.junit.platform.engine.support.hierarchical)
invoke:-1, NodeTestTask$$Lambda/0x0000000401138850 (org.junit.platform.engine.support.hierarchical)
around:137, Node (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$9:144, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, NodeTestTask$$Lambda/0x0000000401138438 (org.junit.platform.engine.support.hierarchical)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
executeRecursively:143, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:100, NodeTestTask (org.junit.platform.engine.support.hierarchical)
exec:274, ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask (org.junit.platform.engine.support.hierarchical)
execSync:247, ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask (org.junit.platform.engine.support.hierarchical)
invokeAll:159, ForkJoinPoolHierarchicalTestExecutorService (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$6:160, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, NodeTestTask$$Lambda/0x0000000401138a70 (org.junit.platform.engine.support.hierarchical)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$8:146, NodeTestTask (org.junit.platform.engine.support.hierarchical)
invoke:-1, NodeTestTask$$Lambda/0x0000000401138850 (org.junit.platform.engine.support.hierarchical)
around:137, Node (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$9:144, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, NodeTestTask$$Lambda/0x0000000401138438 (org.junit.platform.engine.support.hierarchical)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
executeRecursively:143, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:100, NodeTestTask (org.junit.platform.engine.support.hierarchical)
exec:274, ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask (org.junit.platform.engine.support.hierarchical)
execSync:247, ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask (org.junit.platform.engine.support.hierarchical)
invokeAll:159, ForkJoinPoolHierarchicalTestExecutorService (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$6:160, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, NodeTestTask$$Lambda/0x0000000401138a70 (org.junit.platform.engine.support.hierarchical)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$8:146, NodeTestTask (org.junit.platform.engine.support.hierarchical)
invoke:-1, NodeTestTask$$Lambda/0x0000000401138850 (org.junit.platform.engine.support.hierarchical)
around:137, Node (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$9:144, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, NodeTestTask$$Lambda/0x0000000401138438 (org.junit.platform.engine.support.hierarchical)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
executeRecursively:143, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:100, NodeTestTask (org.junit.platform.engine.support.hierarchical)
exec:274, ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask (org.junit.platform.engine.support.hierarchical)
doExec$$$capture:387, ForkJoinTask (java.util.concurrent)
doExec:-1, ForkJoinTask (java.util.concurrent)
topLevelExec:1312, ForkJoinPool$WorkQueue (java.util.concurrent)
scan:1843, ForkJoinPool (java.util.concurrent)
runWorker:1808, ForkJoinPool (java.util.concurrent)
run:188, ForkJoinWorkerThread (java.util.concurrent)

[danstooamerican]

I observed the test completing successfully. It just takes a lot longer (74x). I changed my config using .withDependencyTypes(DependencyType.USES_COMPONENT). Perhaps this reduced the execution time enough that my patience didn't run out 😆

Version 1.3.2

Version 1.3.3

[odrotbohm]

That's all incredibly helpful information, folks. I promise, we're not mining bitcoin on your machines! 😆 I strongly suspect JavaPackage.hashCode() to needlessly perform recomputations, and I'll have to understand why this is triggered on 1.3.3. That said, I'll provide a 1.3.4 snapshot ASAP for you to try.

[odrotbohm]

For the record, 1cc5719 apparently took the sub-package detection out of the SingletonSupplier so that a call to hashCode() now re-triggers the full detection algorithm each and every time, which is, of course, broken.

[odrotbohm]

This has been fixed and back-ported to 1.3.x. Please give the snapshots a try.

[danstooamerican]

This has been fixed and back-ported to 1.3.x. Please give the snapshots a try.

Finished in under 4s. Great work, thank you!

[odrotbohm]

Just out of curiosity: are you free to share how many packages this projects consists of?

[danstooamerican]

23 top level packages and 136 in total.

Tbh we are still struggling to grasp the idea of internal and external packages. We have very few internal packages which has been a point of discussion in our team forever.

[odrotbohm]

Hm, I just tried a dummy project (26 packages with 26 nested packages each, containing a single type in turn) and I stay within under half a second for the PlantUML diagram creation. So I suspect that there are other factors (a larger number of package / module dependencies) contributing to the diagram creation time.

[danstooamerican]

Hm, I just tried a dummy project (26 packages with 26 nested packages each, containing a single type in turn) and I stay within under half a second for the PlantUML diagram creation. So I suspect that there are other factors (a larger number of package / module dependencies) contributing to the diagram creation time.

This is our components diagram at the moment. We have around 1500 classes. I would love to talk about best practices and options to reduce dependencies in the discussion section.