Dependency track takes more than 30 minutes to analyze and Dependency tracker jenkins aborts due to polling time limti.

The defect may already be reported! Please search for the defect before creating one.

Current Behavior:

Jenkins Dependecy tarck jobs fails since server takes more 30 minutes analyze the project.

Steps to Reproduce:

Run jenkins Dependecy track job in Jenkins pipeline for java project which has more than 1000 components(These are java modules)

Expected Behavior:

Jenkins PipleLine should not fail.

Environment:

Dependency-Track Version: 'latest'
Distribution: [ Docker ]
BOM Format & Version: "bomFormat": "CycloneDX", "specVersion": "1.4", "version": 1,
Database Server: PostgreSQL
Browser: Chrome

Additional Details:

22-06-28 06:37:51,463 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed portfolio metrics update 2022-06-28 06:37:56,340 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 06:52:29,046 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processing CycloneDX BOM uploaded to project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 06:56:59,202 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processing CycloneDX dependency graph for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 07:04:14,351 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processed 18477 components and 0 services uploaded to project cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 07:22:08,107 [] INFO [org.dependencytrack.tasks.scanners.InternalAnalysisTask] Starting internal analysis task 2022-06-28 07:22:42,573 [] INFO [org.dependencytrack.tasks.scanners.InternalAnalysisTask] Internal analysis complete 2022-06-28 07:22:42,579 [] WARN [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] An API username or token has not been specified for use with OSS Index. Using anonymous access 2022-06-28 07:22:42,579 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Starting Sonatype OSS Index analysis task 2022-06-28 07:23:21,187 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Sonatype OSS Index analysis complete 2022-06-28 07:23:21,189 [] INFO [org.dependencytrack.policy.PolicyEngine] Evaluating 18477 component(s) against applicable policies 2022-06-28 07:24:34,036 [] INFO [org.dependencytrack.policy.PolicyEngine] Policy analysis complete 2022-06-28 07:24:34,038 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 07:24:41,373 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 07:25:37,850 [] INFO [org.dependencytrack.tasks.ClearComponentAnalysisCacheTask] Clearing ComponentAnalysisCache 2022-06-28 07:25:37,909 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update on vulnerability database 2022-06-28 07:25:37,933 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing portfolio metrics update 2022-06-28 07:25:37,945 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: 7be7ded7-ac02-40c1-a3f8-ca11d1bc005f 2022-06-28 07:25:40,410 [] INFO [org.dependencytrack.tasks.ClearComponentAnalysisCacheTask] Complete 2022-06-28 07:25:46,910 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: 7be7ded7-ac02-40c1-a3f8-ca11d1bc005f 2022-06-28 07:25:46,914 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 07:25:55,015 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 07:25:55,030 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed portfolio metrics update 2022-06-28 07:26:27,843 [] INFO [org.dependencytrack.tasks.VulnDbSyncTask] Starting VulnDB mirror synchronization task 2022-06-28 07:26:27,844 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Starting NIST mirroring task 2022-06-28 07:26:27,844 [] INFO [org.dependencytrack.tasks.VulnDbSyncTask] VulnDB mirror directory does not exist. Skipping. 2022-06-28 07:26:27,848 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Downloading files at Tue Jun 28 07:26:27 UTC 2022 2022-06-28 07:26:28,618 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Initiating download of https://nvd.nist.gov/feeds/json/cve/1.1/nvdcve-1.1-modified.json.gz 2022-06-28 07:26:28,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Downloading... 2022-06-28 07:26:29,602 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Uncompressing nvdcve-1.1-modified.json.gz 2022-06-28 07:26:29,711 [] INFO [org.dependencytrack.parser.nvd.NvdParser] Parsing nvdcve-1.1-modified.json 2022-06-28 07:30:44,409 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update on vulnerability database 2022-06-28 07:33:25,101 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Initiating download of https://nvd.nist.gov/feeds/json/cve/1.1/nvdcve-1.1-modified.meta 2022-06-28 07:33:25,964 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Downloading... 2022-06-28 07:33:25,972 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2022.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,972 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2021.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,972 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2020.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,972 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2019.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,972 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2018.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2017.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2016.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2015.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2014.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2013.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2012.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,973 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2011.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2010.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2009.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2008.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2007.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2006.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2005.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2004.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2003.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,974 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Retrieval of nvdcve-1.1-2002.json.gz not necessary. Will use modified feed for updates. 2022-06-28 07:33:25,975 [] INFO [org.dependencytrack.tasks.NistMirrorTask] NIST mirroring complete 2022-06-28 07:33:25,975 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Time spent (d/l): 1219ms 2022-06-28 07:33:25,975 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Time spent (parse): 415389ms 2022-06-28 07:33:25,975 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Time spent (total): 418131ms 2022-06-28 07:33:26,466 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Starting EPSS mirroring task 2022-06-28 07:33:26,466 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Initiating download of https://epss.cyentia.com/epss_scores-current.csv.gz 2022-06-28 07:33:27,918 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Downloading... 2022-06-28 07:33:28,448 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Uncompressing epss_scores-current.csv.gz 2022-06-28 07:33:28,533 [] INFO [org.dependencytrack.parser.epss.EpssParser] Parsing epss_scores-current.csv 2022-06-28 07:52:55,034 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] EPSS mirroring complete 2022-06-28 07:52:55,034 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Time spent (d/l): 1452ms 2022-06-28 07:52:55,034 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Time spent (parse): 1166500ms 2022-06-28 07:52:55,034 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Time spent (total): 1168568ms 2022-06-28 08:25:27,852 [] INFO [org.dependencytrack.tasks.InternalComponentIdentificationTask] Starting internal component identification task 2022-06-28 08:25:27,914 [] INFO [org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask] Performing component repository metadata analysis against 564 components in project: 7be7ded7-ac02-40c1-a3f8-ca11d1bc005f 2022-06-28 08:25:29,630 [] INFO [org.dependencytrack.tasks.InternalComponentIdentificationTask] Internal component identification task completed 2022-06-28 08:25:37,909 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update on vulnerability database 2022-06-28 08:25:37,934 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing portfolio metrics update 2022-06-28 08:25:37,942 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: 7be7ded7-ac02-40c1-a3f8-ca11d1bc005f 2022-06-28 08:25:48,722 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: 7be7ded7-ac02-40c1-a3f8-ca11d1bc005f 2022-06-28 08:25:48,725 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 08:25:57,114 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update for project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 08:25:57,132 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed portfolio metrics update 2022-06-28 08:30:36,552 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Completed metrics update on vulnerability database 2022-06-28 08:34:26,719 [] INFO [org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask] Completed component repository metadata analysis against 564 components in project: 7be7ded7-ac02-40c1-a3f8-ca11d1bc005f 2022-06-28 08:34:26,757 [] INFO [org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask] Performing component repository metadata analysis against 564 components in project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 08:42:17,083 [] INFO [org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask] Completed component repository metadata analysis against 564 components in project: cd6feaf1-c6df-4c15-a7b4-f118151a6605 2022-06-28 08:42:17,086 [] INFO [org.dependencytrack.tasks.repositories.RepositoryMetaAnalyzerTask] Portfolio component repository metadata analysis complete dtrack@159c5a33cb10:/data$

Based on the logs, DT took nearly 7 minutes to process nvdcve-1.1-modified.json. That’s entirely too much time. Typically this is processed in under a minute. My guess is that either the DT server is under resourced, or the database server it’s connected to is under resourced. If either are under resourced, any job will take longer than normal, and jobs waiting to be processed will take longer.

The server which runs DT has 16 GB ram and 4cors, and also posgress is used as the database and it is running in a docker container in the same server which DT runs. Potsgress docker has 1gb memory and 2 cores. Is this specification not enough for DI to be fast?

Now the postgress has 2GB ram and 2cores and also DI has 12GB ram. However, processing still takes about 37 minutes to complete the analysis. It seems like parsing takes about 29 minutes.

2022-07-01 00:34:17,657 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processing CycloneDX BOM uploaded to project: aabc2da8-ebd3-424e-ad6c-2c885acdf42e 2022-07-01 00:37:41,462 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processing CycloneDX dependency graph for project: aabc2da8-ebd3-424e-ad6c-2c885acdf42e 2022-07-01 00:37:41,790 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processed 18477 components and 0 services uploaded to project aabc2da8-ebd3-424e-ad6c-2c885acdf42e 2022-07-01 00:54:35,408 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] EPSS mirroring complete 2022-07-01 00:54:35,412 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Time spent (d/l): 1369ms 2022-07-01 00:54:35,412 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Time spent (parse): 1742301ms 2022-07-01 00:54:35,412 [] INFO [org.dependencytrack.tasks.EpssMirrorTask] Time spent (total): 1744218ms 2022-07-01 01:03:25,381 [] INFO [org.dependencytrack.tasks.scanners.InternalAnalysisTask] Starting internal analysis task 2022-07-01 01:04:01,813 [] INFO [org.dependencytrack.tasks.scanners.InternalAnalysisTask] Internal analysis complete 2022-07-01 01:04:01,822 [] WARN [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] An API username or token has not been specified for use with OSS Index. Using anonymous access 2022-07-01 01:04:01,822 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Starting Sonatype OSS Index analysis task 2022-07-01 01:04:05,413 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s) 2022-07-01 01:04:07,768 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s) 2022-07-01 01:04:08,770 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 13 component(s) 2022-07-01 01:04:19,183 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 2 component(s) 2022-07-01 01:04:25,473 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 7 component(s) 2022-07-01 01:04:33,818 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 1 component(s) 2022-07-01 01:04:41,021 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 7 component(s) 2022-07-01 01:04:50,704 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 57 component(s) 2022-07-01 01:04:52,958 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s) 2022-07-01 01:04:55,126 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s) 2022-07-01 01:04:57,070 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 77 component(s) 2022-07-01 01:04:57,072 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Sonatype OSS Index analysis complete 2022-07-01 01:04:57,082 [] INFO [org.dependencytrack.policy.PolicyEngine] Evaluating 18477 component(s) against applicable policies 2022-07-01 01:06:07,611 [] INFO [org.dependencytrack.policy.PolicyEngine] Policy analysis complete 2022-07-01 01:06:07,615 [] INFO [org.dependencytrack.tasks.MetricsUpdateTask] Executing metrics update for project: aabc2da8-ebd3-424e-ad6c-2c885acdf42e

This is last log with lastet specifications. 2022-07-05 06:05:41,759 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processing CycloneDX BOM uploaded to project: f1856754-68ca-44f5-97d1-273bd400d214 2022-07-05 06:07:08,803 [] ERROR [org.dependencytrack.notification.publisher.SlackPublisher] An error was encountered publishing notification to Slack 2022-07-05 06:07:08,805 [] ERROR [org.dependencytrack.notification.publisher.SlackPublisher] HTTP Status : 400 Bad Request 2022-07-05 06:07:08,805 [] ERROR [org.dependencytrack.notification.publisher.SlackPublisher] Destination: http://mm.dancernetworks.com/hooks/xscrpz1kri8xbms3szguj8jwke 2022-07-05 06:09:06,265 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processing CycloneDX dependency graph for project: f1856754-68ca-44f5-97d1-273bd400d214 2022-07-05 06:09:06,313 [] INFO [org.dependencytrack.tasks.BomUploadProcessingTask] Processed 19704 components and 0 services uploaded to project f1856754-68ca-44f5-97d1-273bd400d214 2022-07-05 06:09:06,369 [] ERROR [org.dependencytrack.notification.publisher.SlackPublisher] An error was encountered publishing notification to Slack 2022-07-05 06:09:06,369 [] ERROR [org.dependencytrack.notification.publisher.SlackPublisher] HTTP Status : 400 Bad Request 2022-07-05 06:09:06,369 [] ERROR [org.dependencytrack.notification.publisher.SlackPublisher] Destination: http://mm.dancernetworks.com/hooks/xscrpz1kri8xbms3szguj8jwke 2022-07-05 06:24:05,643 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Initiating download of https://nvd.nist.gov/feeds/json/cve/1.1/nvdcve-1.1-2014.meta 2022-07-05 06:24:06,406 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Downloading... 2022-07-05 06:24:06,411 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Initiating download of https://nvd.nist.gov/feeds/json/cve/1.1/nvdcve-1.1-2013.json.gz 2022-07-05 06:24:06,782 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Downloading... 2022-07-05 06:24:08,162 [] INFO [org.dependencytrack.tasks.NistMirrorTask] Uncompressing nvdcve-1.1-2013.json.gz 2022-07-05 06:24:08,701 [] INFO [org.dependencytrack.parser.nvd.NvdParser] Parsing nvdcve-1.1-2013.json 2022-07-05 06:38:15,822 [] WARN [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] An API username or token has not been specified for use with OSS Index. Using anonymous access 2022-07-05 06:38:15,822 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Starting Sonatype OSS Index analysis task 2022-07-05 06:38:18,970 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s) 2022-07-05 06:38:21,533 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s) 2022-07-05 06:38:22,252 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 13 component(s) 2022-07-05 06:38:35,310 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 2 component(s) 2022-07-05 06:38:43,013 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 7 component(s) 2022-07-05 06:38:50,588 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 1 component(s) 2022-07-05 06:38:58,528 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 7 component(s) 2022-07-05 06:39:10,497 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Sonatype OSS Index analysis complete 2022-07-05 06:39:10,499 [] INFO [org.dependencytrack.policy.PolicyEngine] Evaluating 19704 component(s) against applicable policies 2022-07-05 06:40:41,385 [] INFO [org.dependencytrack.policy.PolicyEngine] Policy analysis complete

Can you give me some idea how I can improve the performance. This happened even when I had 16GB memory 6cpu cores and posgress was running with 2gb ram and 2cors.

What portfolio dimensions are we speaking of here? Considering a single project has almost 20k components already, I'm assuming there is a lot going on in your Dependency-Track instance?

Ultimately we need to test with a BOM that large. 30-40min to analyze it truly seem excessive.

Do you need the bom file to check?

I think I see where the bottleneck is. I tested with a BOM with a little above 20k components.

Broadly speaking, when uploading a BOM, Dependency-Track will queue a RepositoryMetaEvent to its internal event bus for every component in it. RepositoryMetaEvent is responsible for reaching out to package repositories like NPM or Maven to query for things like the latest version of the given package.

This is happening before Dependency-Track kicks off the VulnerabilityAnalysisEvent that is responsible for scanning for vulnerabilities. The Jenkins plugin however waits for the vulnerability scanning to complete.

So, given a BOM with 20k components in it, that means that DT's internal queue is stuffed with RepositoryMetaEvents that need to be processed. In the worst possible case, every single one of those 20k events triggers a request to an external repository. Depending how beefy your DT server is (WRT CPU cores, RAM, network connection), that can take a while.

Per default, events in DTs event bus are processed by a worker pool of up to NUM_CPU * 4 threads, in your case that'd be a total of 16 threads. In my case, on my local machine (10 cores ➡️ up to 40 worker threads), it took ~3min from processing the uploaded BOM to the internal vulnerability analysis to complete:

2022-07-07 23:05:28,287 INFO [Config] --------------------------------------------------------------------------------
2022-07-07 23:05:28,288 INFO [Config] OS Name:      Mac OS X
2022-07-07 23:05:28,288 INFO [Config] OS Version:   12.4
2022-07-07 23:05:28,288 INFO [Config] OS Arch:      aarch64
2022-07-07 23:05:28,288 INFO [Config] CPU Cores:    10
2022-07-07 23:05:28,291 INFO [Config] Max Memory:   25,6 GB (27.492.614.144,0 bytes)
2022-07-07 23:05:28,291 INFO [Config] Java Vendor:  Eclipse Adoptium
2022-07-07 23:05:28,292 INFO [Config] Java Version: 11.0.15+10
...
2022-07-07 23:14:49,539 INFO [BomUploadProcessingTask] Processing CycloneDX BOM uploaded to project: f5bd61c4-8a59-4dc8-b452-53d044c13071
2022-07-07 23:15:17,385 INFO [BomUploadProcessingTask] Processing CycloneDX dependency graph for project: f5bd61c4-8a59-4dc8-b452-53d044c13071
2022-07-07 23:15:19,073 INFO [BomUploadProcessingTask] Processed 20466 components and 0 services uploaded to project f5bd61c4-8a59-4dc8-b452-53d044c13071
2022-07-07 23:17:27,189 INFO [InternalAnalysisTask] Starting internal analysis task
2022-07-07 23:17:29,011 INFO [InternalAnalysisTask] Internal analysis complete

Mind you my BOM contained a lot of duplicate components. DT caches results of RepositoryMetaEvent, resulting in less I/O in my case.

To prevent situations like this one, DT would need to have more than one event bus, and it would need a way of prioritizing certain events over others. We could also look into batching RepositoryMetaEvents to reduce the load we're causing on the event bus.

After all this, here's what you can do to linder the pain:

Experiment with tweaking the alpine.worker.threads and alpine.worker.thread.multiplier settings (see here). 16 worker threads are not enough to handle projects with 20k components.
It is very much possible that you'll also need to tweak alpine.database.pool.max.size with an increasing worker thread pool size. Don't modify this setting if you're not running into problems - an excessively large database connection pool can be a performance killer.
You will most likely still need to increase the timeout in your Jenkins plugin. While I think increasing the worker pool size will help, I'm not super sure it'll solve your timeout issues.

Thanks.I have already increased the timeout in jenkins. I will try your suggestion and let you know.

Implemented a partial fix in #1772.

Below is the DI config.

 [alpine.Config] OS Name:      Linux
2022-07-08 08:13:07,749 [] INFO [alpine.Config] OS Version:   5.4.0-121-generic
2022-07-08 08:13:07,750 [] INFO [alpine.Config] OS Arch:      amd64
2022-07-08 08:13:07,750 [] INFO [alpine.Config] CPU Cores:    12
2022-07-08 08:13:07,760 [] INFO [alpine.Config] Max Memory:   12.8 GB (13,744,734,208.0 bytes)
2022-07-08 08:13:07,760 [] INFO [alpine.Config] Java Vendor:  Eclipse Adoptium
2022-07-08 08:13:07,765 [] INFO [alpine.Config] Java Version: 11.0.14.1+1
2022-07-08 08:13:07,766 [] INFO [alpine.Config] Java Home:    /opt/java/openjdk
2022-07-08 08:13:07,766 [] INFO [alpine.Config] Java Temp:    /tmp
2022-07-08 08:13:07,767 [] INFO [alpine.Config] User:         dtrack
2022-07-08 08:13:07,767 [] INFO [alpine.Config] User Home:    /data/
2022-07-08 08:13:07,767 [] INFO [alpine.Config] --------------------------------------------------------------------------------
2022-07-08 08:13:07,767 [] INFO [alpine.Config] Initializing Configuration
2022-07-08 08:13:07,768 [] INFO [alpine.Config] System property alpine.application.properties not specified
2022-07-08 08:13:07,769 [] INFO [alpine.Config] Loading application.properties from classpath
2022-07-08 08:13:07,778 [] INFO [alpine.Config] --------------------------------------------------------------------------------
2022-07-08 08:13:07,778 [] INFO [alpine.Config] Application:  Dependency-Track
2022-07-08 08:13:07,779 [] INFO [alpine.Config] Version:      4.5.0
2022-07-08 08:13:07,779 [] INFO [alpine.Config] Built-on:     2022-05-18T05:56:02Z
2022-07-08 08:13:07,779 [] INFO [alpine.Config] --------------------------------------------------------------------------------
2022-07-08 08:13:07,780 [] INFO [alpine.Config] Framework:    Alpine
2022-07-08 08:13:07,780 [] INFO [alpine.Config] Version :     2.0.0
2022-07-08 08:13:07,780 [] INFO [alpine.Config] Built-on:     2022-05-12T22:49:09Z

This is the relevant configuration in the docker-compose.yml

- ALPINE_LDAP_TEAM_SYNCHRONIZATION=false
        - ALPINE_WORKER_THREADS=2
        - ALPINE_WORKER_THREAD_MULTIPLYER=6
        - ALPINE_DATABASE_POOL_ENABLED=true
        - ALPINE_DATABASE_POOL_MAX_SIZE=30

docker stats

e03ccc12c779   dtrack_dtrack-apiserver.1.f1hb4u6xu0mgwlvgelyctqzaf   8.23%     1.972GiB / 16GiB      12.33%    525MB / 284MB   156kB / 2.74MB   59
042d80a831a8   dtrackdb-postgres                                     0.63%     543.6MiB / 2GiB       26.54%    554MB / 982MB   932MB / 1.3GB    27
377146a1f9f8   dtrack_dtrack-frontend.1.zzp9rvyjcv9jw2pgqnbfdq3yc    0.00%     13.34MiB / 30.62GiB   0.04%     7.28kB / 0B     13.6MB / 0B      13

But I still see the issue.

Hi @jayachathu, please keep in mind the following constraint for alpine.worker.threads.multiplier, as stated in the docs:

This property is only used when alpine.worker.threads is set to 0.

In your provided configuration, you effectively assigned 2 worker threads to DT, which is even less than before.

Even if that constraint didn't apply, 2x6 threads is less than the 4x4 you had before.

Yes. After removing alpine.worker.threads it took 9 minutes now the thread count is 72,

I need more time to investigate and solve this appropriately. Caching of repository lookups (#1943) plays into this as well. I'm moving this to 4.7 for the time being.

There are multiple improvements in 4.7 that will address cases like this:

Improved batching for OSS Index (#2023) will prevent inefficient calls like this from happening:

2022-07-05 06:38:18,970 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s)
2022-07-05 06:38:21,533 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 100 component(s)
2022-07-05 06:38:22,252 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 13 component(s)
2022-07-05 06:38:35,310 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 2 component(s)
2022-07-05 06:38:43,013 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 7 component(s)
2022-07-05 06:38:50,588 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 1 component(s)
2022-07-05 06:38:58,528 [] INFO [org.dependencytrack.tasks.scanners.OssIndexAnalysisTask] Analyzing 7

The batch size was increased to 128 to conform with OSS Index' official API documentation. In the above scenario, the analyzer will now perform only 2 requests with 128 and 102 components.

Caching for repository meta analysis (#2129) will prevent many redundant requests to external repositories from happening. Further, RepositoryMetaAnalysisEvents emitted after BOM upload cannot clog the internal event bus anymore.

Other than that, of course larger BOMs will always take a longer time to be processed. Server resources for both API server and database will need to be in line with the expected workload. The worker pool size can be raised from its default value to improve throughput. Monitoring Dependency-Track is recommended to identify when the instance is incapable of handling the workload it is exposed to.

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

DependencyTrack / dependency-track