Updated frontend logging.

This commit is contained in:
genxium 2022-11-11 23:43:51 +08:00
parent 320e98361e
commit 98daeff408
4 changed files with 26 additions and 31 deletions

View File

@ -532,11 +532,14 @@ func (pR *Room) StartBattle() {
continue continue
} }
indiceInJoinIndexBooleanArr := uint32(player.JoinIndex - 1) /*
var joinMask uint64 = (1 << indiceInJoinIndexBooleanArr) Resync helps
shouldResyncForSlowerClocker := (0 < (unconfirmedMask & joinMask)) // This condition is critical, if we don't send resync upon this condition, the player with a slower frontend clock might never get its input synced 1. when player with a slower frontend clock lags significantly behind and thus wouldn't get its inputUpsync recognized due to faster "forceConfirmation"
if pR.BackendDynamicsEnabled && (MAGIC_LAST_SENT_INPUT_FRAME_ID_READDED == player.LastSentInputFrameId || shouldResyncForSlowerClocker) { 2. reconnection
// [WARNING] Even upon "MAGIC_LAST_SENT_INPUT_FRAME_ID_READDED", it could be true that "0 == ()"! */
shouldResync1 := (MAGIC_LAST_SENT_INPUT_FRAME_ID_READDED == player.LastSentInputFrameId)
shouldResync2 := (0 < unconfirmedMask) // This condition is critical, if we don't send resync upon this condition, the might never get its input synced
if pR.BackendDynamicsEnabled && (shouldResync1 || shouldResync2) {
tmp := pR.RenderFrameBuffer.GetByFrameId(refRenderFrameId) tmp := pR.RenderFrameBuffer.GetByFrameId(refRenderFrameId)
if nil == tmp { if nil == tmp {
panic(fmt.Sprintf("Required refRenderFrameId=%v for roomId=%v, playerId=%v, candidateToSendInputFrameId=%v doesn't exist! InputsBuffer=%v, RenderFrameBuffer=%v", refRenderFrameId, pR.Id, playerId, candidateToSendInputFrameId, pR.InputsBufferString(false), pR.RenderFrameBufferString())) panic(fmt.Sprintf("Required refRenderFrameId=%v for roomId=%v, playerId=%v, candidateToSendInputFrameId=%v doesn't exist! InputsBuffer=%v, RenderFrameBuffer=%v", refRenderFrameId, pR.Id, playerId, candidateToSendInputFrameId, pR.InputsBufferString(false), pR.RenderFrameBufferString()))
@ -560,9 +563,7 @@ func (pR *Room) StartBattle() {
toApplyInputFrameId := pR.ConvertToInputFrameId(refRenderFrameId, pR.InputDelayFrames) toApplyInputFrameId := pR.ConvertToInputFrameId(refRenderFrameId, pR.InputDelayFrames)
/* /*
[WARNING] [WARNING]
The following updates to "toApplyInputFrameId" is necessary because The following updates to "toApplyInputFrameId" is necessary because when "false == pR.BackendDynamicsEnabled", the variable "refRenderFrameId" is not well defined.
1. When "false == pR.BackendDynamicsEnabled", the variable "refRenderFrameId" is not well defined;
2. When "true == pR.BackendDynamicsEnabled", the initial value of "toApplyInputFrameId" might be too big and thus making frontends unable to receive consecutive all-confirmed inputFrameDownsync sequence - which is what we want during a battle if no one disconnects.
*/ */
minLastSentInputFrameId := int32(math.MaxInt32) minLastSentInputFrameId := int32(math.MaxInt32)
for _, player := range pR.Players { for _, player := range pR.Players {
@ -578,7 +579,7 @@ func (pR *Room) StartBattle() {
f := pR.InputsBuffer.Pop().(*InputFrameDownsync) f := pR.InputsBuffer.Pop().(*InputFrameDownsync)
if pR.inputFrameIdDebuggable(f.InputFrameId) { if pR.inputFrameIdDebuggable(f.InputFrameId) {
// Popping of an "inputFrame" would be AFTER its being all being confirmed, because it requires the "inputFrame" to be all acked // Popping of an "inputFrame" would be AFTER its being all being confirmed, because it requires the "inputFrame" to be all acked
Logger.Debug("inputFrame lifecycle#4[popped]:", zap.Any("roomId", pR.Id), zap.Any("inputFrameId", f.InputFrameId), zap.Any("minLastSentInputFrameId", minLastSentInputFrameId), zap.Any("toApplyInputFrameId", toApplyInputFrameId), zap.Any("InputsBuffer", pR.InputsBufferString(false))) Logger.Debug("inputFrame lifecycle#4[popped]:", zap.Any("roomId", pR.Id), zap.Any("inputFrameId", f.InputFrameId), zap.Any("toApplyInputFrameId", toApplyInputFrameId), zap.Any("InputsBuffer", pR.InputsBufferString(false)))
} }
} }
@ -818,7 +819,7 @@ func (pR *Room) OnDismissed() {
pR.BattleDurationFrames = 30 * pR.ServerFps pR.BattleDurationFrames = 30 * pR.ServerFps
pR.BattleDurationNanos = int64(pR.BattleDurationFrames) * (pR.RollbackEstimatedDtNanos + 1) pR.BattleDurationNanos = int64(pR.BattleDurationFrames) * (pR.RollbackEstimatedDtNanos + 1)
pR.InputFrameUpsyncDelayTolerance = 2 pR.InputFrameUpsyncDelayTolerance = 2
pR.MaxChasingRenderFramesPerUpdate = 10 pR.MaxChasingRenderFramesPerUpdate = 5
pR.BackendDynamicsEnabled = true // [WARNING] When "false", recovery upon reconnection wouldn't work! pR.BackendDynamicsEnabled = true // [WARNING] When "false", recovery upon reconnection wouldn't work!

View File

@ -440,7 +440,7 @@
"array": [ "array": [
0, 0,
0, 0,
377.5870760500153, 237.35666382819272,
0, 0,
0, 0,
0, 0,

View File

@ -595,7 +595,7 @@ cc.Class({
// The logic below applies to ( || window.RING_BUFF_NON_CONSECUTIVE_SET == dumpRenderCacheRet) // The logic below applies to ( || window.RING_BUFF_NON_CONSECUTIVE_SET == dumpRenderCacheRet)
if (window.MAGIC_ROOM_DOWNSYNC_FRAME_ID.BATTLE_START == rdf.id) { if (window.MAGIC_ROOM_DOWNSYNC_FRAME_ID.BATTLE_START == rdf.id) {
console.log('On battle resynced! renderFrameId=', rdf.id); console.log('On battle started! renderFrameId=', rdf.id);
} else { } else {
console.log('On battle resynced! renderFrameId=', rdf.id); console.log('On battle resynced! renderFrameId=', rdf.id);
} }
@ -696,7 +696,7 @@ cc.Class({
-------------------------------------------------------- --------------------------------------------------------
*/ */
// The actual rollback-and-chase would later be executed in update(dt). // The actual rollback-and-chase would later be executed in update(dt).
console.warn("Mismatched input detected, resetting chaserRenderFrameId: inputFrameId1:", inputFrameId1, ", renderFrameId1:", renderFrameId1, ", chaserRenderFrameId before reset: ", self.chaserRenderFrameId); console.warn(`Mismatched input detected, resetting chaserRenderFrameId: ${self.chaserRenderFrameId}->${renderFrameId1} by firstPredictedYetIncorrectInputFrameId: ${inputFrameId1}`);
self.chaserRenderFrameId = renderFrameId1; self.chaserRenderFrameId = renderFrameId1;
}, },
@ -713,7 +713,7 @@ cc.Class({
logBattleStats() { logBattleStats() {
const self = this; const self = this;
let s = []; let s = [];
s.push("Battle stats: renderFrameId=" + self.renderFrameId + ", lastAllConfirmedRenderFrameId=" + self.lastAllConfirmedRenderFrameId + ", lastUpsyncInputFrameId=" + self.lastUpsyncInputFrameId + ", lastAllConfirmedInputFrameId=" + self.lastAllConfirmedInputFrameId); s.push(`Battle stats: renderFrameId=${self.renderFrameId}, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastUpsyncInputFrameId=${self.lastUpsyncInputFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, chaserRenderFrameId=${self.chaserRenderFrameId}`);
for (let i = self.recentInputCache.stFrameId; i < self.recentInputCache.edFrameId; ++i) { for (let i = self.recentInputCache.stFrameId; i < self.recentInputCache.edFrameId; ++i) {
const inputFrameDownsync = self.recentInputCache.getByFrameId(i); const inputFrameDownsync = self.recentInputCache.getByFrameId(i);
@ -1073,7 +1073,7 @@ cc.Class({
const self = this; const self = this;
let latestRdf = self.recentRenderCache.getByFrameId(renderFrameIdSt); // typed "RoomDownsyncFrame" let latestRdf = self.recentRenderCache.getByFrameId(renderFrameIdSt); // typed "RoomDownsyncFrame"
if (null == latestRdf) { if (null == latestRdf) {
console.error("Couldn't find renderFrameId=", renderFrameIdSt, " to rollback, lastAllConfirmedRenderFrameId=", self.lastAllConfirmedRenderFrameId, ", lastAllConfirmedInputFrameId=", self.lastAllConfirmedInputFrameId, ", recentRenderCache=", self._stringifyRecentRenderCache(false), ", recentInputCache=", self._stringifyRecentInputCache(false)); console.error(`Couldn't find renderFrameId=${renderFrameIdSt}, to rollback, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, recentRenderCache=${self._stringifyRecentRenderCache(false)}, recentInputCache=${self._stringifyRecentInputCache(false)}`);
return latestRdf; return latestRdf;
} }
@ -1084,13 +1084,13 @@ cc.Class({
for (let i = renderFrameIdSt; i < renderFrameIdEd; ++i) { for (let i = renderFrameIdSt; i < renderFrameIdEd; ++i) {
const currRenderFrame = self.recentRenderCache.getByFrameId(i); // typed "RoomDownsyncFrame"; [WARNING] When "true == isChasing", this function can be interruptted by "onRoomDownsyncFrame(rdf)" asynchronously anytime, making this line return "null"! const currRenderFrame = self.recentRenderCache.getByFrameId(i); // typed "RoomDownsyncFrame"; [WARNING] When "true == isChasing", this function can be interruptted by "onRoomDownsyncFrame(rdf)" asynchronously anytime, making this line return "null"!
if (null == currRenderFrame) { if (null == currRenderFrame) {
console.warn("Couldn't find renderFrame for i=", i, " to rollback, self.renderFrameId=", self.renderFrameId, ", lastAllConfirmedRenderFrameId=", self.lastAllConfirmedRenderFrameId, ", lastAllConfirmedInputFrameId=", self.lastAllConfirmedInputFrameId, ", might've been interruptted by `onRoomDownsyncFrame`"); console.warn(`Couldn't find renderFrame for i=${i} to rollback, self.renderFrameId=${self.renderFrameId}, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, might've been interruptted by onRoomDownsyncFrame`);
return latestRdf; return latestRdf;
} }
const j = self._convertToInputFrameId(i, self.inputDelayFrames); const j = self._convertToInputFrameId(i, self.inputDelayFrames);
const delayedInputFrame = self.getCachedInputFrameDownsyncWithPrediction(j); const delayedInputFrame = self.getCachedInputFrameDownsyncWithPrediction(j);
if (null == delayedInputFrame) { if (null == delayedInputFrame) {
console.warn("Failed to get cached delayedInputFrame for i=", i, ", j=", j, ", self.renderFrameId=", self.renderFrameId, ", lastAllConfirmedRenderFrameId=", self.lastAllConfirmedRenderFrameId, ", lastAllConfirmedInputFrameId=", self.lastAllConfirmedInputFrameId); console.warn(`Failed to get cached delayedInputFrame for i=${i}, j=${j}, self.renderFrameId=${self.renderFrameId}, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}`);
return latestRdf; return latestRdf;
} }
@ -1156,7 +1156,7 @@ cc.Class({
return s.join('\n'); return s.join('\n');
} }
return "[stInputFrameId=" + self.recentInputCache.stFrameId + ", edInputFrameId=" + self.recentInputCache.edFrameId + ")"; return `[stInputFrameId=${self.recentInputCache.stFrameId}, edInputFrameId=${self.recentInputCache.edFrameId})`;
}, },
_stringifyRecentRenderCache(usefullOutput) { _stringifyRecentRenderCache(usefullOutput) {
@ -1169,7 +1169,7 @@ cc.Class({
return s.join('\n'); return s.join('\n');
} }
return "[stRenderFrameId=" + self.recentRenderCache.stFrameId + ", edRenderFrameId=" + self.recentRenderCache.edFrameId + ")"; return `[stRenderFrameId=${self.recentRenderCache.stFrameId}, edRenderFrameId=${self.recentRenderCache.edFrameId})`;
}, },
worldToVirtualGridPos(x, y) { worldToVirtualGridPos(x, y) {

View File

@ -172,22 +172,16 @@ window.initPersistentSessionClient = function(onopenCb, expectedRoomId) {
break; break;
case window.DOWNSYNC_MSG_ACT_FORCED_RESYNC: case window.DOWNSYNC_MSG_ACT_FORCED_RESYNC:
if (null == resp.inputFrameDownsyncBatch || 0 >= resp.inputFrameDownsyncBatch.length) { if (null == resp.inputFrameDownsyncBatch || 0 >= resp.inputFrameDownsyncBatch.length) {
console.error("Got empty inputFrameDownsyncBatch upon resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", the incoming resp=\n", JSON.stringify(resp, null, 2)); console.error(`Got empty inputFrameDownsyncBatch upon resync@localRenderFrameId=${mapIns.renderFrameId}, @lastAllConfirmedRenderFrameId=${mapIns.lastAllConfirmedRenderFrameId}, @lastAllConfirmedInputFrameId=${mapIns.lastAllConfirmedInputFrameId}, @chaserRenderFrameId=${mapIns.chaserRenderFrameId}, @localRecentInputCache=${mapIns._stringifyRecentInputCache(false)}, the incoming resp=
${JSON.stringify(resp, null, 2)}`);
return; return;
} }
// Unless upon ws session lost and reconnected, it's maintained true that "inputFrameDownsyncBatch[0].inputFrameId == frontend.lastAllConfirmedInputFrameId+1", and in this case we should try to keep frontend moving only by "frontend.recentInputCache" to avoid jiggling of synced positions
const inputFrameIdConsecutive = (resp.inputFrameDownsyncBatch[0].inputFrameId == mapIns.lastAllConfirmedInputFrameId + 1); const inputFrameIdConsecutive = (resp.inputFrameDownsyncBatch[0].inputFrameId == mapIns.lastAllConfirmedInputFrameId + 1);
const renderFrameIdConsecutive = (resp.rdf.id <= mapIns.renderFrameId + mapIns.renderFrameIdLagTolerance); const renderFrameIdConsecutive = (resp.rdf.id <= mapIns.renderFrameId + mapIns.renderFrameIdLagTolerance);
if (inputFrameIdConsecutive && renderFrameIdConsecutive) { console.warn(`Got resync@localRenderFrameId=${mapIns.renderFrameId}, @lastAllConfirmedRenderFrameId=${mapIns.lastAllConfirmedRenderFrameId}, @lastAllConfirmedInputFrameId=${mapIns.lastAllConfirmedInputFrameId}, @chaserRenderFrameId=${mapIns.chaserRenderFrameId}, @localRecentInputCache=${mapIns._stringifyRecentInputCache(false)}, inputFrameIdConsecutive=${inputFrameIdConsecutive}, renderFrameIdConsecutive=${renderFrameIdConsecutive}`);
// console.log("Got consecutive resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", the incoming resp=\n", JSON.stringify(resp)); // The following order of execution is important
mapIns.onInputFrameDownsyncBatch(resp.inputFrameDownsyncBatch); mapIns.onRoomDownsyncFrame(resp.rdf);
} else { mapIns.onInputFrameDownsyncBatch(resp.inputFrameDownsyncBatch);
// console.warn("Got forced resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", the incoming resp=\n", JSON.stringify(resp, null, 2));
console.warn("Got forced resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", inputFrameIdConsecutive=", inputFrameIdConsecutive, ", renderFrameIdConsecutive=", renderFrameIdConsecutive);
// The following order of execution is important
mapIns.onRoomDownsyncFrame(resp.rdf);
mapIns.onInputFrameDownsyncBatch(resp.inputFrameDownsyncBatch);
}
break; break;
default: default:
break; break;