From bcf61c2c5d7fb06009c86c9e10d0611c61ce41e3 Mon Sep 17 00:00:00 2001 From: =?utf8?q?S=C3=A9bastien=20Lesaint?= Date: Mon, 27 Jul 2015 15:37:51 +0200 Subject: [PATCH] SONAR-6736 add CE and steps timing logs at INFO level --- .../computation/ComputationService.java | 16 ++-- .../server/computation/ComputationThread.java | 3 + .../container/ComputeEngineContainerImpl.java | 74 ++++++++++++------- .../computation/ComputationServiceTest.java | 5 +- 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 void instantiated(PicoContainer container, ComponentAdapter componentAdapter, + Constructor 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(); -- 2.39.5