Fixed frame data logging.

This commit is contained in:
genxium 2023-02-27 11:09:22 +08:00
parent 7fd96b335a
commit 04b033be7e
2 changed files with 64 additions and 36 deletions

View File

@ -407,6 +407,9 @@ func (pR *Room) rdfIdToActuallyUsedInputString() string {
}
fireballsStrBldr := make([]string, 0, len(rdf.FireballBullets))
for _, fireball := range rdf.FireballBullets {
if 0 > fireball.BattleAttr.BulletLocalId {
break
}
fireballsStrBldr = append(fireballsStrBldr, pR.fireballDownsyncStr(fireball))
}
s = append(s, fmt.Sprintf("rdfId:%d\nplayers:[%v]\nfireballs:[%v]\nactuallyUsedinputList:{%v}", rdfId, strings.Join(playersStrBldr, ","), strings.Join(fireballsStrBldr, ","), pR.inputFrameDownsyncStr(pR.rdfIdToActuallyUsedInput[rdfId])))
@ -805,7 +808,7 @@ func (pR *Room) OnDismissed() {
pR.RenderFrameBuffer = resolv.NewRingBuffer(pR.RenderCacheSize)
pR.InputsBuffer = resolv.NewRingBuffer((pR.RenderCacheSize >> 1) + 1)
pR.rdfIdToActuallyUsedInput = make(map[int32]*pb.InputFrameDownsync)
pR.allowUpdateInputFrameInPlaceUponDynamics = true
pR.allowUpdateInputFrameInPlaceUponDynamics = false
pR.LastIndividuallyConfirmedInputFrameId = make([]int32, pR.Capacity)
for i := 0; i < pR.Capacity; i++ {
pR.LastIndividuallyConfirmedInputFrameId[i] = MAGIC_LAST_SENT_INPUT_FRAME_ID_NORMAL_ADDED
@ -1305,15 +1308,18 @@ func (pR *Room) forceConfirmationIfApplicable(prevRenderFrameId int32) uint64 {
panic(fmt.Sprintf("inputFrameId=%v doesn't exist for roomId=%v! InputsBuffer=%v", j, pR.Id, pR.InputsBufferString(false)))
}
inputFrameDownsync := tmp.(*battle.InputFrameDownsync)
if pR.allowUpdateInputFrameInPlaceUponDynamics {
battle.UpdateInputFrameInPlaceUponDynamics(j, pR.Capacity, inputFrameDownsync.ConfirmedList, inputFrameDownsync.InputList, pR.LastIndividuallyConfirmedInputFrameId, pR.LastIndividuallyConfirmedInputList, int32(MAGIC_JOIN_INDEX_INVALID))
}
/*
// [WARN] Frame logging showed that using "battle.UpdateInputFrameInPlaceUponDynamics" here would CONTAMINATE "all-confirmed inputs already sent & recognized by the frontends", root cause remains to be invesitgated!
if pR.allowUpdateInputFrameInPlaceUponDynamics {
battle.UpdateInputFrameInPlaceUponDynamics(j, pR.Capacity, inputFrameDownsync.ConfirmedList, inputFrameDownsync.InputList, pR.LastIndividuallyConfirmedInputFrameId, pR.LastIndividuallyConfirmedInputList, int32(MAGIC_JOIN_INDEX_INVALID))
}
*/
unconfirmedMask |= (allConfirmedMask ^ inputFrameDownsync.ConfirmedList)
inputFrameDownsync.ConfirmedList = allConfirmedMask
pR.onInputFrameDownsyncAllConfirmed(inputFrameDownsync, -1)
}
if 0 < unconfirmedMask {
Logger.Info(fmt.Sprintf("[type#1 forceConfirmation] For roomId=%d@renderFrameId=%d, curDynamicsRenderFrameId=%d, LatestPlayerUpsyncedInputFrameId:%d, oldLastAllConfirmedInputFrameId:%d, newLastAllConfirmedInputFrameId:%d, InputFrameUpsyncDelayTolerance:%d, unconfirmedMask=%d; there's a slow ticker suspect, forcing all-confirmation", pR.Id, pR.RenderFrameId, pR.CurDynamicsRenderFrameId, pR.LatestPlayerUpsyncedInputFrameId, oldLastAllConfirmedInputFrameId, pR.LastAllConfirmedInputFrameId, pR.InputFrameUpsyncDelayTolerance, unconfirmedMask))
Logger.Info(fmt.Sprintf("[type#1 forceConfirmation] For roomId=%d@renderFrameId=%d, curDynamicsRenderFrameId=%d, LatestPlayerUpsyncedInputFrameId:%d, LastAllConfirmedInputFrameId:%d -> %d, InputFrameUpsyncDelayTolerance:%d, unconfirmedMask=%d; there's a slow ticker suspect, forcing all-confirmation", pR.Id, pR.RenderFrameId, pR.CurDynamicsRenderFrameId, pR.LatestPlayerUpsyncedInputFrameId, oldLastAllConfirmedInputFrameId, pR.LastAllConfirmedInputFrameId, pR.InputFrameUpsyncDelayTolerance, unconfirmedMask))
}
} else {
// Type#2 helps resolve the edge case when all players are disconnected temporarily
@ -1602,9 +1608,10 @@ func (pR *Room) downsyncToSinglePlayer(playerId int32, player *Player, refRender
pbRefRenderFrame := toPbRoomDownsyncFrame(refRenderFrame)
pbRefRenderFrame.SpeciesIdList = pR.SpeciesIdList
pR.sendSafely(pbRefRenderFrame, toSendInputFrameDownsyncsSnapshot, DOWNSYNC_MSG_ACT_FORCED_RESYNC, playerId, false, MAGIC_JOIN_INDEX_DEFAULT)
//Logger.Warn(fmt.Sprintf("Sent refRenderFrameId=%v & inputFrameIds [%d, %d), for roomId=%v, playerId=%d, playerJoinIndex=%d, renderFrameId=%d, curDynamicsRenderFrameId=%d, playerLastSentInputFrameId=%d: InputsBuffer=%v", refRenderFrameId, toSendInputFrameIdSt, toSendInputFrameIdEd, pR.Id, playerId, player.JoinIndex, pR.RenderFrameId, pR.CurDynamicsRenderFrameId, player.LastSentInputFrameId, pR.InputsBufferString(false)))
if shouldResync1 || shouldResync3 {
Logger.Debug(fmt.Sprintf("Sent refRenderFrameId=%v & inputFrameIds [%d, %d), for roomId=%v, playerId=%d, playerJoinIndex=%d, renderFrameId=%d, curDynamicsRenderFrameId=%d, playerLastSentInputFrameId=%d: shouldResync1=%v, shouldResync2=%v, shouldResync3=%v, playerBattleState=%d", refRenderFrameId, toSendInputFrameIdSt, toSendInputFrameIdEd, pR.Id, playerId, player.JoinIndex, pR.RenderFrameId, pR.CurDynamicsRenderFrameId, player.LastSentInputFrameId, shouldResync1, shouldResync2, shouldResync3, playerBattleState))
Logger.Info(fmt.Sprintf("Sent refRenderFrameId=%v & inputFrameIds [%d, %d), for roomId=%v, playerId=%d, playerJoinIndex=%d, renderFrameId=%d, curDynamicsRenderFrameId=%d, playerLastSentInputFrameId=%d: shouldResync1=%v, shouldResync2=%v, shouldResync3=%v, playerBattleState=%d", refRenderFrameId, toSendInputFrameIdSt, toSendInputFrameIdEd, pR.Id, playerId, player.JoinIndex, pR.RenderFrameId, pR.CurDynamicsRenderFrameId, player.LastSentInputFrameId, shouldResync1, shouldResync2, shouldResync3, playerBattleState))
} else {
Logger.Debug(fmt.Sprintf("Sent refRenderFrameId=%v & inputFrameIds [%d, %d), for roomId=%v, playerId=%d, playerJoinIndex=%d, renderFrameId=%d, curDynamicsRenderFrameId=%d, playerLastSentInputFrameId=%d: InputsBuffer=%v", refRenderFrameId, toSendInputFrameIdSt, toSendInputFrameIdEd, pR.Id, playerId, player.JoinIndex, pR.RenderFrameId, pR.CurDynamicsRenderFrameId, player.LastSentInputFrameId, pR.InputsBufferString(false)))
}
} else {
pR.sendSafely(nil, toSendInputFrameDownsyncsSnapshot, DOWNSYNC_MSG_ACT_INPUT_BATCH, playerId, false, MAGIC_JOIN_INDEX_DEFAULT)

View File

@ -714,6 +714,11 @@ cc.Class({
shouldForceDumping2 = false;
shouldForceResync = false;
self.othersForcedDownsyncRenderFrameDict.set(rdfId, rdf);
if (CC_DEBUG) {
console.warn(`Someone else is forced to resync! renderFrameId=${rdf.GetId()}
backendUnconfirmedMask=${pbRdf.backendUnconfirmedMask}
accompaniedInputFrameDownsyncBatchRange=[${null == accompaniedInputFrameDownsyncBatch ? null : accompaniedInputFrameDownsyncBatch[0].inputFrameId}, ${null == accompaniedInputFrameDownsyncBatch ? null : accompaniedInputFrameDownsyncBatch[accompaniedInputFrameDownsyncBatch.length - 1].inputFrameId}]`);
}
}
/*
TODO
@ -744,10 +749,15 @@ cc.Class({
// In fact, not having "window.RING_BUFF_CONSECUTIVE_SET == dumpRenderCacheRet" should already imply that "self.renderFrameId <= rdfId", but here we double check and log the anomaly
if (window.MAGIC_ROOM_DOWNSYNC_FRAME_ID.BATTLE_START == rdfId) {
console.log('On battle started! renderFrameId=', rdfId);
console.log(`On battle started! renderFrameId=${rdfId}`);
} else {
self.hideFindingPlayersGUI();
console.warn('On battle resynced! renderFrameId=', rdf.GetId());
if (CC_DEBUG) {
console.warn(`On battle resynced! renderFrameId=${rdf.GetId()}
accompaniedInputFrameDownsyncBatchRange=[${accompaniedInputFrameDownsyncBatch[0].inputFrameId}, ${accompaniedInputFrameDownsyncBatch[accompaniedInputFrameDownsyncBatch.length - 1].inputFrameId}]`);
} else {
console.warn(`On battle resynced! renderFrameId=${rdf.GetId()}`);
}
}
self.renderFrameId = rdfId;
@ -872,12 +882,12 @@ cc.Class({
while (self.recentInputCache.GetStFrameId() <= candidateInputFrameId && candidateInputFrameId < self.recentInputCache.GetEdFrameId()) {
const inputFrameDownsync = gopkgs.GetInputFrameDownsync(self.recentInputCache, candidateInputFrameId);
if (null == inputFrameDownsync) break;
if (self._allConfirmed(inputFrameDownsync.GetConfirmedList())) break;
if (false == self._allConfirmed(inputFrameDownsync.GetConfirmedList())) break;
++candidateInputFrameId;
++newAllConfirmedCnt;
}
if (0 < newAllConfirmedCnt) {
self.lastAllConfirmedInputFrameId = candidateInputFrameId;
self.lastAllConfirmedInputFrameId = candidateInputFrameId - 1;
}
return newAllConfirmedCnt;
},
@ -904,6 +914,7 @@ cc.Class({
continue;
}
// [WARNING] Now that "inputFrameDownsyncId > self.lastAllConfirmedInputFrameId", we should make an update immediately because unlike its backend counterpart "Room.LastAllConfirmedInputFrameId", the frontend "mapIns.lastAllConfirmedInputFrameId" might inevitably get gaps among discrete values due to "either type#1 or type#2 forceConfirmation" -- and only "onInputFrameDownsyncBatch" can catch this!
self.lastAllConfirmedInputFrameId = inputFrameDownsyncId;
const localInputFrame = gopkgs.GetInputFrameDownsync(self.recentInputCache, inputFrameDownsyncId);
if (null != localInputFrame
&&
@ -1000,8 +1011,8 @@ fromUDP=${fromUDP}`);
}
const peerJoinIndexMask = (1 << (peerJoinIndex - 1));
self.getOrPrefabInputFrameUpsync(inputFrameId, false); // Make sure that inputFrame exists locally
const existingInputFrame = self.recentInputCache.GetByFrameId(inputFrameId);
if (0 < (existingInputFrame.ConfirmedList & peerJoinIndexMask)) {
const existingInputFrame = gopkgs.GetInputFrameDownsync(self.recentInputCache, inputFrameId);
if (0 < (existingInputFrame.GetConfirmedList() & peerJoinIndexMask)) {
continue;
}
if (inputFrameId > self.lastIndividuallyConfirmedInputFrameId[peerJoinIndex - 1]) {
@ -1010,9 +1021,9 @@ fromUDP=${fromUDP}`);
}
effCnt += 1;
// the returned "gopkgs.NewInputFrameDownsync.InputList" is immutable, thus we can only modify the values in "newInputList" and "newConfirmedList"!
let newInputList = existingInputFrame.InputList.slice();
let newInputList = existingInputFrame.GetInputList().slice();
newInputList[peerJoinIndex - 1] = peerEncodedInput;
let newConfirmedList = (existingInputFrame.ConfirmedList | peerJoinIndexMask);
let newConfirmedList = (existingInputFrame.GetConfirmedList() | peerJoinIndexMask);
const newInputFrameDownsyncLocal = gopkgs.NewInputFrameDownsync(inputFrameId, newInputList, newConfirmedList);
//console.log(`Updated encoded input of peerJoinIndex=${peerJoinIndex} to ${peerEncodedInput} for inputFrameId=${inputFrameId}/renderedInputFrameIdUpper=${renderedInputFrameIdUpper} from ${JSON.stringify(inputFrame)}; newInputFrameDownsyncLocal=${self.gopkgsInputFrameDownsyncStr(newInputFrameDownsyncLocal)}; existingInputFrame=${self.gopkgsInputFrameDownsyncStr(existingInputFrame)}`);
self.recentInputCache.SetByFrameId(newInputFrameDownsyncLocal, inputFrameId);
@ -1164,9 +1175,11 @@ fromUDP=${fromUDP}`);
const delayedInputFrameId = gopkgs.ConvertToDelayedInputFrameId(rdf.GetId());
const othersForcedDownsyncRenderFrame = self.othersForcedDownsyncRenderFrameDict.get(rdf.GetId());
if (self.lastAllConfirmedInputFrameId >= delayedInputFrameId && !self.equalRoomDownsyncFrames(othersForcedDownsyncRenderFrame, rdf)) {
console.warn(`Mismatched render frame@rdf.id=${rdf.GetId()} w/ inputFrameId=${delayedInputFrameId}:
rdf=${JSON.stringify(rdf)}
othersForcedDownsyncRenderFrame=${JSON.stringify(othersForcedDownsyncRenderFrame)}`);
if (CC_DEBUG) {
console.warn(`Mismatched render frame@rdf.id=${rdf.GetId()} w/ inputFrameId=${delayedInputFrameId}:
rdf=${self._stringifyGopkgRdfForFrameDataLogging(rdf)}
othersForcedDownsyncRenderFrame=${self._stringifyGopkgRdfForFrameDataLogging(othersForcedDownsyncRenderFrame)}`);
}
rdf = othersForcedDownsyncRenderFrame;
self.othersForcedDownsyncRenderFrameDict.delete(rdf.GetId());
}
@ -1423,8 +1436,11 @@ othersForcedDownsyncRenderFrame=${JSON.stringify(othersForcedDownsyncRenderFrame
const j = gopkgs.ConvertToDelayedInputFrameId(i);
const delayedInputFrame = gopkgs.GetInputFrameDownsync(self.recentInputCache, j);
const allowUpdateInputFrameInPlaceUponDynamics = (!isChasing);
const renderRes = gopkgs.ApplyInputFrameDownsyncDynamicsOnSingleRenderFrameJs(self.recentInputCache, i, collisionSys, collisionSysMap, self.spaceOffsetX, self.spaceOffsetY, self.chConfigsOrderedByJoinIndex, self.recentRenderCache, self.collisionHolder, self.effPushbacks, self.hardPushbackNormsArr, self.jumpedOrNotList, self.dynamicRectangleColliders, self.lastIndividuallyConfirmedInputFrameId, self.lastIndividuallyConfirmedInputList, allowUpdateInputFrameInPlaceUponDynamics, self.selfPlayerInfo.joinIndex);
if (self.frameDataLoggingEnabled) {
const actuallyUsedInputClone = delayedInputFrame.GetInputList();
// [WARNING] The "inputList" of "delayedInputFrame" could be mutated in "ApplyInputFrameDownsyncDynamicsOnSingleRenderFrameJs", thus should clone after dynamics is applied!
const actuallyUsedInputClone = delayedInputFrame.GetInputList().slice();
const inputFrameDownsyncClone = {
inputFrameId: j,
inputList: actuallyUsedInputClone,
@ -1432,8 +1448,6 @@ othersForcedDownsyncRenderFrame=${JSON.stringify(othersForcedDownsyncRenderFrame
};
self.rdfIdToActuallyUsedInput.set(i, inputFrameDownsyncClone);
}
const allowUpdateInputFrameInPlaceUponDynamics = (!isChasing);
const renderRes = gopkgs.ApplyInputFrameDownsyncDynamicsOnSingleRenderFrameJs(self.recentInputCache, i, collisionSys, collisionSysMap, self.spaceOffsetX, self.spaceOffsetY, self.chConfigsOrderedByJoinIndex, self.recentRenderCache, self.collisionHolder, self.effPushbacks, self.hardPushbackNormsArr, self.jumpedOrNotList, self.dynamicRectangleColliders, self.lastIndividuallyConfirmedInputFrameId, self.lastIndividuallyConfirmedInputList, allowUpdateInputFrameInPlaceUponDynamics, self.selfPlayerInfo.joinIndex);
const nextRdf = gopkgs.GetRoomDownsyncFrame(self.recentRenderCache, i + 1);
if (true == isChasing) {
@ -1549,34 +1563,41 @@ othersForcedDownsyncRenderFrame=${JSON.stringify(othersForcedDownsyncRenderFrame
if (null == inputFrameDownsync) return "{}";
const self = this;
let s = [];
s.push(`InputFrameId:${inputFrameDownsync.InputFrameId}`);
s.push(`InputFrameId:${inputFrameDownsync.GetInputFrameId()}`);
let ss = [];
for (let k = 0; k < window.boundRoomCapacity; ++k) {
ss.push(`"${inputFrameDownsync.InputList[k]}"`);
ss.push(`"${inputFrameDownsync.GetInputList()[k]}"`);
}
s.push(`InputList:[${ss.join(',')}]`);
s.push(`ConfirmedList:${inputFrameDownsync.ConfirmedList}`);
s.push(`ConfirmedList:${inputFrameDownsync.GetConfirmedList()}`);
return `{${s.join(',')}}`;
},
_stringifyGopkgRdfForFrameDataLogging(rdf) {
const playersStrBldr = [];
for (let k = 0; k < window.boundRoomCapacity; k++) {
playersStrBldr.push(this.playerDownsyncStr(gopkgs.GetPlayer(rdf, k)));
}
const fireballsStrBldr = [];
for (let k = 0;; k++) {
const fireball = gopkgs.GetFireballBullet(rdf, k);
if (null == fireball) break;
fireballsStrBldr.push(this.fireballDownsyncStr(fireball));
}
return `rdfId:${rdf.GetId()}
players:[${playersStrBldr.join(',')}]
fireballs:[${fireballsStrBldr.join(',')}]`;
},
_stringifyRdfIdToActuallyUsedInput() {
const self = this;
let s = [];
for (let i = self.recentRenderCache.GetStFrameId(); i < self.recentRenderCache.GetEdFrameId(); i++) {
const actuallyUsedInputClone = self.rdfIdToActuallyUsedInput.get(i);
const rdf = self.recentRenderCache.GetByFrameId(i);
const playersStrBldr = [];
for (let k in rdf.GetPlayersArr()) {
playersStrBldr.push(self.playerDownsyncStr(rdf.GetPlayersArr()[k]));
}
const fireballsStrBldr = [];
for (let k in rdf.FireballBullets) {
fireballsStrBldr.push(self.fireballDownsyncStr(rdf.FireballBullets[k]));
}
s.push(`rdfId:${i}
players:[${playersStrBldr.join(',')}]
fireballs:[${fireballsStrBldr.join(',')}]
const rdf = gopkgs.GetRoomDownsyncFrame(self.recentRenderCache, i);
const rdfStr = self._stringifyGopkgRdfForFrameDataLogging(rdf);
s.push(`${rdfStr}
actuallyUsedinputList:{${self.inputFrameDownsyncStr(actuallyUsedInputClone)}}`);
}