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