From 92e1fd3f286f306502cfa18f694a95f072f4f6b0 Mon Sep 17 00:00:00 2001
From: Anthony Whitford <anthony@whitford.com>
Date: Sat, 5 Sep 2015 00:31:50 -0700
Subject: [PATCH] Added time measurements for key steps.

---
 .../src/main/java/org/owasp/dependencycheck/Engine.java     | 6 ++++--
 .../owasp/dependencycheck/data/update/nvd/DownloadTask.java | 4 +++-
 .../owasp/dependencycheck/data/update/nvd/ProcessTask.java  | 4 +++-
 3 files changed, 10 insertions(+), 4 deletions(-)

diff --git a/dependency-check-core/src/main/java/org/owasp/dependencycheck/Engine.java b/dependency-check-core/src/main/java/org/owasp/dependencycheck/Engine.java
index cdb1a4706..2da745245 100644
--- a/dependency-check-core/src/main/java/org/owasp/dependencycheck/Engine.java
+++ b/dependency-check-core/src/main/java/org/owasp/dependencycheck/Engine.java
@@ -352,6 +352,7 @@ public class Engine implements FileFilter {
 
         LOGGER.debug("\n----------------------------------------------------\nBEGIN ANALYSIS\n----------------------------------------------------");
         LOGGER.info("Analysis Starting");
+        final long analysisStart = System.currentTimeMillis();
 
         // analysis phases
         for (AnalysisPhase phase : AnalysisPhase.values()) {
@@ -398,7 +399,7 @@ public class Engine implements FileFilter {
         }
 
         LOGGER.debug("\n----------------------------------------------------\nEND ANALYSIS\n----------------------------------------------------");
-        LOGGER.info("Analysis Complete");
+        LOGGER.info("Analysis Complete ({} ms)", System.currentTimeMillis() - analysisStart);
     }
 
     /**
@@ -442,6 +443,7 @@ public class Engine implements FileFilter {
      */
     public void doUpdates() {
         LOGGER.info("Checking for updates");
+        final long updateStart = System.currentTimeMillis();
         final UpdateService service = new UpdateService(serviceClassLoader);
         final Iterator<CachedWebDataSource> iterator = service.getDataSources();
         while (iterator.hasNext()) {
@@ -454,7 +456,7 @@ public class Engine implements FileFilter {
                 LOGGER.debug("Unable to update details for {}", source.getClass().getName(), ex);
             }
         }
-        LOGGER.info("Check for updates complete");
+        LOGGER.info("Check for updates complete ({} ms)", System.currentTimeMillis() - updateStart);
     }
 
     /**
diff --git a/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/DownloadTask.java b/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/DownloadTask.java
index ed1ab22bc..4b4d04201 100644
--- a/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/DownloadTask.java
+++ b/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/DownloadTask.java
@@ -185,6 +185,7 @@ public class DownloadTask implements Callable<Future<ProcessTask>> {
             final URL url1 = new URL(nvdCveInfo.getUrl());
             final URL url2 = new URL(nvdCveInfo.getOldSchemaVersionUrl());
             LOGGER.info("Download Started for NVD CVE - {}", nvdCveInfo.getId());
+            final long startDownload = System.currentTimeMillis();
             try {
                 Downloader.fetchFile(url1, first);
                 Downloader.fetchFile(url2, second);
@@ -204,7 +205,8 @@ public class DownloadTask implements Callable<Future<ProcessTask>> {
                 extractGzip(second);
             }
 
-            LOGGER.info("Download Complete for NVD CVE - {}", nvdCveInfo.getId());
+            LOGGER.info("Download Complete for NVD CVE - {}  ({} ms)", nvdCveInfo.getId(),
+                System.currentTimeMillis() - startDownload);
             if (this.processorService == null) {
                 return null;
             }
diff --git a/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/ProcessTask.java b/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/ProcessTask.java
index 8934337c9..775048cfb 100644
--- a/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/ProcessTask.java
+++ b/dependency-check-core/src/main/java/org/owasp/dependencycheck/data/update/nvd/ProcessTask.java
@@ -157,6 +157,7 @@ public class ProcessTask implements Callable<ProcessTask> {
      */
     private void processFiles() throws UpdateException {
         LOGGER.info("Processing Started for NVD CVE - {}", filePair.getNvdCveInfo().getId());
+        final long startProcessing = System.currentTimeMillis();
         try {
             importXML(filePair.getFirst(), filePair.getSecond());
             cveDB.commit();
@@ -178,6 +179,7 @@ public class ProcessTask implements Callable<ProcessTask> {
         } finally {
             filePair.cleanup();
         }
-        LOGGER.info("Processing Complete for NVD CVE - {}", filePair.getNvdCveInfo().getId());
+        LOGGER.info("Processing Complete for NVD CVE - {}  ({} ms)", filePair.getNvdCveInfo().getId(),
+            System.currentTimeMillis() - startProcessing);
     }
 }