Huge performance degradation after upgrade dependency-check-maven from 6.3.1 to 6.4.x / 6.5.x

[sammyhk]

Describe the bug
There is a hug performance degradation after upgrade dependency-check-maven from 6.3.1 to 6.4.x / 6.5.x.
Before the upgrade (v6.3.1) it just take ~7 minutes for running org.owasp:dependency-check-maven:aggregate but it bump to ~1.5 hour for running the same command in v6.4.x / v6.5.x.
Note that due to issue #3679, v6.3.2 got NPE in my project so cannot have the statistic data.

Detail of the execution time:
v6.3.1: 07:06 minutes
v6.3.2: 02:04 minutes and then NPE exception
v6.4.0: 01:21 hours
v6.4.1: 01:19 hours
v6.5.0: 01:16 hours
v6.5.1: 01:17 hours

Version of dependency-check used
The problem occurs using version 6.4.0 / 6.4.1 / 6.5.0 / 6.5.1 of the maven plugin

Log file
Log will be provided when needed.

To Reproduce
Steps to reproduce the behavior:

1. execute org.owasp:dependency-check-maven:6.3.1:aggregate on a multi-module project, notice the execution time
2. execute org.owasp:dependency-check-maven:6.4.0:aggregate on the same multi-module project, notice the execution time

Expected behavior
Should not talking some much time to execute.

Additional context
N/A

[jeremylong]

Are you keeping the dependency-check database between executions or are you abusing the NVD and downloading the full data set on each execution? As the NVD implemented some fairly strict rate limiting with the 6.4.x we had to slow down the downloads from the NVD. That being said - I've never seen it take over an hour.

Can you provide the full verbose log file for 6.5.1 so we can see where the extra time is being spent?

[sammyhk]

1. There is no network involved, the jar is already resolved/ downloaded, the dependency-check database is also downloaded. Actually we also have a proxy server to proxy the dependency-check database in local network. Everything is just CPU/ IO time with a SSD in a local machine.
2. Maven log attached (for v6.3.1 and v6.5.1) (https://gist.github.com/sammyhk/b4f5c7bd21eaacd7aea289c1341d7e7b) with timestamp enabled for tracking. The commands are basically the same (org.owasp:dependency-check-maven:6.3.1:aggregate vs org.owasp:dependency-check-maven:6.5.1:aggregate

[aikebah]

Can you do a run with the verbose log as indicated by Jeremy (including -X on your maven command-line) with 6.5.1?
Based on the changes I would expect a lot of Expensive lookup as workaround for MSHARED-998 for <xxxxx> DEBUG level log messages in your case for dependencies including a classifier.

If not we would definitely be interested in the underlying debug log to try and trace down where the extra time is spent.

[jeremylong]

@aikebah looking at the code:

DependencyCheck/maven/src/main/java/org/owasp/dependencycheck/maven/BaseDependencyCheckMojo.java

Lines 1356 to 1357 in 36d4307

	final Iterable<ArtifactResult> allDeps
	= dependencyResolver.resolveDependencies(buildingRequest, dependencies, managedDependencies,

If that is the culprit - instead of resolving on each dependency that hits this line could we save the resolution results and re-use them? Alternatively - can a filter be created (like the else clause ~18 lines below) that includes the scope?

[aikebah]

@jeremylong Regarding the first: I guess caching it should be doable - if you take into consideration the alternative caching of resolution results from the exception handling as well.
Regarding the second: no... that's what I first tried which ultimately led to MSHARED-998

I was planning on seeing whether we could massively sanitize this code by doing the resolution once (never use a filter), caching the result and looking up all from either the successfully resolved dependencies or the resolved dependencies status contained in the ArtifactResolutionException, but didn't get time yet to further investigate on that.

Just let me know if you're planning to work on the first approach (caching) as a quick-win. If not, I'll look and see if I can spend time on that tonight after work. So that we can try and include it in 6.5.2.

[jeremylong]

I'm not going to have time with other things I'm working on to dig into this one. If you do have time - great.

[aikebah]

@sammyhk Would you be so kind to try what a snapshot built from https://github.com/jeremylong/DependencyCheck/tree/issue-3923 would yield for your project?

[aikebah]

@jeremylong local run of aggregate goal on DependencyProject itself (failing on DependencyNotFoundException: Unable to resolve system scoped dependency: com.sun:tools:jar:1.8.0:system on my system) looks promising saw runtimes 13-14 secs with new code versus 17-21secs for 6.5.1 in a few trial runs
Though I think the change would need some more thorough testing as indicated in the draft PR.

[sammyhk]

Debug log added and a profiling result using VisualVM attached (https://gist.github.com/sammyhk/b4f5c7bd21eaacd7aea289c1341d7e7b). Please check. Will build the branch locally and check.

[sammyhk]

WoW, the fix works, the execution time drop back to become 5 minutes. 👍
Will also attach the logs later.

[sammyhk]

Added log for 6.5.2-SNAPSHOT