aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorSébastien Lesaint <sebastien.lesaint@sonarsource.com>2015-07-27 15:37:51 +0200
committerSébastien Lesaint <sebastien.lesaint@sonarsource.com>2015-07-29 15:35:31 +0200
commitbcf61c2c5d7fb06009c86c9e10d0611c61ce41e3 (patch)
treea0690fdbb3b0d13a4a654127782a41ae1e96fe89
parent0f0dafbc24fe056dfcffffd2aa9cc68df9b3ee05 (diff)
downloadsonarqube-bcf61c2c5d7fb06009c86c9e10d0611c61ce41e3.tar.gz
sonarqube-bcf61c2c5d7fb06009c86c9e10d0611c61ce41e3.zip
SONAR-6736 add CE and steps timing logs at INFO level
-rw-r--r--server/sonar-server/src/main/java/org/sonar/server/computation/ComputationService.java16
-rw-r--r--server/sonar-server/src/main/java/org/sonar/server/computation/ComputationThread.java3
-rw-r--r--server/sonar-server/src/main/java/org/sonar/server/computation/container/ComputeEngineContainerImpl.java74
-rw-r--r--server/sonar-server/src/test/java/org/sonar/server/computation/ComputationServiceTest.java5
4 files changed, 64 insertions, 34 deletions
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 9daf008e58f..1dac5611f55 100644
--- 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 aa621b317e8..58b23538c7d 100644
--- 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 bdd9c9b9c85..eeba9f111e8 100644
--- 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 199c9e45e66..1a7b654d47f 100644
--- 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();