perf test

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<RunningMongodProcess> 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<String> knownFailureMessages() {
 			"(?<error>failed errno)",
 			"ERROR:(?<error>.*)",
 			"(?<error>error command line)",
-			"(?<error>Address already in use)"
+			"(?<error>Address already in use)",
+			"(?<error>error while loading shared libraries:.*)"
 		);
 	}
 

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<Long> timeStamp=System::currentTimeMillis;
+		List<Pair<StateID<?>, Long>> timeline=new ArrayList<>();
+
+		Listener listener=new Listener() {
+			@Override public <T> void onStateReached(StateID<T> stateID, T value) {
+				timeline.add(Pair.of(stateID, timeStamp.get()));
+			}
+
+			@Override public <T> void onStateTearDown(StateID<T> stateID, T value) {
+				timeline.add(Pair.of(stateID, timeStamp.get()));
+			}
+		};
+
+		timeline.add(Pair.of(StateID.of(Void.class),timeStamp.get()));
+
+		try (TransitionWalker.ReachedState<RunningMongodProcess> 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<StateID<?>, Long> startEntry = timeline.get(i);
+			Pair<StateID<?>, 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<RunningMongodProcess> outerMongod = Mongod.instance().start(Version.Main.PRODUCTION)) {

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