SONAR-6736 add CE and steps timing logs at INFO level

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationService.java b/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationService.java
index 9daf008e58f60f87cec33944582b4035a17afdab..1dac5611f55b529c62b2b4363308f45afbb48756 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationService.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationService.java
@@ -24,11 +24,12 @@ import org.sonar.api.server.ServerSide;
 import org.sonar.api.utils.System2;
 import org.sonar.api.utils.log.Logger;
 import org.sonar.api.utils.log.Loggers;
-import org.sonar.api.utils.log.Profiler;
+import org.sonar.core.util.logs.Profiler;
 import org.sonar.server.computation.activity.ActivityManager;
 import org.sonar.server.computation.step.ComputationStep;
 import org.sonar.server.computation.step.ComputationSteps;
 
+import static java.lang.String.format;
 import static org.sonar.db.compute.AnalysisReportDto.Status.FAILED;
 import static org.sonar.db.compute.AnalysisReportDto.Status.SUCCESS;
 
@@ -51,15 +52,16 @@ public class ComputationService {
 
   public void process() {
     String projectKey = item.dto.getProjectKey();
-    Profiler profiler = Profiler.create(LOG).startDebug(
-      String.format("Analysis of project %s (report %d)", projectKey, item.dto.getId())
-      );
+    String message = format("Analysis of project %s (report %d)", projectKey, item.dto.getId());
+    Profiler profiler = Profiler.create(LOG).startDebug(message);
 
+    long timingSum = 0L;
+    Profiler stepProfiler = Profiler.create(LOG);
     try {
       for (ComputationStep step : steps.instances()) {
-        Profiler stepProfiler = Profiler.createIfDebug(LOG).startDebug(step.getDescription());
+        stepProfiler.start();
         step.execute();
-        stepProfiler.stopDebug();
+        timingSum += stepProfiler.stopInfo(step.getDescription());
       }
       item.dto.setStatus(SUCCESS);
     } catch (Throwable e) {
@@ -68,7 +70,7 @@ public class ComputationService {
     } finally {
       item.dto.setFinishedAt(system.now());
       activityManager.saveActivity(item.dto);
-      profiler.stopInfo();
+      profiler.stopInfo(format("%s total time spent in steps=%sms", message, timingSum));
     }
   }
 }

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationThread.java b/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationThread.java
index aa621b317e87c1e70bd2f8135845b0a59672b456..58b23538c7da3990855d99d260c19e772217c7bc 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationThread.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/ComputationThread.java
@@ -23,6 +23,7 @@ package org.sonar.server.computation;
 import org.sonar.api.utils.log.Logger;
 import org.sonar.api.utils.log.Loggers;
 import org.sonar.core.platform.ComponentContainer;
+import org.sonar.core.util.logs.Profiler;
 import org.sonar.server.computation.container.ComputeEngineContainer;
 import org.sonar.server.computation.container.ContainerFactory;
 
@@ -45,6 +46,7 @@ public class ComputationThread implements Runnable {
 
   @Override
   public void run() {
+    Profiler profiler = Profiler.create(LOG).start();
     ReportQueue.Item item = null;
     try {
       item = queue.pop();
@@ -66,6 +68,7 @@ public class ComputationThread implements Runnable {
 
       removeSilentlyFromQueue(item);
     }
+    profiler.stopInfo(String.format("Total thread execution of project %s (report %d)", item.dto.getProjectKey(), item.dto.getId()));
   }
 
   private void removeSilentlyFromQueue(ReportQueue.Item item) {

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/container/ComputeEngineContainerImpl.java b/server/sonar-server/src/main/java/org/sonar/server/computation/container/ComputeEngineContainerImpl.java
index bdd9c9b9c85b1fda3b949406963401699a25f3da..eeba9f111e8c4c1e815564f84e2dc3975129852c 100644 (file)
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/container/ComputeEngineContainerImpl.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/container/ComputeEngineContainerImpl.java
@@ -19,16 +19,21 @@
  */
 package org.sonar.server.computation.container;
 
+import java.lang.reflect.Constructor;
+import java.lang.reflect.Member;
 import java.util.Arrays;
 import java.util.List;
 import org.picocontainer.ComponentAdapter;
+import org.picocontainer.ComponentMonitor;
 import org.picocontainer.DefaultPicoContainer;
 import org.picocontainer.MutablePicoContainer;
+import org.picocontainer.PicoContainer;
 import org.picocontainer.behaviors.OptInCaching;
 import org.picocontainer.lifecycle.ReflectionLifecycleStrategy;
+import org.picocontainer.monitors.ComponentMonitorHelper;
 import org.picocontainer.monitors.NullComponentMonitor;
+import org.sonar.api.utils.log.Logger;
 import org.sonar.api.utils.log.Loggers;
-import org.sonar.api.utils.log.Profiler;
 import org.sonar.core.issue.tracking.Tracker;
 import org.sonar.core.platform.ComponentContainer;
 import org.sonar.core.platform.Module;
@@ -85,8 +90,14 @@ import org.sonar.server.computation.step.ComputationSteps;
 import org.sonar.server.view.index.ViewIndex;
 
 import static java.util.Objects.requireNonNull;
+import static org.picocontainer.monitors.ComponentMonitorHelper.ctorToString;
+import static org.picocontainer.monitors.ComponentMonitorHelper.format;
+import static org.picocontainer.monitors.ComponentMonitorHelper.methodToString;
+import static org.picocontainer.monitors.ComponentMonitorHelper.parmsToString;
 
 public class ComputeEngineContainerImpl extends ComponentContainer implements ComputeEngineContainer {
+  private static final Logger LOG = Loggers.get(ComputeEngineContainerImpl.class);
+
   private final ReportQueue.Item item;
   private final ComputationSteps steps;
 
@@ -125,22 +136,36 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
    * and lazily starts its components.
    */
   private static MutablePicoContainer createContainer(ComponentContainer parent) {
-    ReflectionLifecycleStrategy lifecycleStrategy = new ReflectionLifecycleStrategy(new NullComponentMonitor(), "start", "stop", "close") {
+    ComponentMonitor componentMonitor = instanceComponentMonitor();
+    ReflectionLifecycleStrategy lifecycleStrategy = new ReflectionLifecycleStrategy(componentMonitor, "start", "stop", "close") {
       @Override
       public boolean isLazy(ComponentAdapter<?> adapter) {
         return true;
       }
-
-      @Override
-      public void start(Object component) {
-        Profiler profiler = Profiler.createIfTrace(Loggers.get(ComponentContainer.class));
-        profiler.start();
-        super.start(component);
-        profiler.stopTrace(component.getClass().getCanonicalName() + " started");
-      }
     };
 
-    return new DefaultPicoContainer(new OptInCaching(), lifecycleStrategy, parent.getPicoContainer());
+    return new DefaultPicoContainer(new OptInCaching(), lifecycleStrategy, parent.getPicoContainer(), componentMonitor);
+  }
+
+  private static ComponentMonitor instanceComponentMonitor() {
+    if (!LOG.isTraceEnabled()) {
+      return new NullComponentMonitor();
+    }
+    return new ComputeEngineComponentMonitor();
+  }
+
+  private static class ComputeEngineComponentMonitor extends NullComponentMonitor {
+
+    public <T> void instantiated(PicoContainer container, ComponentAdapter<T> componentAdapter,
+      Constructor<T> constructor, Object instantiated, Object[] parameters, long duration) {
+      LOG.trace(format(ComponentMonitorHelper.INSTANTIATED, ctorToString(constructor), duration, instantiated.getClass().getName(), parmsToString(parameters)));
+    }
+
+    @Override
+    public void invoked(PicoContainer container, ComponentAdapter<?> componentAdapter, Member member, Object instance, long duration, Object[] args, Object retVal) {
+      LOG.trace(format(ComponentMonitorHelper.INVOKED, methodToString(member), instance, duration));
+    }
+
   }
 
   /**
@@ -151,11 +176,11 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
     return Arrays.asList(
       new ComputationTempFolderProvider(),
 
-      ActivityManager.class,
+    ActivityManager.class,
 
-      MetricModule.class,
+    MetricModule.class,
 
-      // holders
+    // holders
       BatchReportDirectoryHolderImpl.class,
       TreeRootHolderImpl.class,
       PeriodsHolderImpl.class,
@@ -164,9 +189,9 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
       SqaleRatingSettings.class,
       ActiveRulesHolderImpl.class,
 
-      BatchReportReaderImpl.class,
+    BatchReportReaderImpl.class,
 
-      // repositories
+    // repositories
       LanguageRepositoryImpl.class,
       MeasureRepositoryImpl.class,
       EventRepositoryImpl.class,
@@ -175,10 +200,10 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
       QualityGateServiceImpl.class,
       EvaluationResultTextConverterImpl.class,
 
-      // new coverage measures
+    // new coverage measures
       NewCoverageMetricKeysModule.class,
 
-      // issues
+    // issues
       RuleCacheLoader.class,
       RuleRepositoryImpl.class,
       ScmAccountToUserLoader.class,
@@ -188,7 +213,7 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
       IssueVisitors.class,
       IssueLifecycle.class,
 
-      // common rules
+    // common rules
       CommonRuleEngineImpl.class,
       BranchCoverageRule.class,
       LineCoverageRule.class,
@@ -197,7 +222,7 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
       TestErrorRule.class,
       SkippedTestRule.class,
 
-      // order is important: DebtAggregator then NewDebtAggregator (new debt requires debt)
+    // order is important: DebtAggregator then NewDebtAggregator (new debt requires debt)
       DebtCalculator.class,
       DebtAggregator.class,
       NewDebtCalculator.class,
@@ -206,19 +231,18 @@ public class ComputeEngineContainerImpl extends ComponentContainer implements Co
       RuleTagsCopier.class,
       IssueCounter.class,
 
-      UpdateConflictResolver.class,
+    UpdateConflictResolver.class,
       TrackerBaseInputFactory.class,
       TrackerRawInputFactory.class,
       Tracker.class,
       TrackerExecution.class,
       BaseIssuesLoader.class,
 
-      // views
+    // views
       ViewIndex.class,
 
-      // ComputationService
-      ComputationService.class
-      );
+    // ComputationService
+      ComputationService.class);
   }
 
   @Override

diff --git a/server/sonar-server/src/test/java/org/sonar/server/computation/ComputationServiceTest.java b/server/sonar-server/src/test/java/org/sonar/server/computation/ComputationServiceTest.java
index 199c9e45e66f9a351da21f270f3819483e62eadc..1a7b654d47f2d1eafd03cc1605bdc6538be75861 100644 (file)
--- a/server/sonar-server/src/test/java/org/sonar/server/computation/ComputationServiceTest.java
+++ b/server/sonar-server/src/test/java/org/sonar/server/computation/ComputationServiceTest.java
@@ -74,8 +74,9 @@ public class ComputationServiceTest {
     assertThat(dto.getFinishedAt()).isNotNull();
 
     // one info log at the end
-    assertThat(logTester.logs(LoggerLevel.INFO)).hasSize(1);
-    assertThat(logTester.logs(LoggerLevel.INFO).get(0)).startsWith("Analysis of project P1 (report 1) (done) | time=");
+    assertThat(logTester.logs(LoggerLevel.INFO)).hasSize(3);
+//    assertThat(logTester.logs(LoggerLevel.INFO).get(0)).startsWith("Analysis of project P1 (report 1) (done) | time=");
+    assertThat(logTester.logs(LoggerLevel.INFO).get(2)).startsWith("Analysis of project P1 (report 1) total time spent in steps=");
 
     // execute only the steps supporting the project qualifier
     verify(projectStep1).execute();