SONAR-11546 add time info to scm logs (#1939)

* SONAR-11546 - add time measures to scm logs

* SONAR-11546 - add time measure for CPD executor and SCM publisher steps

sonar-scanner-engine/src/main/java/org/sonar/scanner/cpd/CpdExecutor.java

@@ -76,7 +76,7 @@ public class CpdExecutor {
   }
 
   public CpdExecutor(CpdSettings settings, SonarCpdBlockIndex index, ReportPublisher publisher, InputComponentStore inputComponentCache,
-    ExecutorService executorService) {
+                     ExecutorService executorService) {
     this.settings = settings;
     this.index = index;
     this.publisher = publisher;
@@ -104,17 +104,17 @@ public class CpdExecutor {
 
     int filesWithoutBlocks = index.noIndexedFiles() - index.noResources();
     if (filesWithoutBlocks > 0) {
-      LOG.info("{} {} had no CPD blocks", filesWithoutBlocks, pluralize(filesWithoutBlocks));
+      LOG.info("CPD Executor {} {} had no CPD blocks", filesWithoutBlocks, pluralize(filesWithoutBlocks));
     }
 
     total = components.size();
-    progressReport.start(String.format("Calculating CPD for %d %s", total, pluralize(total)));
+    progressReport.start(String.format("CPD Executor Calculating CPD for %d %s", total, pluralize(total)));
     try {
       for (FileBlocks fileBlocks : components) {
         runCpdAnalysis(executorService, fileBlocks.getInputFile(), fileBlocks.getBlocks(), timeout);
         count++;
       }
-      progressReport.stop("CPD calculation finished");
+      progressReport.stopAndLogTotalTime("CPD Executor CPD calculation finished");
     } catch (Exception e) {
       progressReport.stop("");
       throw e;

sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/DefaultBlameOutput.java

@@ -29,9 +29,9 @@ import java.util.concurrent.TimeUnit;
 import javax.annotation.Nullable;
 import org.apache.commons.lang.StringUtils;
 import org.sonar.api.batch.fs.InputFile;
+import org.sonar.api.batch.fs.internal.DefaultInputFile;
 import org.sonar.api.batch.scm.BlameCommand.BlameOutput;
 import org.sonar.api.batch.scm.BlameLine;
-import org.sonar.api.batch.fs.internal.DefaultInputFile;
 import org.sonar.api.utils.log.Logger;
 import org.sonar.api.utils.log.Loggers;
 import org.sonar.scanner.protocol.output.ScannerReport;
@@ -57,7 +57,7 @@ class DefaultBlameOutput implements BlameOutput {
     count = 0;
     total = filesToBlame.size();
     progressReport = new ProgressReport("Report about progress of SCM blame", TimeUnit.SECONDS.toMillis(10));
-    progressReport.start(total + " files to be analyzed");
+    progressReport.start("SCM Publisher " + total + " " + pluralize(total) + " to be analyzed");
   }
 
   @Override
@@ -91,7 +91,7 @@ class DefaultBlameOutput implements BlameOutput {
     writer.writeComponentChangesets(scmBuilder.build());
     allFilesToBlame.remove(file);
     count++;
-    progressReport.message(count + "/" + total + " files analyzed");
+    progressReport.message(count + "/" + total + " " + pluralize(count) + " have been analyzed");
   }
 
   private static void validateLine(BlameLine line, int lineId, InputFile file) {
@@ -124,7 +124,7 @@ class DefaultBlameOutput implements BlameOutput {
   }
 
   public void finish(boolean success) {
-    progressReport.stop(count + "/" + total + " files analyzed");
+    progressReport.stopAndLogTotalTime("SCM Publisher " + count + "/" + total + " " + pluralize(count) + " have been analyzed");
     if (success && !allFilesToBlame.isEmpty()) {
       LOG.warn("Missing blame information for the following files:");
       for (InputFile f : allFilesToBlame) {
@@ -133,4 +133,8 @@ class DefaultBlameOutput implements BlameOutput {
       LOG.warn("This may lead to missing/broken features in SonarQube");
     }
   }
+
+  private static String pluralize(long filesCount) {
+    return filesCount == 1 ? "source file" : "source files";
+  }
 }

sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/ScmPublisher.java

@@ -26,10 +26,10 @@ import org.sonar.api.CoreProperties;
 import org.sonar.api.batch.fs.FileSystem;
 import org.sonar.api.batch.fs.InputFile;
 import org.sonar.api.batch.fs.InputFile.Status;
+import org.sonar.api.batch.fs.internal.DefaultInputFile;
 import org.sonar.api.batch.scm.ScmProvider;
 import org.sonar.api.utils.log.Logger;
 import org.sonar.api.utils.log.Loggers;
-import org.sonar.api.batch.fs.internal.DefaultInputFile;
 import org.sonar.scanner.protocol.output.ScannerReport;
 import org.sonar.scanner.protocol.output.ScannerReport.Changesets.Builder;
 import org.sonar.scanner.protocol.output.ScannerReportWriter;
@@ -68,14 +68,14 @@ public final class ScmPublisher {
 
     ScmProvider provider = configuration.provider();
     if (provider == null) {
-      LOG.info("No SCM system was detected. You can use the '" + CoreProperties.SCM_PROVIDER_KEY + "' property to explicitly specify it.");
+      LOG.info("SCM Publisher No SCM system was detected. You can use the '" + CoreProperties.SCM_PROVIDER_KEY + "' property to explicitly specify it.");
       return;
     }
 
     List<InputFile> filesToBlame = collectFilesToBlame(writer);
     if (!filesToBlame.isEmpty()) {
       String key = provider.key();
-      LOG.info("SCM provider for this project is: " + key);
+      LOG.info("SCM Publisher SCM provider for this project is: " + key);
       DefaultBlameOutput output = new DefaultBlameOutput(writer, filesToBlame);
       try {
         provider.blameCommand().blame(new DefaultBlameInput(fs, filesToBlame), output);

sonar-scanner-engine/src/main/java/org/sonar/scanner/util/ProgressReport.java

@@ -27,6 +27,7 @@ public class ProgressReport implements Runnable {
 
   private static final Logger LOG = Loggers.get(ProgressReport.class);
   private final long period;
+  private long startTime;
   private String message = "";
   private final Thread thread;
   private String stopMessage = null;
@@ -56,6 +57,7 @@ public class ProgressReport implements Runnable {
   public void start(String startMessage) {
     log(startMessage);
     thread.start();
+    startTime = currentTimeMillis();
   }
 
   public void message(String message) {
@@ -72,6 +74,12 @@ public class ProgressReport implements Runnable {
     }
   }
 
+  public void stopAndLogTotalTime(@Nullable String stopMessage) {
+    long stopTime = currentTimeMillis();
+    stopMessage += String.format(" (done) | time=%dms", timeDiff(stopTime, startTime));
+    stop(stopMessage);
+  }
+
   private static void log(String message) {
     synchronized (LOG) {
       LOG.info(message);
@@ -79,4 +87,11 @@ public class ProgressReport implements Runnable {
     }
   }
 
+  private static long currentTimeMillis() {
+    return System.currentTimeMillis();
+  }
+
+  private static long timeDiff(long endTime, long startTime) {
+    return endTime - startTime;
+  }
 }

sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/cpd/CpdMediumTest.java

@@ -33,8 +33,8 @@ import org.junit.rules.TemporaryFolder;
 import org.sonar.api.batch.fs.InputFile;
 import org.sonar.api.utils.log.LogTester;
 import org.sonar.api.utils.log.LoggerLevel;
-import org.sonar.scanner.mediumtest.ScannerMediumTester;
 import org.sonar.scanner.mediumtest.AnalysisResult;
+import org.sonar.scanner.mediumtest.ScannerMediumTester;
 import org.sonar.scanner.protocol.output.ScannerReport;
 import org.sonar.xoo.XooPlugin;
 import org.sonar.xoo.rule.XooRulesDefinition;
@@ -222,7 +222,7 @@ public class CpdMediumTest {
     assertThat(result.inputFiles()).hasSize(2);
 
     assertThat(logTester.logs()).contains("Not enough content in 'src/sample2.xoo' to have CPD blocks, it will not be part of the duplication detection");
-    assertThat(logTester.logs()).contains("1 file had no CPD blocks");
+    assertThat(logTester.logs()).contains("CPD Executor 1 file had no CPD blocks");
 
   }
 

sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/scm/ScmMediumTest.java

@@ -24,6 +24,7 @@ import java.io.File;
 import java.io.IOException;
 import java.net.URISyntaxException;
 import java.nio.charset.StandardCharsets;
+import java.util.regex.Pattern;
 import org.apache.commons.codec.digest.DigestUtils;
 import org.apache.commons.io.FileUtils;
 import org.assertj.core.util.Files;
@@ -175,8 +176,10 @@ public class ScmMediumTest {
     ScannerReport.Changesets fileWithoutBlameScm = getChangesets(baseDir, "src/sample_no_blame.xoo");
     assertThat(fileWithoutBlameScm).isNull();
 
-    assertThat(logTester.logs()).containsSubsequence("2 files to be analyzed", "1/2 files analyzed", MISSING_BLAME_INFORMATION_FOR_THE_FOLLOWING_FILES,
+    assertThat(logTester.logs()).containsSubsequence("SCM Publisher 2 source files to be analyzed", MISSING_BLAME_INFORMATION_FOR_THE_FOLLOWING_FILES,
       "  * src/sample_no_blame.xoo");
+
+    assertThat(logTester.logs().stream().anyMatch(s -> Pattern.matches("SCM Publisher 1/2 source file have been analyzed \\(done\\) \\| time=[0-9]+ms", s))).isTrue();
   }
 
   // SONAR-6397
@@ -234,7 +237,8 @@ public class ScmMediumTest {
 
     // 5 .xoo files + 3 .scm files, but only 4 marked for publishing. 1 file is SAME so not included in the total
     assertThat(logTester.logs()).containsSubsequence("8 files indexed");
-    assertThat(logTester.logs()).containsSubsequence("4 files to be analyzed", "3/4 files analyzed");
+    assertThat(logTester.logs()).containsSubsequence("SCM Publisher 4 source files to be analyzed");
+    assertThat(logTester.logs().stream().anyMatch(s -> Pattern.matches("SCM Publisher 3/4 source files have been analyzed \\(done\\) \\| time=[0-9]+ms", s))).isTrue();
     assertThat(logTester.logs()).containsSubsequence(MISSING_BLAME_INFORMATION_FOR_THE_FOLLOWING_FILES, "  * src/no_blame_scm_on_server.xoo");
   }
 
@@ -289,7 +293,8 @@ public class ScmMediumTest {
 
     // 5 .xoo files + 3 .scm files, but only 4 marked for publishing. 1 file is SAME so not included in the total
     assertThat(logTester.logs()).containsSubsequence("8 files indexed");
-    assertThat(logTester.logs()).containsSubsequence("4 files to be analyzed", "3/4 files analyzed");
+    assertThat(logTester.logs()).containsSubsequence("SCM Publisher 4 source files to be analyzed");
+    assertThat(logTester.logs().stream().anyMatch(s -> Pattern.matches("SCM Publisher 3/4 source files have been analyzed \\(done\\) \\| time=[0-9]+ms", s))).isTrue();
     assertThat(logTester.logs()).containsSubsequence(MISSING_BLAME_INFORMATION_FOR_THE_FOLLOWING_FILES, "  * src/no_blame_scm_on_server.xoo");
   }
 

sonar-scanner-engine/src/test/java/org/sonar/scanner/util/ProgressReportTest.java

@@ -20,6 +20,7 @@
 package org.sonar.scanner.util;
 
 import java.util.Set;
+import java.util.regex.Pattern;
 import org.junit.Rule;
 import org.junit.Test;
 import org.junit.rules.DisableOnDebug;
@@ -63,6 +64,14 @@ public class ProgressReportTest {
       logged = logTester.logs().contains("Some message");
     }
     underTest.stop("stop");
+    assertThat(logTester.logs().stream().anyMatch(s -> Pattern.matches("stop", s))).isTrue();
+  }
+
+  @Test
+  public void do_log_with_time() {
+    underTest.start("start");
+    underTest.stopAndLogTotalTime("stop");
+    assertThat(logTester.logs().stream().anyMatch(s -> Pattern.matches("stop \\(done\\) \\| time=[0-9]+ms", s))).isTrue();
   }
 
   private static boolean isDaemon(String name) {