diff --git a/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraServer.kt b/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraServer.kt index 70de7d23c..8d1f99660 100644 --- a/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraServer.kt +++ b/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 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) { diff --git a/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraUser.kt b/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraUser.kt index 3b004c2a4..6289f6dc4 100644 --- a/emulinker/src/main/java/org/emulinker/kaillera/model/KailleraUser.kt +++ b/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) { diff --git a/emulinker/src/main/java/org/emulinker/kaillera/model/impl/KailleraGameImpl.kt b/emulinker/src/main/java/org/emulinker/kaillera/model/impl/KailleraGameImpl.kt index 94411d77d..6a2ee9486 100644 --- a/emulinker/src/main/java/org/emulinker/kaillera/model/impl/KailleraGameImpl.kt +++ b/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 = 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