Added basic frontend-backend dynamics comparison logging.

.gitignore

@@ -132,3 +132,5 @@ gradle/*
 *.project
 
 *~
+jsexport/jsexport.js*
+battle_srv/room_*.txt

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)

frontend/assets/resources/map/dungeon/map.tmx

@@ -9,10 +9,10 @@
   </data>
  </layer>
  <objectgroup id="1" name="PlayerStartingPos">
-  <object id="135" x="999" y="1608">
+  <object id="135" x="901" y="1579">
    <point/>
   </object>
-  <object id="137" x="875" y="1450">
+  <object id="137" x="865" y="1561">
    <point/>
   </object>
  </objectgroup>

frontend/assets/scenes/login.fire

@@ -440,7 +440,7 @@
       "array": [
         0,
         0,
-        217.37237634989413,
+        216.79265527990535,
         0,
         0,
         0,

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(firstPredictedYetIncorrectInputFrameId, self.inputDelayFrames) - 1;
-    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.
-
     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}`);
+    s.push(`InputFrameId:${inputFrameDownsync.inputFrameId}`);
-
+    let ss = [];
-    for (let i = self.recentRenderCache.stFrameId; i < self.recentRenderCache.edFrameId; ++i) {
+    for (let k in inputFrameDownsync.inputList) {
-      let jPrev = self._convertToInputFrameId(i - 1, self.inputDelayFrames);
+      ss.push(`"${inputFrameDownsync.inputList[k]}"`);
-      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(`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');
   },
 

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:

jsexport/.gitignore

@@ -1,2 +0,0 @@
-jsexport.js
-jsexport.js.map