The roughest of performance measurements

justfile

@@ -1,3 +1,6 @@
+updates-flags := "-q '-Dmaven.version.ignore=.*\\.Beta\\d*,.*\\.BETA\\d*,.*-beta-\\d*,.*\\.android\\d*,.*-M\\d' -Dversions.outputFile=updates.txt -Dversions.outputLineWidth=1000 -P release"
+mvn := "mvn"
+
 # Prints a help text and exits to catch a bare "just" invocation
 help:
   @just --list
@@ -28,3 +31,9 @@ outdated-rust module:
 outdated-rust-all:
   just outdated-rust live
   just outdated-rust irc
+
+outdated-java:
+  {{mvn}} versions:display-plugin-updates {{updates-flags}} && { grep -- "->" updates.txt */updates.txt */*/updates.txt | sed 's/\.\+/./g'; }
+  {{mvn}} versions:display-property-updates {{updates-flags}} && { grep -- "->" updates.txt */updates.txt */*/updates.txt | sed 's/\.\+/./g'; }
+  {{mvn}} versions:display-dependency-updates {{updates-flags}} && { grep -- "->" updates.txt */updates.txt */*/updates.txt | sed 's/\.\+/./g'; }
+  rm updates.txt */updates.txt */*/updates.txt

pom.xml

@@ -32,7 +32,7 @@
 		<spotbugs.version>4.8.5</spotbugs.version>
 		<spotbugs.plugin.version>4.8.3.1</spotbugs.plugin.version>
 		<project.build.outputTimestamp>2020-02-20T20:20:20Z</project.build.outputTimestamp>
-		<mockito.version>5.12.0</mockito.version>
+		<mockito.version>5.14.2</mockito.version>
 		<rabbitmq.version>5.21.0</rabbitmq.version>
 		<lombok.version>1.18.32</lombok.version>
 		<mysql-connector-java.version>8.4.0</mysql-connector-java.version>

tillerinobot-model/src/main/java/org/tillerino/ppaddict/chat/GameChatEvent.java

@@ -41,4 +41,8 @@ public int getPriority() {
 		}
 		return 1;
 	}
+
+	public void completePhase(String name) {
+		meta.getTimer().completePhase(name);
+	}
 }

tillerinobot-model/src/main/java/org/tillerino/ppaddict/chat/GameChatEventMeta.java

@@ -3,6 +3,7 @@
 import org.tillerino.ppaddict.util.MdcUtils.MdcSnapshot;
 
 import lombok.Data;
+import org.tillerino.ppaddict.util.PhaseTimer;
 
 /**
  * This is non-critical meta information of a {@link GameChatEvent} which is implemented as mutable.
@@ -12,4 +13,6 @@ public class GameChatEventMeta {
 	private long rateLimiterBlockedTime;
 
 	private MdcSnapshot mdc;
+
+	private PhaseTimer timer;
 }

tillerinobot-model/src/main/java/org/tillerino/ppaddict/util/PhaseTimer.java

@@ -0,0 +1,55 @@
+package org.tillerino.ppaddict.util;
+
+import lombok.Getter;
+import lombok.Setter;
+import org.apache.commons.lang3.StringUtils;
+
+import javax.annotation.Nullable;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.stream.Collectors;
+
+/**
+ * This is a simple timer to measure the duration of phases of a process.
+ * Since there is a lot of heap activity, this is meant for rough measurements.
+ * It is meant to be serialized to be able to trace events through all queues and threads.
+ */
+@Getter
+@Setter
+public class PhaseTimer {
+	public static final String PREPROCESS = "preprocess";
+	public static final String INTERNAL_QUEUE = "eventQueue";
+	public static final String THREAD_POOL_QUEUE = "threadPoolQueue";
+	public static final String HANDLE = "handle";
+	public static final String RESPONSE_QUEUE = "responseQueue";
+	public static final String POSTPROCESS = "postprocess";
+
+	private long endOfLastPhase = System.nanoTime();
+	private @Nullable List<Phase> completedPhases;
+
+	public void completePhase(String name) {
+		long now = System.nanoTime();
+		if (completedPhases == null) {
+			completedPhases = new ArrayList<>();
+		}
+		completedPhases.add(new Phase(name, now - endOfLastPhase));
+		endOfLastPhase = now;
+	}
+
+	public void print() {
+		if (completedPhases == null) {
+			return;
+		}
+		System.out.println("total:" + leftPad((int) Math.round(completedPhases.stream().mapToLong(p -> p.duration).sum() / 1_000_000D)) + "ms"
+				+ completedPhases.stream()
+				.map(p -> ", " + p.name + ":" + leftPad((int) Math.round(p.duration / 1_000_000D)) + "ms")
+				.collect(Collectors.joining()));
+	}
+
+	public static String leftPad(int x) {
+		return StringUtils.leftPad(Integer.toString(x), 5);
+	}
+
+	record Phase(String name, long duration) {
+	}
+}

tillerinobot-model/src/test/java/org/tillerino/ppaddict/chat/GameChatEventTest.java

@@ -10,7 +10,7 @@ public class GameChatEventTest {
 	@Test
 	public void joinedSerialization() throws Exception {
 		String expected = """
-				{"@c":".Joined","eventId":123,"nick":"nick","timestamp":456,"meta":{"rateLimiterBlockedTime":0,"mdc":null}}
+				{"@c":".Joined","eventId":123,"nick":"nick","timestamp":456,"meta":{"rateLimiterBlockedTime":0,"mdc":null,"timer":null}}
 			""";
 		Joined joined = new Joined(123, "nick", 456);
 		String actual = new ObjectMapper().writeValueAsString(joined);

tillerinobot/src/main/java/org/tillerino/ppaddict/chat/impl/MessageHandlerScheduler.java

@@ -19,6 +19,7 @@
 
 import lombok.RequiredArgsConstructor;
 import lombok.extern.slf4j.Slf4j;
+import org.tillerino.ppaddict.util.PhaseTimer;
 import tillerino.tillerinobot.IRCBot;
 
 /**
@@ -36,7 +37,9 @@ public class MessageHandlerScheduler implements GameChatEventConsumer {
 
 	@Override
 	public void onEvent(GameChatEvent event) throws InterruptedException {
+		event.completePhase(PhaseTimer.INTERNAL_QUEUE);
 		Runnable task = () -> {
+			event.completePhase(PhaseTimer.THREAD_POOL_QUEUE);
 			try (MdcAttributes attr = event.getMeta().getMdc().apply()) {
 				messageHandler.onEvent(event);
 			} catch (Throwable e) {

tillerinobot/src/main/java/org/tillerino/ppaddict/chat/impl/MessagePreprocessor.java

@@ -20,6 +20,7 @@
 import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
 import lombok.RequiredArgsConstructor;
 import lombok.extern.slf4j.Slf4j;
+import org.tillerino.ppaddict.util.PhaseTimer;
 
 /**
  * Here we do anything that we can do right after we receive the message and
@@ -48,6 +49,7 @@ public void onEvent(GameChatEvent event) throws InterruptedException {
 		try (MdcAttributes mdc = MdcUtils.with(MdcUtils.MDC_EVENT, event.getEventId())) {
 			mdc.add(MdcUtils.MDC_USER, event.getNick());
 			event.getMeta().setMdc(MdcUtils.getSnapshot());
+			event.getMeta().setTimer(new PhaseTimer());
 
 			if (event instanceof PrivateMessage || event instanceof PrivateAction) {
 				liveActivity.propagateReceivedMessage(event.getNick(), event.getEventId());
@@ -66,6 +68,8 @@ public void onEvent(GameChatEvent event) throws InterruptedException {
 				responses.onResponse(handleSemaphoreInUse(event), event);
 				return;
 			}
+
+			event.completePhase(PhaseTimer.PREPROCESS);
 			queue.onEvent(event);
 		}
 	}

tillerinobot/src/main/java/org/tillerino/ppaddict/chat/impl/ResponsePostprocessor.java

@@ -2,7 +2,6 @@
 
 import java.io.IOException;
 import java.util.Objects;
-import java.util.Optional;
 
 import javax.inject.Inject;
 
@@ -22,6 +21,7 @@
 import org.tillerino.ppaddict.util.Clock;
 import org.tillerino.ppaddict.util.MdcUtils;
 import org.tillerino.ppaddict.util.MdcUtils.MdcAttributes;
+import org.tillerino.ppaddict.util.PhaseTimer;
 import org.tillerino.ppaddict.util.Result;
 import org.tillerino.ppaddict.util.Result.Err;
 
@@ -49,6 +49,7 @@ public class ResponsePostprocessor implements GameChatResponseConsumer {
 
 	@Override
 	public void onResponse(GameChatResponse response, GameChatEvent event) throws InterruptedException {
+		event.completePhase(PhaseTimer.RESPONSE_QUEUE);
 		try {
 			for (GameChatResponse r : response.flatten()) {
 				for (int i = 0; i < 10; i++) { // arbitrary retry limit greater than zero
@@ -109,6 +110,7 @@ private Result<Response, Error> message(String msg, boolean success, GameChatEve
 				}
 				liveActivity.propagateSentMessage(result.getNick(), result.getEventId(), ok.ping());
 				if (success) {
+					result.completePhase(PhaseTimer.POSTPROCESS);
 					mdc.add(MdcUtils.MDC_DURATION, clock.currentTimeMillis() - result.getTimestamp());
 					mdc.add(MdcUtils.MDC_SUCCESS, true);
 					mdc.add(MdcUtils.MCD_OSU_API_RATE_BLOCKED_TIME, result.getMeta().getRateLimiterBlockedTime());
@@ -117,6 +119,7 @@ private Result<Response, Error> message(String msg, boolean success, GameChatEve
 					}
 				}
 				log.debug("sent: " + msg);
+				result.getMeta().getTimer().print();
 				botInfo.setLastSentMessage(clock.currentTimeMillis());
 			}
 			return ok;

tillerinobot/src/main/java/tillerino/tillerinobot/IRCBot.java

@@ -37,6 +37,7 @@
 
 import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
 import lombok.extern.slf4j.Slf4j;
+import org.tillerino.ppaddict.util.PhaseTimer;
 import tillerino.tillerinobot.UserDataManager.UserData;
 import tillerino.tillerinobot.handlers.AccHandler;
 import tillerino.tillerinobot.handlers.ComplaintHandler;
@@ -281,7 +282,13 @@ public void onEvent(GameChatEvent event) {
 			rateLimiter.blockedTime();
 
 			try {
-				sendResponse(visit(event), event);
+				GameChatResponse visit;
+				try {
+					visit = visit(event);
+				} finally {
+					event.completePhase(PhaseTimer.HANDLE);
+				}
+				sendResponse(visit, event);
 			} catch (SQLException | IOException | UserException e) {
 				GameChatResponse exceptionResponse = handleException(e, new Default());
 				if (event.isInteractive()) {

tillerinobot/src/test/java/org/tillerino/ppaddict/chat/impl/ResponsePostprocessorTest.java

@@ -21,19 +21,15 @@
 import org.mockito.Spy;
 import org.mockito.junit.MockitoJUnitRunner;
 import org.slf4j.MDC;
-import org.tillerino.ppaddict.chat.GameChatResponse;
+import org.tillerino.ppaddict.chat.*;
 import org.tillerino.ppaddict.chat.GameChatResponse.Action;
 import org.tillerino.ppaddict.chat.GameChatResponse.Message;
 import org.tillerino.ppaddict.chat.GameChatResponse.Success;
-import org.tillerino.ppaddict.chat.GameChatWriter;
-import org.tillerino.ppaddict.chat.Joined;
-import org.tillerino.ppaddict.chat.LiveActivity;
-import org.tillerino.ppaddict.chat.PrivateMessage;
-import org.tillerino.ppaddict.chat.Sighted;
 import org.tillerino.ppaddict.chat.local.LocalGameChatMetrics;
 import org.tillerino.ppaddict.util.Clock;
 import org.tillerino.ppaddict.util.MdcUtils;
 import org.tillerino.ppaddict.util.MdcUtils.MdcAttributes;
+import org.tillerino.ppaddict.util.PhaseTimer;
 
 @RunWith(MockitoJUnitRunner.class)
 public class ResponsePostprocessorTest {
@@ -55,24 +51,25 @@ public class ResponsePostprocessorTest {
 	@InjectMocks
 	private ResponsePostprocessor responsePostprocessor;
 
+	PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
+
 	@Before
 	public void setUp() throws Exception {
 		when(writer.action(any(), any())).thenReturn(ok(new GameChatWriter.Response(null)));
 		when(writer.message(any(), any())).thenReturn(ok(new GameChatWriter.Response(null)));
+		event.getMeta().setTimer(new PhaseTimer());
 	}
 
 	@Test
 	public void testAction() throws Exception {
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
-		responsePostprocessor.onResponse(new Action("xyz"), event);
+		responsePostprocessor.onResponse( new Action("xyz"), event);
 		verify(writer).action("xyz", "nick");
 		verify(liveActivity).propagateSentMessage("nick", 1, null);
 		verify(bouncer).exit("nick", 1);
 	}
 
 	@Test
 	public void testMessage() throws Exception {
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 		responsePostprocessor.onResponse(new Message("xyz"), event);
 		verify(writer).message("xyz", "nick");
 		verify(liveActivity).propagateSentMessage("nick", 1, null);
@@ -82,7 +79,6 @@ public void testMessage() throws Exception {
 
 	@Test
 	public void testSuccess() throws Exception {
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 		responsePostprocessor.onResponse(new Success("xyz"), event);
 		verify(writer).message("xyz", "nick");
 		verify(liveActivity).propagateSentMessage("nick", 1, null);
@@ -91,7 +87,6 @@ public void testSuccess() throws Exception {
 
 	@Test
 	public void testList() throws Exception {
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 		responsePostprocessor.onResponse(new Message("xyz").then(new Action("abc")), event);
 		verify(writer).message("xyz", "nick");
 		verify(writer).action("abc", "nick");
@@ -101,7 +96,6 @@ public void testList() throws Exception {
 
 	@Test
 	public void testNoResponse() throws Exception {
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 		responsePostprocessor.onResponse(GameChatResponse.none(), event);
 		verifyNoInteractions(writer);
 		verifyNoInteractions(liveActivity);
@@ -112,7 +106,6 @@ public void testNoResponse() throws Exception {
 	public void testRecommendation() throws Exception {
 		when(clock.currentTimeMillis()).thenReturn(159L);
 		try (MdcAttributes mdc = MdcUtils.with("handler", "r")) {
-			PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 			responsePostprocessor.onResponse(new Success("xyz"), event);
 			verify(botInfo).setLastRecommendation(159);
 		}
@@ -121,6 +114,7 @@ public void testRecommendation() throws Exception {
 	@Test
 	public void testNoBouncerForNonInteractiveEvents() throws Exception {
 		Sighted event = new Sighted(1, "nick", 2);
+		event.getMeta().setTimer(new PhaseTimer());
 		responsePostprocessor.onResponse(new Success("hai"), event);
 		verify(writer).message("hai", "nick");
 		verifyNoInteractions(bouncer);
@@ -137,7 +131,6 @@ public void testMdcThrowup() throws Exception {
 			assertThat(MDC.get("osuApiRateBlockedTime")).isEqualTo("32");
 			return null;
 		}).when(botInfo).setLastSentMessage(123L);
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 		event.getMeta().setRateLimiterBlockedTime(32);
 		when(clock.currentTimeMillis()).thenReturn(123L);
 		responsePostprocessor.onResponse(new Success("yeah"), event);
@@ -155,7 +148,6 @@ public void testNoMdcThrowupForPlainMessage() throws Exception {
 			assertThat(MDC.get("osuApiRateBlockedTime")).isNull();
 			return null;
 		}).when(botInfo).setLastSentMessage(123L);
-		PrivateMessage event = new PrivateMessage(1, "nick", 2, "yo");
 		event.getMeta().setRateLimiterBlockedTime(32);
 		when(clock.currentTimeMillis()).thenReturn(123L);
 		responsePostprocessor.onResponse(new Message("yeah"), event);
@@ -164,7 +156,6 @@ public void testNoMdcThrowupForPlainMessage() throws Exception {
 
 	@Test
 	public void writingIsRetried() throws Exception {
-		Joined event = new Joined(1234, "nick", 0);
 		int[] count = { 0 };
 		doAnswer(x -> {
 			if (count[0]++ > 0) {
@@ -178,7 +169,6 @@ public void writingIsRetried() throws Exception {
 
 	@Test
 	public void retryingStops() throws Exception {
-		Joined event = new Joined(1234, "nick", 0);
 		doReturn(err(new GameChatWriter.Error.Retry(0))).when(writer).message("abc", "nick");
 		responsePostprocessor.onResponse(new Message("abc"), event);
 		verify(writer, times(10)).message("abc", "nick");