How to use

logTimeLast

method

in

org.sonar.core.util.logs.Profiler

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

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");
}

@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");
}

@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");
}

@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");
}

@Test
public void stopInfo_clears_context() {
 addSomeContext(underTest);
 underTest.logTimeLast(true);
 underTest.start().stopInfo("Foo");
 underTest.start().stopInfo("Bar");
 assertThat(tester.logs()).hasSize(2);
 List<String> logs = tester.logs(LoggerLevel.INFO);
 assertThat(logs.get(0))
   .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=")
   .endsWith("ms");
 assertThat(logs.get(1))
   .startsWith("Bar | time=")
   .endsWith("ms");
}

@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=");
}

@Test
public void stopDebug_clears_context() {
 tester.setLevel(LoggerLevel.DEBUG);
 addSomeContext(underTest);
 underTest.logTimeLast(true);
 underTest.start().stopDebug("Foo");
 underTest.start().stopDebug("Bar");
 assertThat(tester.logs()).hasSize(2);
 List<String> logs = tester.logs(LoggerLevel.DEBUG);
 assertThat(logs.get(0))
   .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=")
   .endsWith("ms");
 assertThat(logs.get(1))
   .startsWith("Bar | time=")
   .endsWith("ms");
}

@Test
public void stopTrace_clears_context() {
 tester.setLevel(LoggerLevel.TRACE);
 addSomeContext(underTest);
 underTest.logTimeLast(true);
 underTest.start().stopTrace("Foo");
 underTest.start().stopTrace("Bar");
 assertThat(tester.logs()).hasSize(2);
 List<String> logs = tester.logs(LoggerLevel.TRACE);
 assertThat(logs.get(0))
   .startsWith("Foo | a_string=bar | an_int=42 | after_start=true | time=")
   .endsWith("ms");
 assertThat(logs.get(1))
   .startsWith("Bar | time=")
   .endsWith("ms");
}

@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
@UseDataProvider("logTimeLastValues")
public void stop_reuses_start_message(boolean logTimeLast) throws InterruptedException {
 underTest.logTimeLast(logTimeLast);
 tester.setLevel(LoggerLevel.TRACE);

 private static void addContext(Profiler profiler, CeTask task) {
  profiler
   .logTimeLast(true)
   .addContext("project", task.getComponentKey())
   .addContext("type", task.getType())
   .addContext("id", task.getUuid());
  String submitterLogin = task.getSubmitterLogin();
  if (submitterLogin != null) {
   profiler.addContext("submitter", submitterLogin);
  }
 }
}