Ignore time spent waiting on other users when calculating lag. (#125)

Also some performance improvements and adopting kotlinx-datetime. Non-game owners can also use /lagstat now (though not /lagreset yet). Some changes to how activity and ping timeouts are calculated, we will need to test to make sure there are no bugs.
hopskipnfall · Aug 29, 2024 · a116e8f · a116e8f
1 parent f1431c0
commit a116e8f
Show file tree

Hide file tree

Showing 9 changed files with 158 additions and 112 deletions.
diff --git a/emulinker/build.gradle.kts b/emulinker/build.gradle.kts
@@ -49,6 +49,8 @@ dependencies {
   implementation("io.ktor:ktor-server-status-pages-jvm:$ktorVersion")
   implementation("io.ktor:ktor-server-default-headers-jvm:$ktorVersion")
 
+  implementation("org.jetbrains.kotlinx:kotlinx-datetime:0.6.1")
+
   // This is only used by the fake testing client, hopefully we can remove this.
   testImplementation("org.jetbrains.kotlinx:kotlinx-coroutines-core:1.7.1")
 

diff --git a/emulinker/src/main/java/org/emulinker/config/RuntimeFlags.kt b/emulinker/src/main/java/org/emulinker/config/RuntimeFlags.kt
@@ -30,7 +30,7 @@ data class RuntimeFlags(
   val maxGameChatLength: Int,
   val maxGameNameLength: Int,
   val maxGames: Int,
-  val maxPing: Int,
+  val maxPing: Duration,
   val maxQuitMessageLength: Int,
   val maxUserNameLength: Int,
   val maxUsers: Int,
@@ -62,7 +62,7 @@ data class RuntimeFlags(
     require(maxUserNameLength <= 31) { "server.maxUserNameLength must be <= 31" }
     require(maxGameNameLength <= 127) { "server.maxGameNameLength must be <= 127" }
     require(maxClientNameLength <= 127) { "server.maxClientNameLength must be <= 127" }
-    require(maxPing in 1..1000) { "server.maxPing must be in 1..1000" }
+    require(maxPing in 1.milliseconds..1000.milliseconds) { "server.maxPing must be in 1..1000" }
     require(keepAliveTimeout.isPositive()) {
       "server.keepAliveTimeout must be > 0 (190 is recommended)"
     }
@@ -104,7 +104,7 @@ data class RuntimeFlags(
         maxGameChatLength = config.getInt("server.maxGameChatLength"),
         maxGameNameLength = config.getInt("server.maxGameNameLength"),
         maxGames = config.getInt("server.maxGames"),
-        maxPing = config.getInt("server.maxPing"),
+        maxPing = config.getInt("server.maxPing").milliseconds,
         maxQuitMessageLength = config.getInt("server.maxQuitMessageLength"),
         maxUserNameLength = config.getInt("server.maxUserNameLength"),
         maxUsers = config.getInt("server.maxUsers"),

diff --git a/emulinker/src/main/java/org/emulinker/kaillera/controller/v086/V086ClientHandler.kt b/emulinker/src/main/java/org/emulinker/kaillera/controller/v086/V086ClientHandler.kt
@@ -355,9 +355,12 @@ constructor(
     }
   }
 
+  // Caching here for speed.
+  private val maxPingMs: Long = flags.maxPing.inWholeMilliseconds
+
   fun resend(timeoutCounter: Int) {
     // if ((System.currentTimeMillis() - lastResend) > (user.getPing()*3))
-    if (System.currentTimeMillis() - lastResend > controller.server.maxPing) {
+    if (System.currentTimeMillis() - lastResend > maxPingMs) {
       // int numToSend = (3+timeoutCounter);
       var numToSend = 3 * timeoutCounter
       if (numToSend > V086Controller.MAX_BUNDLE_SIZE) numToSend = V086Controller.MAX_BUNDLE_SIZE

diff --git a/emulinker/src/main/java/org/emulinker/kaillera/controller/v086/action/GameChatAction.kt b/emulinker/src/main/java/org/emulinker/kaillera/controller/v086/action/GameChatAction.kt
@@ -484,6 +484,18 @@ internal constructor(
         } else {
           clientHandler.user.game!!.announce("No pending tweets.", clientHandler.user)
         }
+      } else if (message.message == "/lagstat") {
+        // Note: This was duplicated from GameOwnerCommandAction.
+        clientHandler.user.game!!.announce("Lagged frames per player:")
+        clientHandler.user.game!!
+          .players
+          .asSequence()
+          .filter { !it.inStealthMode }
+          .forEach {
+            clientHandler.user.game!!.announce(
+              "P${it.playerNumber}: ${it.smallLagSpikesCausedByUser} (tiny), ${it.bigLagSpikesCausedByUser} (big)"
+            )
+          }
       } else
         clientHandler.user.game!!.announce(
           "Unknown Command: " + message.message,

diff --git a/emulinker/src/main/java/org/emulinker/kaillera/master/client/EmuLinkerMasterUpdateTask.kt b/emulinker/src/main/java/org/emulinker/kaillera/master/client/EmuLinkerMasterUpdateTask.kt
@@ -30,9 +30,9 @@ constructor(
       this.append("website", publicInfo.website)
       this.append("port", flags.serverPort.toString())
       this.append("numUsers", kailleraServer.users.size.toString())
-      this.append("maxUsers", kailleraServer.maxUsers.toString())
+      this.append("maxUsers", flags.maxUsers.toString())
       this.append("numGames", kailleraServer.games.size.toString())
-      this.append("maxGames", kailleraServer.maxGames.toString())
+      this.append("maxGames", flags.maxGames.toString())
       // I want to use `releaseInfo.versionWithElkPrefix` here, but it's too long for the db schema
       // field, so we just write elk (lowercase in protest :P ).
       this.append("version", "elk")

diff --git a/emulinker/src/main/java/org/emulinker/kaillera/master/client/KailleraMasterUpdateTask.kt b/emulinker/src/main/java/org/emulinker/kaillera/master/client/KailleraMasterUpdateTask.kt
@@ -41,7 +41,7 @@ constructor(
       this.append("servername", publicInfo.serverName)
       this.append("port", flags.serverPort.toString())
       this.append("nbusers", kailleraServer.users.size.toString())
-      this.append("maxconn", kailleraServer.maxUsers.toString())
+      this.append("maxconn", flags.maxUsers.toString())
       // I want to use `releaseInfo.versionWithElkPrefix` here, but it's too long for the db schema
       // field, so we just write elk (lowercase in protest :P ).
       this.append("version", "elk")

diff --git a/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraServer.kt b/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraServer.kt
@@ -12,7 +12,9 @@ import javax.inject.Inject
 import javax.inject.Named
 import javax.inject.Singleton
 import kotlin.Throws
+import kotlin.time.Duration
 import kotlin.time.Duration.Companion.milliseconds
+import kotlinx.datetime.Clock
 import org.emulinker.config.RuntimeFlags
 import org.emulinker.kaillera.access.AccessManager
 import org.emulinker.kaillera.lookingforgame.LookingForGameEvent
@@ -54,6 +56,7 @@ internal constructor(
   metrics: MetricRegistry,
   @param:Named("userActionsExecutor") private val userActionsExecutor: ThreadPoolExecutor,
   private val taskScheduler: TaskScheduler,
+  private val clock: Clock,
 ) {
 
   private var allowedConnectionTypes = BooleanArray(7)
@@ -83,10 +86,6 @@ internal constructor(
     return gamesMap[gameID]
   }
 
-  val maxPing: Int = flags.maxPing
-  val maxUsers: Int = flags.maxUsers
-  val maxGames: Int = flags.maxGames
-
   val allowSinglePlayer = flags.allowSinglePlayer
   private val maxUserNameLength: Int = flags.maxUserNameLength
   val maxGameChatLength = flags.maxGameChatLength
@@ -106,8 +105,8 @@ internal constructor(
   fun start() {
     timerTask =
       taskScheduler.scheduleRepeating(
-        period = (flags.maxPing * 3).milliseconds,
-        initialDelay = (flags.maxPing * 3).milliseconds,
+        period = flags.maxPing * 3,
+        initialDelay = flags.maxPing * 3,
       ) {
         run()
       }
@@ -155,7 +154,9 @@ internal constructor(
     val access = accessManager.getAccess(clientSocketAddress.address)
 
     // admins will be allowed in even if the server is full
-    if (flags.maxUsers > 0 && usersMap.size >= maxUsers && access <= AccessManager.ACCESS_NORMAL) {
+    if (
+      flags.maxUsers > 0 && usersMap.size >= flags.maxUsers && access <= AccessManager.ACCESS_NORMAL
+    ) {
       logger
         .atWarning()
         .log(
@@ -173,7 +174,8 @@ internal constructor(
         listener,
         this,
         flags,
-        userActionsExecutor
+        userActionsExecutor,
+        clock,
       )
     user.status = UserStatus.CONNECTING
     logger
@@ -197,11 +199,11 @@ internal constructor(
   )
   fun login(user: KailleraUser?) = withLock {
     val userImpl = user
-    val loginDelay = System.currentTimeMillis() - user!!.connectTime
+    val loginDelay: Duration = clock.now() - user!!.connectTime
     logger
       .atInfo()
       .log(
-        "%s: login request: delay=%d ms, clientAddress=%s, name=%s, ping=%d, client=%s, connection=%s",
+        "%s: login request: delay=%s, clientAddress=%s, name=%s, ping=%d, client=%s, connection=%s",
         user,
         loginDelay,
         EmuUtil.formatSocketAddress(user.socketAddress!!),
@@ -226,13 +228,17 @@ internal constructor(
       usersMap.remove(userListKey)
       throw LoginException(EmuLang.getString("KailleraServerImpl.LoginDeniedAccessDenied"))
     }
-    if (access == AccessManager.ACCESS_NORMAL && maxPing > 0 && user.ping > maxPing) {
-      logger.atInfo().log("%s login denied: Ping %d > %d", user, user.ping, maxPing)
+    if (
+      access == AccessManager.ACCESS_NORMAL &&
+        flags.maxPing > 0.milliseconds &&
+        user.ping.milliseconds > flags.maxPing
+    ) {
+      logger.atInfo().log("%s login denied: Ping %d ms > %s", user, user.ping, flags.maxPing)
       usersMap.remove(userListKey)
       throw PingTimeException(
         EmuLang.getString(
           "KailleraServerImpl.LoginDeniedPingTooHigh",
-          user.ping.toString() + " > " + maxPing
+          "${user.ping} > ${flags.maxPing}"
         )
       )
     }
@@ -530,8 +536,8 @@ internal constructor(
     if (
       access == AccessManager.ACCESS_NORMAL &&
         flags.chatFloodTime > 0 &&
-        (System.currentTimeMillis() - (user as KailleraUser?)!!.lastChatTime <
-          flags.chatFloodTime * 1000)
+        (clock.now() - (user as KailleraUser?)!!.lastChatTime <
+          (flags.chatFloodTime * 1000).milliseconds)
     ) {
       logger.atWarning().log("%s chat denied: Flood: %s", user, message)
       throw FloodException(EmuLang.getString("KailleraServerImpl.ChatDeniedFloodControl"))
@@ -827,15 +833,11 @@ internal constructor(
             }
           }
         }
-        if (!user.loggedIn && System.currentTimeMillis() - user.connectTime > flags.maxPing * 15) {
+        if (!user.loggedIn && clock.now() - user.connectTime > flags.maxPing * 15) {
           logger.atInfo().log("%s connection timeout!", user)
           usersMap.remove(user.id)
-        } else if (
-          user.loggedIn &&
-            System.currentTimeMillis() - user.lastKeepAlive >
-              flags.keepAliveTimeout.inWholeMilliseconds
-        ) {
-          logger.atInfo().log("%s keepalive timeout!", user)
+        } else if (user.loggedIn && user.isDead) {
+          logger.atInfo().log("%s keepalive timeout! (ping timeout)", user)
           try {
             quit(user, EmuLang.getString("KailleraServerImpl.ForcedQuitPingTimeout"))
           } catch (e: Exception) {
@@ -845,9 +847,9 @@ internal constructor(
           flags.idleTimeout.isPositive() &&
             access == AccessManager.ACCESS_NORMAL &&
             user.loggedIn &&
-            (System.currentTimeMillis() - user.lastActivity > flags.idleTimeout.inWholeMilliseconds)
+            user.isIdleForTooLong
         ) {
-          logger.atInfo().log("%s inactivity timeout!", user)
+          logger.atInfo().log("%s inactivity timeout! (idle for too long)", user)
           try {
             quit(user, EmuLang.getString("KailleraServerImpl.ForcedQuitInactivityTimeout"))
           } catch (e: Exception) {