diff --git a/src/main/java/de/flapdoodle/embed/mongo/transitions/RunningMongodProcess.java b/src/main/java/de/flapdoodle/embed/mongo/transitions/RunningMongodProcess.java index 671e7783..34723560 100644 --- a/src/main/java/de/flapdoodle/embed/mongo/transitions/RunningMongodProcess.java +++ b/src/main/java/de/flapdoodle/embed/mongo/transitions/RunningMongodProcess.java @@ -37,9 +37,7 @@ import java.net.UnknownHostException; import java.nio.file.Path; import java.util.Arrays; -import java.util.HashSet; import java.util.List; -import java.util.Set; public class RunningMongodProcess extends RunningProcessImpl { @@ -134,15 +132,25 @@ public static RunningProcessFactory factory(long startupTi // LogWatchStreamProcessor logWatch = new LogWatchStreamProcessor(successMessage(), knownFailureMessages(), // StreamToLineProcessor.wrap(processOutput.output())); + LOGGER.trace("setup logWatch"); SuccessMessageLineListener logWatch = SuccessMessageLineListener.of(successMessage(), knownFailureMessages(), "error"); + LOGGER.trace("connect io"); ReaderProcessor output = Processors.connect(process.getReader(), new ListeningStreamProcessor(StreamToLineProcessor.wrap(processOutput.output()), logWatch::inspect)); ReaderProcessor error = Processors.connect(process.getError(), StreamToLineProcessor.wrap(processOutput.error())); - Runnable closeAllOutputs = () -> ReaderProcessor.abortAll(output, error); + Runnable closeAllOutputs = () -> { + LOGGER.trace("ReaderProcessor.abortAll"); + ReaderProcessor.abortAll(output, error); + LOGGER.trace("ReaderProcessor.abortAll done"); + }; + LOGGER.trace("waitForResult"); logWatch.waitForResult(startupTimeout); + LOGGER.trace("check if successMessageFound"); if (logWatch.successMessageFound()) { + LOGGER.trace("getMongodProcessId"); int pid = Mongod.getMongodProcessId(logWatch.allLines(), -1); + LOGGER.trace("return RunningMongodProcess"); return new RunningMongodProcess(process, pidFile, timeout, closeAllOutputs, supportConfig, platform, net, processOutput.commands(), pid); } else { @@ -176,7 +184,8 @@ private static List knownFailureMessages() { "(?failed errno)", "ERROR:(?.*)", "(?error command line)", - "(?Address already in use)" + "(?Address already in use)", + "(?error while loading shared libraries:.*)" ); } diff --git a/src/test/java/de/flapdoodle/embed/mongo/transitions/MongodTest.java b/src/test/java/de/flapdoodle/embed/mongo/transitions/MongodTest.java index a0fe0f61..5200d0c4 100644 --- a/src/test/java/de/flapdoodle/embed/mongo/transitions/MongodTest.java +++ b/src/test/java/de/flapdoodle/embed/mongo/transitions/MongodTest.java @@ -40,10 +40,12 @@ import de.flapdoodle.embed.process.runtime.Network; import de.flapdoodle.embed.process.store.ExtractedFileSetStore; import de.flapdoodle.os.*; +import de.flapdoodle.reverse.Listener; import de.flapdoodle.reverse.StateID; import de.flapdoodle.reverse.Transition; import de.flapdoodle.reverse.TransitionWalker; import de.flapdoodle.reverse.transitions.Start; +import de.flapdoodle.types.Pair; import org.assertj.core.api.Assertions; import org.bson.Document; import org.junit.Assume; @@ -62,6 +64,7 @@ import java.util.ArrayList; import java.util.Date; import java.util.List; +import java.util.function.Supplier; import static de.flapdoodle.embed.mongo.ServerAddressMapping.serverAddress; import static org.assertj.core.api.Assertions.assertThat; @@ -155,6 +158,68 @@ public void perfTest() throws IOException { } } + @Test + public void measureTimeSpend() throws IOException { + Mongod mongod = Mongod.instance() + .withMongodArguments(Start.to(MongodArguments.class) + .initializedWith(MongodArguments.defaults() + .withUseNoPrealloc(true) + .withUseSmallFiles(true))) +// .withProcessOutput(Start.to(ProcessOutput.class) +// .initializedWith(ProcessOutput.silent())) + ; + + Supplier timeStamp=System::currentTimeMillis; + List, Long>> timeline=new ArrayList<>(); + + Listener listener=new Listener() { + @Override public void onStateReached(StateID stateID, T value) { + timeline.add(Pair.of(stateID, timeStamp.get())); + } + + @Override public void onStateTearDown(StateID stateID, T value) { + timeline.add(Pair.of(stateID, timeStamp.get())); + } + }; + + timeline.add(Pair.of(StateID.of(Void.class),timeStamp.get())); + + try (TransitionWalker.ReachedState runningMongod = mongod.transitions(Version.Main.PRODUCTION) + .walker() + .initState(StateID.of(RunningMongodProcess.class), listener)) { + try (MongoClient mongo = new MongoClient(serverAddress(runningMongod.current().getServerAddress()))) { + DB db = mongo.getDB("test"); + DBCollection col = db.createCollection("testCol", new BasicDBObject()); + col.save(new BasicDBObject("testDoc", new Date())); + } + } + + timeline.add(Pair.of(StateID.of(Void.class),timeStamp.get())); + + int lastEntryOffset=timeline.size()-1; + + long start=timeline.get(0).second(); + long end=timeline.get(lastEntryOffset).second(); + + String columnFormat="| %-25s | %4s | %4s | %5s |%n"; + System.out.println("---------------------------------------------------"); + System.out.printf(columnFormat,"State","up","down","<->"); + System.out.println("---------------------------------------------------"); + for (int i = 0; i < timeline.size()/2; i++) { + Pair, Long> startEntry = timeline.get(i); + Pair, Long> endEntry = timeline.get(lastEntryOffset-i); + long timeSpendOnStart=startEntry.second()-start; + long timeSpendOnTeardown=end-endEntry.second(); + long timeStateIsActive=endEntry.second()-startEntry.second(); + + System.out.printf(columnFormat, startEntry.first().type().getSimpleName(), timeSpendOnStart, timeSpendOnTeardown, timeStateIsActive); + + end=endEntry.second(); + start=startEntry.second(); + } + System.out.println("---------------------------------------------------"); + } + @Test public void startTwoMongodInstancesUsingDifferentPorts() throws UnknownHostException { try (TransitionWalker.ReachedState outerMongod = Mongod.instance().start(Version.Main.PRODUCTION)) { diff --git a/src/test/resources/simplelogger.properties b/src/test/resources/simplelogger.properties index acc5a787..261a5559 100644 --- a/src/test/resources/simplelogger.properties +++ b/src/test/resources/simplelogger.properties @@ -20,3 +20,6 @@ # org.slf4j.simpleLogger.defaultLogLevel=trace +org.slf4j.simpleLogger.log.org.mongodb=info +#org.slf4j.simpleLogger.log.de.flapdoodle.embed.mongo=debug +org.slf4j.simpleLogger.showDateTime=true