How to use

Profiler

in

org.sonar.core.util.logs

@Override
public void execute(List<RegisteredMigrationStep> steps) {
 Profiler globalProfiler = Profiler.create(LOGGER);
 globalProfiler.startInfo(GLOBAL_START_MESSAGE);
 boolean allStepsExecuted = false;
 try {
  steps.forEach(this::execute);
  allStepsExecuted = true;
 } finally {
  if (allStepsExecuted) {
   globalProfiler.stopInfo(GLOBAL_END_MESSAGE, "success");
  } else {
   globalProfiler.stopError(GLOBAL_END_MESSAGE, "failure");
  }
 }
}

private static Profiler startLogProfiler(CeTask task) {
 Profiler profiler = Profiler.create(LOG)
  .logTimeLast(true)
  .addContext("project", task.getMainComponent().flatMap(CeTask.Component::getKey).orElse(null))
  .addContext("type", task.getType());
 for (Map.Entry<String, String> characteristic : task.getCharacteristics().entrySet()) {
  profiler.addContext(characteristic.getKey(), characteristic.getValue());
 }
 return profiler
  .addContext("id", task.getUuid())
  .addContext("submitter", submitterOf(task))
  .startInfo("Execute task");
}

private void doUpgradeDb() {
 Profiler profiler = Profiler.createIfTrace(LOGGER);
 profiler.startTrace("Starting DB Migration");
 migrationEngine.execute();
 profiler.stopTrace("DB Migration ended");
}

private static void stopLogProfiler(Profiler profiler, CeActivityDto.Status status) {
 profiler.addContext("status", status.name());
 profiler.stopInfo("Executed task");
}

private void execute(Collection<ModuleSensorWrapper> sensors) {
 for (ModuleSensorWrapper sensor : sensors) {
  String sensorName = getSensorName(sensor);
  profiler.startInfo("Sensor " + sensorName);
  sensor.analyse();
  profiler.stopInfo();
 }
}

@Test
@UseDataProvider("logTimeLastValues")
public void different_start_and_stop_messages(boolean logTimeLast) {
 underTest.logTimeLast(logTimeLast);
 tester.setLevel(LoggerLevel.TRACE);
 // start TRACE and stop DEBUG
 underTest.startTrace("Register rules");
 underTest.stopDebug("Rules registered");
 assertThat(tester.logs()).hasSize(2);
 assertThat(tester.logs().get(0)).contains("Register rules");
 assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
 tester.clear();
 // start DEBUG and stop INFO
 underTest.startDebug("Register rules {}", 10);
 underTest.stopInfo("Rules registered");
 assertThat(tester.logs()).hasSize(2);
 assertThat(tester.logs().get(0)).contains("Register rules 10");
 assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
 tester.clear();
 // start INFO and stop TRACE
 underTest.startInfo("Register rules");
 underTest.stopTrace("Rules registered");
 assertThat(tester.logs()).hasSize(2);
 assertThat(tester.logs().get(0)).contains("Register rules");
 assertThat(tester.logs().get(1)).startsWith("Rules registered | time=");
}

public static Profiler createIfDebug(Logger logger) {
 if (logger.isDebugEnabled()) {
  return create(logger);
 }
 return NullProfiler.NULL_INSTANCE;
}

private void visitNode(Component component, VisitorWrapper visitor) {
 Profiler profiler = Profiler.create(Loggers.get(visitor.getWrappedVisitor().getClass()))
  .startTrace("Visiting component {}", component.getDbKey());
 visitor.visitAny(component);
 switch (component.getType()) {
  case PROJECT:
   visitor.visitProject(component);
   break;
  case DIRECTORY:
   visitor.visitDirectory(component);
   break;
  case FILE:
   visitor.visitFile(component);
   break;
  case VIEW:
   visitor.visitView(component);
   break;
  case SUBVIEW:
   visitor.visitSubView(component);
   break;
  case PROJECT_VIEW:
   visitor.visitProjectView(component);
   break;
  default:
   throw new IllegalStateException(String.format("Unknown type %s", component.getType().name()));
 }
 long duration = profiler.stopTrace();
 incrementDuration(visitor, duration);
}

@Test
@UseDataProvider("logTimeLastValues")
public void log_on_at_stop(boolean logTimeLast) {
 underTest.logTimeLast(logTimeLast);
 tester.setLevel(LoggerLevel.TRACE);
 // trace
 underTest.start();
 underTest.stopTrace("Rules registered");
 assertThat(tester.logs()).hasSize(1);
 assertThat(tester.logs().get(0)).startsWith("Rules registered | time=");
 tester.clear();
 // debug
 underTest.start();
 underTest.stopDebug("Rules registered {} on {}", 6, 10);
 assertThat(tester.logs()).hasSize(1);
 assertThat(tester.logs().get(0)).startsWith("Rules registered 6 on 10 | time=");
 tester.clear();
 // info
 underTest.start();
 underTest.stopInfo("Rules registered");
 assertThat(tester.logs()).hasSize(1);
 assertThat(tester.logs().get(0)).startsWith("Rules registered | time=");
}

@Test
public void empty_message() {
 underTest.addContext("foo", "bar");
 underTest.startInfo("");
 assertThat(tester.logs()).containsOnly("foo=bar");
 underTest.addContext("after_start", true);
 underTest.stopInfo("");
 assertThat(tester.logs()).hasSize(2);
 assertThat(tester.logs().get(1))
  .startsWith("time=")
  .endsWith("ms | foo=bar | after_start=true");
}

@Test
public void stopInfo_adds_context_before_time_if_logTimeLast_is_true() {
 addSomeContext(underTest);
 underTest.logTimeLast(true);
 underTest.start().stopInfo("Rules registered");
 assertThat(tester.logs()).hasSize(1);
 assertThat(tester.logs(LoggerLevel.INFO).get(0))
  .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=")
  .endsWith("ms");
}

private void executeStep(Profiler stepProfiler, ComputationStep.Context context, ComputationStep step) {
 String status = "FAILED";
 stepProfiler.start();
 try {
  taskInterrupter.check(Thread.currentThread());
  step.execute(context);
  status = "SUCCESS";
 } finally {
  stepProfiler.addContext("status", status);
  stepProfiler.stopInfo(step.getDescription());
 }
}

@Test
@UseDataProvider("logTimeLastValues")
public void stop_reuses_start_message(boolean logTimeLast) throws InterruptedException {
 underTest.logTimeLast(logTimeLast);
 tester.setLevel(LoggerLevel.TRACE);
 underTest.startTrace("Register rules {}", 1);
 Thread.sleep(2);
 assertThat(tester.logs()).containsOnly("Register rules 1");
 long timing = underTest.stopTrace();
 assertThat(timing).isGreaterThan(0);
 assertThat(tester.logs()).hasSize(2);
 underTest.startDebug("Register rules");
 Thread.sleep(2);
 assertThat(tester.logs()).containsOnly("Register rules");
 timing = underTest.stopTrace();
 assertThat(timing).isGreaterThan(0);
 assertThat(tester.logs()).hasSize(2);
 underTest.startInfo("Register rules");
 Thread.sleep(2);
 assertThat(tester.logs()).containsOnly("Register rules");
 timing = underTest.stopTrace();
 assertThat(timing).isGreaterThan(0);
 assertThat(tester.logs()).hasSize(2);

private static Profiler startActivityProfiler(CeTask task) {
 Profiler profiler = Profiler.create(LOG);
 addContext(profiler, task);
 return profiler.startInfo("Execute task");
}

public void execute() {
 Profiler stepProfiler = Profiler.create(LOGGER).logTimeLast(true);
 boolean allStepsExecuted = false;
 try {
  executeSteps(stepProfiler);
  allStepsExecuted = true;
 } finally {
  if (listener != null) {
   executeListener(allStepsExecuted);
  }
 }
}

@Test
public void fail_if_stop_without_message() {
 underTest.start();
 try {
  underTest.stopInfo();
  fail();
 } catch (IllegalStateException e) {
  assertThat(e).hasMessage("Profiler#stopXXX() can't be called without any message defined in start methods");
 }
}

@Test
public void stopTrace_adds_context_before_time_if_logTimeLast_is_true() {
 tester.setLevel(LoggerLevel.TRACE);
 addSomeContext(underTest);
 underTest.logTimeLast(true);
 underTest.start().stopTrace("Rules registered");
 assertThat(tester.logs()).hasSize(1);
 assertThat(tester.logs(LoggerLevel.TRACE).get(0))
  .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=")
  .endsWith("ms");
}

 return;
Profiler p = Profiler.createIfTrace(LOG);
p.start();
Map<String, Component> reportFilesByUuid = getReportFilesByUuid(this.rootHolder.getRoot());
context.getStatistics().add("reportFiles", reportFilesByUuid.size());
p.stopTrace("loaded");
p.start();
ScoreMatrix scoreMatrix = computeScoreMatrix(dbFilesByUuid, removedFileUuids, reportFileSourcesByUuid);
p.stopTrace("Score matrix computed");
scoreMatrixDumper.dumpAsCsv(scoreMatrix);
p.start();
MatchesByScore matchesByScore = MatchesByScore.create(scoreMatrix);
p.stopTrace("Matches elected");

private static void stopActivityProfiler(Profiler profiler, CeTask task, CeActivityDto.Status status) {
 addContext(profiler, task);
 if (status == CeActivityDto.Status.FAILED) {
  profiler.stopError("Executed task");
 } else {
  profiler.stopInfo("Executed task");
 }
}

@Test
public void stopError_adds_context_before_time_if_logTimeLast_is_true() {
 addSomeContext(underTest);
 underTest.logTimeLast(true);
 underTest.start().stopError("Rules registered");
 assertThat(tester.logs()).hasSize(1);
 assertThat(tester.logs(LoggerLevel.ERROR).get(0))
  .startsWith("Rules registered | a_string=bar | an_int=42 | after_start=true | time=")
  .endsWith("ms");
}