From fb78ba2317ac775bedd82c84cb1411a6abc10d45 Mon Sep 17 00:00:00 2001 From: Jacek <52388493+jacek-poreda-sonarsource@users.noreply.github.com> Date: Wed, 24 Jul 2019 14:33:01 +0200 Subject: [PATCH] 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 --- .../java/org/sonar/scanner/cpd/CpdExecutor.java | 8 ++++---- .../org/sonar/scanner/scm/DefaultBlameOutput.java | 12 ++++++++---- .../java/org/sonar/scanner/scm/ScmPublisher.java | 6 +++--- .../org/sonar/scanner/util/ProgressReport.java | 15 +++++++++++++++ .../scanner/mediumtest/cpd/CpdMediumTest.java | 4 ++-- .../scanner/mediumtest/scm/ScmMediumTest.java | 11 ++++++++--- .../sonar/scanner/util/ProgressReportTest.java | 9 +++++++++ 7 files changed, 49 insertions(+), 16 deletions(-) diff --git a/sonar-scanner-engine/src/main/java/org/sonar/scanner/cpd/CpdExecutor.java b/sonar-scanner-engine/src/main/java/org/sonar/scanner/cpd/CpdExecutor.java index 635c07fb94e..7b2ae74b18b 100644 --- a/sonar-scanner-engine/src/main/java/org/sonar/scanner/cpd/CpdExecutor.java +++ b/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; diff --git a/sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/DefaultBlameOutput.java b/sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/DefaultBlameOutput.java index 0908056ed5a..fd64a9615fe 100644 --- a/sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/DefaultBlameOutput.java +++ b/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"; + } } diff --git a/sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/ScmPublisher.java b/sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/ScmPublisher.java index d4da2729661..1b42121c923 100644 --- a/sonar-scanner-engine/src/main/java/org/sonar/scanner/scm/ScmPublisher.java +++ b/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 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); diff --git a/sonar-scanner-engine/src/main/java/org/sonar/scanner/util/ProgressReport.java b/sonar-scanner-engine/src/main/java/org/sonar/scanner/util/ProgressReport.java index 8802e240836..b5f0c8458c7 100644 --- a/sonar-scanner-engine/src/main/java/org/sonar/scanner/util/ProgressReport.java +++ b/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; + } } diff --git a/sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/cpd/CpdMediumTest.java b/sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/cpd/CpdMediumTest.java index eaea6f109ea..293ec4c055d 100644 --- a/sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/cpd/CpdMediumTest.java +++ b/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"); } diff --git a/sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/scm/ScmMediumTest.java b/sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/scm/ScmMediumTest.java index 16d3e528e91..cd8c1c20f72 100644 --- a/sonar-scanner-engine/src/test/java/org/sonar/scanner/mediumtest/scm/ScmMediumTest.java +++ b/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"); } diff --git a/sonar-scanner-engine/src/test/java/org/sonar/scanner/util/ProgressReportTest.java b/sonar-scanner-engine/src/test/java/org/sonar/scanner/util/ProgressReportTest.java index 70dffa9d2c6..69f7824d7da 100644 --- a/sonar-scanner-engine/src/test/java/org/sonar/scanner/util/ProgressReportTest.java +++ b/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) { -- 2.39.5