Test a technique for improving lagstat for intentionally high frame delay users

emulinker/src/main/java/org/emulinker/kaillera/model/KailleraServer.kt

@@ -14,6 +14,7 @@ import javax.inject.Singleton
 import kotlin.Throws
 import kotlin.time.Duration.Companion.milliseconds
 import kotlin.time.Duration.Companion.minutes
+import kotlin.time.Duration.Companion.nanoseconds
 import kotlin.time.Duration.Companion.seconds
 import kotlinx.datetime.Clock
 import org.emulinker.config.RuntimeFlags
@@ -61,7 +62,6 @@ internal constructor(
   private val taskScheduler: TaskScheduler,
   private val clock: Clock,
 ) {
-
   private var allowedConnectionTypes = BooleanArray(7)
   private val loginMessages: List<String>
   private var connectionCounter = 1
@@ -840,6 +840,32 @@ internal constructor(
   }
 
   private fun run() {
+    // TODO(nue): Remove this. This is just being used for testing.
+    for (game in gamesMap.values) {
+      if (game.status == GameStatus.PLAYING) {
+        logger
+          .atInfo()
+          .log(
+            "LAGSTAT: G%d - %s - %s",
+            game.id,
+            (game.totalDriftNs - (game.totalDriftCache.getDelayedValue() ?: 0))
+              .nanoseconds
+              .absoluteValue,
+            game.players.joinToString(separator = " ") { "[${it.name} ${it.summarizeLag()}]" }
+          )
+        logger
+          .atInfo()
+          .log(
+            "LAGSTAT: G%d - %s - %s",
+            game.id,
+            (game.NEWtotalDriftNs - (game.NEWtotalDriftCache.getDelayedValue() ?: 0))
+              .nanoseconds
+              .absoluteValue,
+            game.players.joinToString(separator = " ") { "[${it.name} ${it.NEWsummarizeLag()}]" }
+          )
+      }
+    }
+
     try {
       if (usersMap.isEmpty()) return
       for (user in usersMap.values) {

emulinker/src/main/java/org/emulinker/kaillera/model/KailleraUser.kt

@@ -26,6 +26,7 @@ import org.emulinker.kaillera.model.exception.*
 import org.emulinker.kaillera.model.impl.KailleraGameImpl
 import org.emulinker.util.EmuLang
 import org.emulinker.util.TimeOffsetCache
+import kotlin.time.DurationUnit
 
 /**
  * Represents a user in the server.
@@ -80,8 +81,14 @@ class KailleraUser(
   private val totalDriftCache =
     TimeOffsetCache(delay = flags.lagstatDuration, resolution = 5.seconds)
 
+  private var NEWlagLeewayNs = 0.seconds.inWholeNanoseconds
+  private var NEWtotalDriftNs = 0.seconds.inWholeNanoseconds
+  private val NEWtotalDriftCache =
+    TimeOffsetCache(delay = flags.lagstatDuration, resolution = 5.seconds)
+
   /** The last time we heard from this player for lag detection purposes. */
   private var lastUpdateNs = System.nanoTime()
+  private var NEWlastUpdateNs = System.nanoTime()
 
   private fun updateLastActivity() {
     lastKeepAlive = clock.now()
@@ -305,9 +312,17 @@ class KailleraUser(
       .absoluteValue
       .toString(MILLISECONDS)
 
+  fun NEWsummarizeLag(): String =
+    (NEWtotalDriftNs - (NEWtotalDriftCache.getDelayedValue() ?: 0))
+      .nanoseconds
+      .absoluteValue
+      .toString(MILLISECONDS)
+
   fun resetLag() {
     totalDriftNs = 0
     totalDriftCache.clear()
+    NEWtotalDriftNs = 0
+    NEWtotalDriftCache.clear()
   }
 
   @Throws(JoinGameException::class)
@@ -524,9 +539,9 @@ class KailleraUser(
     return Result.success(Unit)
   }
 
-  fun updateUserDrift() {
+  fun updateUserDrift(nowNs: Long) {
     val receivedGameDataNs = receivedGameDataNs ?: return
-    val nowNs = System.nanoTime()
+    //    val nowNs = System.nanoTime()
     val delaySinceLastResponseNs = nowNs - lastUpdateNs
     val timeWaitingNs = nowNs - receivedGameDataNs
     val delaySinceLastResponseMinusWaitingNs = delaySinceLastResponseNs - timeWaitingNs
@@ -544,6 +559,28 @@ class KailleraUser(
     totalDriftCache.update(totalDriftNs, nowNs = nowNs)
   }
 
+  fun NEWupdateUserDrift(nowNs: Long) {
+    val receivedGameDataNs = receivedGameDataNs ?: return
+    //    val nowNs = System.nanoTime()
+    val delaySinceLastResponseNs = nowNs - NEWlastUpdateNs
+    val timeWaitingNs = nowNs - receivedGameDataNs
+    val delaySinceLastResponseMinusWaitingNs = delaySinceLastResponseNs - timeWaitingNs
+    val leewayChangeNs = singleFrameDurationNs - delaySinceLastResponseMinusWaitingNs
+    NEWlagLeewayNs += leewayChangeNs
+    if (NEWlagLeewayNs < 0) {
+      // Lag leeway fell below zero. We caused lag!
+      NEWtotalDriftNs += NEWlagLeewayNs
+      NEWlagLeewayNs = 0
+    }
+    // ALLOW THIS FOR HIGH FRAME DELAY. See if this actually makes a difference.
+        else if (NEWlagLeewayNs > singleFrameDurationNs) {
+      logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log("USER IS OVER FRAME DURATION: %s", NEWlagLeewayNs.nanoseconds.toString(DurationUnit.MILLISECONDS))
+//          NEWlagLeewayNs = singleFrameDurationNs
+        }
+    NEWlastUpdateNs = nowNs
+    NEWtotalDriftCache.update(NEWtotalDriftNs, nowNs = nowNs)
+  }
+
   fun queueEvent(event: KailleraEvent) {
     if (status != UserStatus.IDLE) {
       if (ignoringUnnecessaryServerActivity) {

emulinker/src/main/java/org/emulinker/kaillera/model/impl/KailleraGameImpl.kt

@@ -16,6 +16,7 @@ import org.emulinker.kaillera.model.GameStatus
 import org.emulinker.kaillera.model.KailleraGame
 import org.emulinker.kaillera.model.KailleraServer
 import org.emulinker.kaillera.model.KailleraUser
+import org.emulinker.kaillera.model.KailleraUser.Companion
 import org.emulinker.kaillera.model.UserStatus
 import org.emulinker.kaillera.model.event.AllReadyEvent
 import org.emulinker.kaillera.model.event.GameChatEvent
@@ -41,6 +42,9 @@ import org.emulinker.kaillera.model.exception.UserReadyException
 import org.emulinker.util.EmuLang
 import org.emulinker.util.EmuUtil.threadSleep
 import org.emulinker.util.TimeOffsetCache
+import java.util.concurrent.TimeUnit
+import kotlin.time.Duration.Companion.nanoseconds
+import kotlin.time.DurationUnit
 
 class KailleraGameImpl(
   override val id: Int,
@@ -69,6 +73,7 @@ class KailleraGameImpl(
 
   /** Last time we fanned out data for a frame. */
   private var lastFrameNs = System.nanoTime()
+  private var NEWlastFrameNs = System.nanoTime()
 
   override var startTimeoutTime: Instant? = null
     private set
@@ -79,6 +84,10 @@ class KailleraGameImpl(
   var totalDriftNs = 0.seconds.inWholeNanoseconds
   val totalDriftCache = TimeOffsetCache(delay = flags.lagstatDuration, resolution = 5.seconds)
 
+  var NEWlagLeewayNs = 0.seconds.inWholeNanoseconds
+  var NEWtotalDriftNs = 0.seconds.inWholeNanoseconds
+  val NEWtotalDriftCache = TimeOffsetCache(delay = flags.lagstatDuration, resolution = 5.seconds)
+
   val mutedUsers: MutableList<String> = mutableListOf()
   var aEmulator = "any"
   var aConnection = "any"
@@ -697,10 +706,13 @@ class KailleraGameImpl(
           )
         }
         player.queueEvent(GameDataEvent(this, response))
-        player.updateUserDrift()
+        val nowNs = System.nanoTime()
+        player.updateUserDrift(nowNs)
+        player.NEWupdateUserDrift(nowNs)
         val firstPlayer = players.firstOrNull()
         if (firstPlayer != null && firstPlayer.id == player.id) {
-          updateGameDrift()
+          updateGameDrift(nowNs)
+          NEWupdateGameDrift(nowNs)
         }
       }
     }
@@ -710,10 +722,12 @@ class KailleraGameImpl(
   fun resetLag() {
     totalDriftCache.clear()
     totalDriftNs = 0
+    NEWtotalDriftCache.clear()
+    NEWtotalDriftNs = 0
   }
 
-  private fun updateGameDrift() {
-    val nowNs = System.nanoTime()
+  private fun updateGameDrift(nowNs: Long) {
+    //    val nowNs = System.nanoTime()
     val delaySinceLastResponseNs = nowNs - lastFrameNs
 
     lagLeewayNs += singleFrameDurationNs - delaySinceLastResponseNs
@@ -729,6 +743,26 @@ class KailleraGameImpl(
     lastFrameNs = nowNs
   }
 
+  private fun NEWupdateGameDrift(nowNs: Long) {
+    //    val nowNs = System.nanoTime()
+    val delaySinceLastResponseNs = nowNs - NEWlastFrameNs
+
+    NEWlagLeewayNs += singleFrameDurationNs - delaySinceLastResponseNs
+    if (NEWlagLeewayNs < 0) {
+      // Lag leeway fell below zero. Lag occurred!
+      NEWtotalDriftNs += NEWlagLeewayNs
+      NEWlagLeewayNs = 0
+    }
+    // ALLOWING THIS FOR HIGH FRAME DELAY TESTING.
+        else if (NEWlagLeewayNs > singleFrameDurationNs) {
+
+      logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log("GAME IS OVER FRAME DURATION: %s", NEWlagLeewayNs.nanoseconds.toString(DurationUnit.MILLISECONDS))
+//          NEWlagLeewayNs = singleFrameDurationNs
+        }
+    NEWtotalDriftCache.update(NEWtotalDriftNs, nowNs = nowNs)
+    NEWlastFrameNs = nowNs
+  }
+
   // it's very important this method is synchronized
   private fun handleTimeout(e: PlayerTimeoutException) = withLock {
     if (!isSynched) return