From ac5217611d3314df482611b019dc28b40fd8fd26 Mon Sep 17 00:00:00 2001 From: genxium Date: Mon, 26 Dec 2022 18:25:20 +0800 Subject: [PATCH] Added basic frontend-backend dynamics comparison logging. --- .gitignore | 2 + battle_srv/models/room.go | 45 +++++++++++++++- frontend/assets/resources/map/dungeon/map.tmx | 4 +- frontend/assets/scenes/login.fire | 2 +- frontend/assets/scripts/Map.js | 54 ++++++++++++------- frontend/assets/scripts/WsSessionMgr.js | 3 +- jsexport/.gitignore | 2 - 7 files changed, 86 insertions(+), 26 deletions(-) delete mode 100644 jsexport/.gitignore diff --git a/.gitignore b/.gitignore index d3d839f..d17edae 100644 --- a/.gitignore +++ b/.gitignore @@ -132,3 +132,5 @@ gradle/* *.project *~ +jsexport/jsexport.js* +battle_srv/room_*.txt diff --git a/battle_srv/models/room.go b/battle_srv/models/room.go index cc59a0d..d72c0c7 100644 --- a/battle_srv/models/room.go +++ b/battle_srv/models/room.go @@ -13,13 +13,13 @@ import ( "io/ioutil" "jsexport/battle" "math/rand" - "os" "path/filepath" "resolv" "strings" "sync" "sync/atomic" "time" + "os" ) const ( @@ -146,6 +146,8 @@ type Room struct { TmxPointsMap StrToVec2DListMap TmxPolygonsMap StrToPolygon2DListMap + + rdfIdToActuallyUsedInput map[int32]*pb.InputFrameDownsync } func (pR *Room) updateScore() { @@ -342,6 +344,32 @@ func (pR *Room) InputsBufferString(allDetails bool) string { } } +func (pR *Room) inputFrameDownsyncStr(inputFrameDownsync *pb.InputFrameDownsync) string { + if nil == inputFrameDownsync { + return "" + } + s := make([]string, 0) + s = append(s, fmt.Sprintf("InputFrameId:%d", inputFrameDownsync.InputFrameId)) + ss := make([]string, 0) + for _, v := range inputFrameDownsync.InputList { + ss = append(ss, fmt.Sprintf("\"%d\"", v)) + } + s = append(s, fmt.Sprintf("InputList:[%v]", strings.Join(ss, ","))) + //s = append(s, fmt.Sprintf("ConfirmedList:%d", inputFrameDownsync.ConfirmedList)) + + return strings.Join(s, ",") +} + +func (pR *Room) rdfIdToActuallyUsedInputString() string { + // Appending of the array of strings can be very SLOW due to on-demand heap allocation! Use this printing with caution. + s := make([]string, 0) + for rdfId := pR.RenderFrameBuffer.StFrameId; rdfId < pR.RenderFrameBuffer.EdFrameId; rdfId++ { + s = append(s, fmt.Sprintf("rdfId:%d\nactuallyUsedinputList:{%v}", rdfId, pR.inputFrameDownsyncStr(pR.rdfIdToActuallyUsedInput[rdfId]))) + } + + return strings.Join(s, "\n") +} + func (pR *Room) StartBattle() { if RoomBattleStateIns.WAITING != pR.State { Logger.Debug("[StartBattle] Battle not started due to not being WAITING!", zap.Any("roomId", pR.Id), zap.Any("roomState", pR.State)) @@ -378,7 +406,9 @@ func (pR *Room) StartBattle() { Logger.Error("battleMainLoop, recovery spot#1, recovered from: ", zap.Any("roomId", pR.Id), zap.Any("panic", r)) } pR.StopBattleForSettlement() + rdfIdToActuallyUsedInputDump := pR.rdfIdToActuallyUsedInputString() Logger.Info(fmt.Sprintf("The `battleMainLoop` for roomId=%v is stopped@renderFrameId=%v, with battleDurationFrames=%v:\n%v", pR.Id, pR.RenderFrameId, pR.BattleDurationFrames, pR.InputsBufferString(false))) // This takes sometime to print + os.WriteFile(fmt.Sprintf("room_%d.txt", pR.Id), []byte(rdfIdToActuallyUsedInputDump), 0644) // DEBUG ONLY pR.onBattleStoppedForSettlement() }() @@ -708,6 +738,7 @@ func (pR *Room) OnDismissed() { pR.RenderCacheSize = 1024 pR.RenderFrameBuffer = NewRingBuffer(pR.RenderCacheSize) pR.InputsBuffer = NewRingBuffer((pR.RenderCacheSize >> 1) + 1) + pR.rdfIdToActuallyUsedInput = make(map[int32]*pb.InputFrameDownsync) pR.LatestPlayerUpsyncedInputFrameId = -1 pR.LastAllConfirmedInputFrameId = -1 @@ -724,7 +755,7 @@ func (pR *Room) OnDismissed() { pR.RollbackEstimatedDtNanos = 16666666 // A little smaller than the actual per frame time, just for logging FAST FRAME dilutedServerFps := float64(58.0) // Don't set this value too small, otherwise we might miss force confirmation needs for slow tickers! pR.dilutedRollbackEstimatedDtNanos = int64(float64(pR.RollbackEstimatedDtNanos) * float64(pR.ServerFps) / dilutedServerFps) - pR.BattleDurationFrames = 60 * pR.ServerFps + pR.BattleDurationFrames = 15 * pR.ServerFps pR.BattleDurationNanos = int64(pR.BattleDurationFrames) * (pR.RollbackEstimatedDtNanos + 1) pR.InputFrameUpsyncDelayTolerance = (pR.NstDelayFrames >> pR.InputScaleFrames) - 1 // this value should be strictly smaller than (NstDelayFrames >> InputScaleFrames), otherwise "type#1 forceConfirmation" might become a lag avalanche pR.MaxChasingRenderFramesPerUpdate = 12 // Don't set this value too high to avoid exhausting frontend CPU within a single frame @@ -1233,6 +1264,16 @@ func (pR *Room) applyInputFrameDownsyncDynamics(fromRenderFrameId int32, toRende delayedInputFrameForPrevRenderFrame := tmp.(*pb.InputFrameDownsync) delayedInputListForPrevRenderFrame = &delayedInputFrameForPrevRenderFrame.InputList } + + actuallyUsedInputClone := make([]uint64, len(*delayedInputList), len(*delayedInputList)) + for i, v := range *delayedInputList { + actuallyUsedInputClone[i] = v + } + pR.rdfIdToActuallyUsedInput[currRenderFrame.Id] = &pb.InputFrameDownsync{ + InputFrameId: delayedInputFrame.InputFrameId, + InputList: actuallyUsedInputClone, + ConfirmedList: delayedInputFrame.ConfirmedList, + } } nextRenderFrame := battle.ApplyInputFrameDownsyncDynamicsOnSingleRenderFrame(*delayedInputList, *delayedInputListForPrevRenderFrame, currRenderFrame, pR.Space, pR.CollisionSysMap, pR.GravityX, pR.GravityY, pR.JumpingInitVelY, pR.InputDelayFrames, pR.InputScaleFrames, pR.collisionSpaceOffsetX, pR.collisionSpaceOffsetY, pR.SnapIntoPlatformOverlap, pR.SnapIntoPlatformThreshold, pR.WorldToVirtualGridRatio, pR.VirtualGridToWorldRatio) diff --git a/frontend/assets/resources/map/dungeon/map.tmx b/frontend/assets/resources/map/dungeon/map.tmx index a0fda48..b853993 100644 --- a/frontend/assets/resources/map/dungeon/map.tmx +++ b/frontend/assets/resources/map/dungeon/map.tmx @@ -9,10 +9,10 @@ - + - + diff --git a/frontend/assets/scenes/login.fire b/frontend/assets/scenes/login.fire index c6d411c..b45c341 100644 --- a/frontend/assets/scenes/login.fire +++ b/frontend/assets/scenes/login.fire @@ -440,7 +440,7 @@ "array": [ 0, 0, - 217.37237634989413, + 216.79265527990535, 0, 0, 0, diff --git a/frontend/assets/scripts/Map.js b/frontend/assets/scripts/Map.js index 529280c..8c29b44 100644 --- a/frontend/assets/scripts/Map.js +++ b/frontend/assets/scripts/Map.js @@ -161,7 +161,7 @@ cc.Class({ inputList: prefabbedInputList, confirmedList: (1 << (joinIndex - 1)) }); - + // console.log(`Prefabbed inputFrameId=${prefabbedInputFrameDownsync.inputFrameId}`); self.recentInputCache.put(prefabbedInputFrameDownsync); } @@ -325,6 +325,7 @@ cc.Class({ self.battleState = ALL_BATTLE_STATES.WAITING; self.othersForcedDownsyncRenderFrameDict = new Map(); + self.rdfIdToActuallyUsedInput = new Map(); self.countdownNanos = null; if (self.countdownLabel) { @@ -753,6 +754,7 @@ cc.Class({ firstPredictedYetIncorrectInputFrameId = inputFrameDownsyncId; } inputFrameDownsync.confirmedList = (1 << self.playerRichInfoDict.size) - 1; + //console.log(`Confirmed inputFrameId=${inputFrameDownsync.inputFrameId}`); const [ret, oldStFrameId, oldEdFrameId] = self.recentInputCache.setByFrameId(inputFrameDownsync, inputFrameDownsync.inputFrameId); if (window.RING_BUFF_FAILED_TO_SET == ret) { throw `Failed to dump input cache (maybe recentInputCache too small)! inputFrameDownsync.inputFrameId=${inputFrameDownsync.inputFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}; recentRenderCache=${self._stringifyRecentRenderCache(false)}, recentInputCache=${self._stringifyRecentInputCache(false)}`; @@ -760,10 +762,7 @@ cc.Class({ } if (null == firstPredictedYetIncorrectInputFrameId) return; - const inputFrameId1 = firstPredictedYetIncorrectInputFrameId; - const renderFrameId1 = self._convertToFirstUsedRenderFrameId(inputFrameId1, self.inputDelayFrames); // a.k.a. "firstRenderFrameIdUsingIncorrectInputFrameId" - if (renderFrameId1 >= self.renderFrameId) return; // No need to rollback when "renderFrameId1 == self.renderFrameId", because the "corresponding delayedInputFrame for renderFrameId1" is NOT YET EXECUTED BY NOW, it just went through "++self.renderFrameId" in "update(dt)" and javascript-runtime is mostly single-threaded in our programmable range. - + const renderFrameId1 = self._convertToFirstUsedRenderFrameId(firstPredictedYetIncorrectInputFrameId, self.inputDelayFrames) - 1; if (renderFrameId1 >= self.chaserRenderFrameId) return; /* @@ -778,7 +777,7 @@ cc.Class({ -------------------------------------------------------- */ // The actual rollback-and-chase would later be executed in update(dt). - console.warn(`Mismatched input detected, resetting chaserRenderFrameId: ${self.chaserRenderFrameId}->${renderFrameId1} by firstPredictedYetIncorrectInputFrameId: ${inputFrameId1} + console.warn(`Mismatched input detected, resetting chaserRenderFrameId: ${self.chaserRenderFrameId}->${renderFrameId1} by firstPredictedYetIncorrectInputFrameId: ${firstPredictedYetIncorrectInputFrameId} lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId} recentInputCache=${self._stringifyRecentInputCache(false)} batchInputFrameIdRange=[${batch[0].inputFrameId}, ${batch[batch.length - 1].inputFrameId}]`); @@ -800,7 +799,7 @@ batchInputFrameIdRange=[${batch[0].inputFrameId}, ${batch[batch.length - 1].inpu if (ALL_BATTLE_STATES.IN_BATTLE != self.battleState) { return; } - self._stringifyRecentInputAndRenderCacheCorrespondingly(); + self._stringifyRdfIdToActuallyUsedInput(); window.closeWSConnection(constants.RET_CODE.BATTLE_STOPPED); self.battleState = ALL_BATTLE_STATES.IN_SETTLEMENT; self.countdownNanos = null; @@ -922,7 +921,7 @@ batchInputFrameIdRange=[${batch[0].inputFrameId}, ${batch[batch.length - 1].inpu console.warn(`Mismatched render frame@rdf.id=${rdf.id} w/ inputFrameId=${delayedInputFrameId}: rdf=${JSON.stringify(rdf)} othersForcedDownsyncRenderFrame=${JSON.stringify(othersForcedDownsyncRenderFrame)} -${self._stringifyRecentInputAndRenderCacheCorrespondingly()}`); +${self._stringifyRdfIdToActuallyUsedInput()}`); // closeWSConnection(constants.RET_CODE.CLIENT_MISMATCHED_RENDER_FRAME, ""); // self.onManualRejoinRequired("[DEBUG] CLIENT_MISMATCHED_RENDER_FRAME"); rdf = othersForcedDownsyncRenderFrame; @@ -1114,6 +1113,13 @@ ${self._stringifyRecentInputAndRenderCacheCorrespondingly()}`); const jPrev = self._convertToInputFrameId(i - 1, self.inputDelayFrames); const delayedInputFrameForPrevRenderFrame = self.recentInputCache.getByFrameId(jPrev); + const actuallyUsedInputClone = delayedInputFrame.inputList.slice(); + const inputFrameDownsyncClone = { + inputFrameId: delayedInputFrame.inputFrameId, + inputList: actuallyUsedInputClone, + confirmedList: delayedInputFrame.confirmedList, + }; + self.rdfIdToActuallyUsedInput.set(currRdf.Id, inputFrameDownsyncClone); const nextRdf = gopkgs.ApplyInputFrameDownsyncDynamicsOnSingleRenderFrameJs(delayedInputFrame.inputList, (null == delayedInputFrameForPrevRenderFrame ? null : delayedInputFrameForPrevRenderFrame.inputList), currRdf, collisionSys, collisionSysMap, self.gravityX, self.gravityY, self.jumpingInitVelY, self.inputDelayFrames, self.inputScaleFrames, self.spaceOffsetX, self.spaceOffsetY, self.snapIntoPlatformOverlap, self.snapIntoPlatformThreshold, self.worldToVirtualGridRatio, self.virtualGridToWorldRatio); if (true == isChasing) { @@ -1200,19 +1206,31 @@ ${self._stringifyRecentInputAndRenderCacheCorrespondingly()}`); return `[stRenderFrameId=${self.recentRenderCache.stFrameId}, edRenderFrameId=${self.recentRenderCache.edFrameId})`; }, - _stringifyRecentInputAndRenderCacheCorrespondingly() { + inputFrameDownsyncStr(inputFrameDownsync) { + if (null == inputFrameDownsync) return ""; const self = this; let s = []; - s.push(`@lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, @renderFrameId=${self.renderFrameId}, @chaserRenderFrameId=${self.chaserRenderFrameId}`); - - for (let i = self.recentRenderCache.stFrameId; i < self.recentRenderCache.edFrameId; ++i) { - let jPrev = self._convertToInputFrameId(i - 1, self.inputDelayFrames); - let j = self._convertToInputFrameId(i, self.inputDelayFrames); - if (i == self.recentRenderCache.stFrameId || j > jPrev) { - s.push(JSON.stringify(self.recentInputCache.getByFrameId(j))); - } - s.push(JSON.stringify(self.recentRenderCache.getByFrameId(i))); + s.push(`InputFrameId:${inputFrameDownsync.inputFrameId}`); + let ss = []; + for (let k in inputFrameDownsync.inputList) { + ss.push(`"${inputFrameDownsync.inputList[k]}"`); } + s.push(`InputList:[${ss.join(',')}]`); + // The "confirmedList" is not worth comparing, because frontend might actually use a non-all-confirmed inputFrame during its history, as long as it's correctly predicted. + //s.push(`ConfirmedList:${inputFrameDownsync.confirmedList}`); + + return s.join(','); + }, + + _stringifyRdfIdToActuallyUsedInput() { + const self = this; + let s = []; + for (let i = self.recentRenderCache.stFrameId; i < self.recentRenderCache.edFrameId; i++) { + const actuallyUsedInputClone = self.rdfIdToActuallyUsedInput.get(i); + s.push(`rdfId:${i} +actuallyUsedinputList:{${self.inputFrameDownsyncStr(actuallyUsedInputClone)}}`); + } + return s.join('\n'); }, diff --git a/frontend/assets/scripts/WsSessionMgr.js b/frontend/assets/scripts/WsSessionMgr.js index 4174857..8c4f056 100644 --- a/frontend/assets/scripts/WsSessionMgr.js +++ b/frontend/assets/scripts/WsSessionMgr.js @@ -197,6 +197,7 @@ window.initPersistentSessionClient = function(onopenCb, expectedRoomId) { break; case constants.RET_CODE.BATTLE_STOPPED: // deliberately do nothing + console.warn(`${mapIns._stringifyRdfIdToActuallyUsedInput()}`); break; case constants.RET_CODE.PLAYER_NOT_ADDABLE_TO_ROOM: case constants.RET_CODE.PLAYER_NOT_READDABLE_TO_ROOM: @@ -211,7 +212,7 @@ window.initPersistentSessionClient = function(onopenCb, expectedRoomId) { case constants.RET_CODE.PLAYER_NOT_FOUND: case constants.RET_CODE.PLAYER_CHEATING: case 1006: // Peer(i.e. the backend) gone unexpectedly - console.warn(`${mapIns._stringifyRecentInputAndRenderCacheCorrespondingly()}`); + console.warn(`${mapIns._stringifyRdfIdToActuallyUsedInput()}`); window.clearLocalStorageAndBackToLoginScene(true); break; default: diff --git a/jsexport/.gitignore b/jsexport/.gitignore deleted file mode 100644 index f886659..0000000 --- a/jsexport/.gitignore +++ /dev/null @@ -1,2 +0,0 @@ -jsexport.js -jsexport.js.map