Updated logging.

This commit is contained in:
genxium 2022-10-01 20:45:38 +08:00
parent cd83539197
commit 2264c0d362
6 changed files with 259 additions and 244 deletions

View File

@ -8,8 +8,8 @@ import (
"github.com/solarlune/resolv"
"go.uber.org/zap"
"io/ioutil"
"math/rand"
"math"
"math/rand"
"os"
"path/filepath"
. "server/common"
@ -336,7 +336,7 @@ func (pR *Room) ConvertToFirstUsedRenderFrameId(inputFrameId int32, inputDelayFr
}
func (pR *Room) ConvertToLastUsedRenderFrameId(inputFrameId int32, inputDelayFrames int32) int32 {
return ((inputFrameId << pR.InputScaleFrames) + inputDelayFrames + (1 << pR.InputScaleFrames)-1)
return ((inputFrameId << pR.InputScaleFrames) + inputDelayFrames + (1 << pR.InputScaleFrames) - 1)
}
func (pR *Room) EncodeUpsyncCmd(upsyncCmd *pb.InputFrameUpsync) uint64 {
@ -346,9 +346,10 @@ func (pR *Room) EncodeUpsyncCmd(upsyncCmd *pb.InputFrameUpsync) uint64 {
return ret
}
func (pR *Room) AllPlayerInputsBufferString() string {
func (pR *Room) AllPlayerInputsBufferString(allDetails bool) string {
s := make([]string, 0)
s = append(s, fmt.Sprintf("\n{stInputFrameId: %v, edInputFrameId: %v, lastAllConfirmedInputFrameIdWithChange: %v, lastAllConfirmedInputFrameId: %v}", pR.AllPlayerInputsBuffer.StFrameId, pR.AllPlayerInputsBuffer.EdFrameId, pR.LastAllConfirmedInputFrameIdWithChange, pR.LastAllConfirmedInputFrameId))
s = append(s, fmt.Sprintf("{renderFrameId: %v, stInputFrameId: %v, edInputFrameId: %v, lastAllConfirmedInputFrameIdWithChange: %v, lastAllConfirmedInputFrameId: %v}", pR.RenderFrameId, pR.AllPlayerInputsBuffer.StFrameId, pR.AllPlayerInputsBuffer.EdFrameId, pR.LastAllConfirmedInputFrameIdWithChange, pR.LastAllConfirmedInputFrameId))
if allDetails {
for playerId, player := range pR.Players {
s = append(s, fmt.Sprintf("{playerId: %v, ackingFrameId: %v, ackingInputFrameId: %v, lastSentInputFrameId: %v}", playerId, player.AckingFrameId, player.AckingInputFrameId, player.LastSentInputFrameId))
}
@ -360,6 +361,7 @@ func (pR *Room) AllPlayerInputsBufferString() string {
f := tmp.(*pb.InputFrameDownsync)
s = append(s, fmt.Sprintf("{inputFrameId: %v, inputList: %v, confirmedList: %v}", f.InputFrameId, f.InputList, f.ConfirmedList))
}
}
return strings.Join(s, "\n")
}
@ -373,7 +375,17 @@ func (pR *Room) StartBattle() {
// Always instantiates a new channel and let the old one die out due to not being retained by any root reference.
nanosPerFrame := 1000000000 / int64(pR.ServerFPS)
pR.RenderFrameId = 0
// Initialize the "collisionSys" as well as "RenderFrameBuffer"
pR.CurDynamicsRenderFrameId = 0
kickoffFrame := &pb.RoomDownsyncFrame{
Id: pR.RenderFrameId,
RefFrameId: MAGIC_ROOM_DOWNSYNC_FRAME_ID_BATTLE_START, // Legacy frontend codes need this special "refFrameId" to remove the "3-2-1-countdown" logo
Players: toPbPlayers(pR.Players),
SentAt: utils.UnixtimeMilli(),
CountdownNanos: pR.BattleDurationNanos,
}
pR.RenderFrameBuffer.Put(kickoffFrame)
// Refresh "Colliders"
pR.refreshColliders()
@ -398,30 +410,8 @@ func (pR *Room) StartBattle() {
for {
stCalculation := utils.UnixtimeNano()
if 0 == pR.RenderFrameId {
// The legacy frontend code needs this "kickoffFrame" to remove the "ready to start 3-2-1" panel
kickoffFrame := pb.RoomDownsyncFrame{
Id: pR.RenderFrameId,
RefFrameId: MAGIC_ROOM_DOWNSYNC_FRAME_ID_BATTLE_START,
Players: toPbPlayers(pR.Players),
SentAt: utils.UnixtimeMilli(),
CountdownNanos: (pR.BattleDurationNanos - totalElapsedNanos),
}
pR.RenderFrameBuffer.Put(&kickoffFrame)
for playerId, player := range pR.Players {
if swapped := atomic.CompareAndSwapInt32(&player.BattleState, PlayerBattleStateIns.ACTIVE, PlayerBattleStateIns.ACTIVE); !swapped {
/*
[WARNING] DON'T send anything into "DedicatedForwardingChanForPlayer" if the player is disconnected, because it could jam the channel and cause significant delay upon "battle recovery for reconnected player".
*/
continue
}
pR.sendSafely(&kickoffFrame, nil, DOWNSYNC_MSG_ACT_ROOM_FRAME, playerId)
}
}
if totalElapsedNanos > pR.BattleDurationNanos {
Logger.Info(fmt.Sprintf("The `battleMainLoop` for roomId=%v is stopped:\n%v", pR.Id, pR.AllPlayerInputsBufferString()))
Logger.Info(fmt.Sprintf("The `battleMainLoop` for roomId=%v is stopped:\n%v", pR.Id, pR.AllPlayerInputsBufferString(true)))
pR.StopBattleForSettlement()
}
@ -438,25 +428,32 @@ func (pR *Room) StartBattle() {
// Force setting all-confirmed of buffered inputFrames periodically
unconfirmedMask := pR.forceConfirmationIfApplicable()
dynamicsDuration := int64(0)
if 0 <= pR.LastAllConfirmedInputFrameId {
dynamicsStartedAt := utils.UnixtimeNano()
// Apply "all-confirmed inputFrames" to move forward "pR.CurDynamicsRenderFrameId"
if 0 <= pR.CurDynamicsRenderFrameId {
nextDynamicsRenderFrameId := pR.ConvertToLastUsedRenderFrameId(pR.LastAllConfirmedInputFrameId, pR.InputDelayFrames)
Logger.Debug(fmt.Sprintf("roomId=%v, room.RenderFrameId=%v, LastAllConfirmedInputFrameId=%v, InputDelayFrames=%v, nextDynamicsRenderFrameId=%v", pR.Id, pR.RenderFrameId, pR.LastAllConfirmedInputFrameId, pR.InputDelayFrames, nextDynamicsRenderFrameId))
pR.applyInputFrameDownsyncDynamics(pR.CurDynamicsRenderFrameId, nextDynamicsRenderFrameId)
dynamicsDuration = utils.UnixtimeNano() - dynamicsStartedAt
}
lastAllConfirmedInputFrameIdWithChange := atomic.LoadInt32(&(pR.LastAllConfirmedInputFrameIdWithChange))
for playerId, player := range pR.Players {
if swapped := atomic.CompareAndSwapInt32(&player.BattleState, PlayerBattleStateIns.ACTIVE, PlayerBattleStateIns.ACTIVE); !swapped {
/*
[WARNING] DON'T send anything into "DedicatedForwardingChanForPlayer" if the player is disconnected, because it could jam the channel and cause significant delay upon "battle recovery for reconnected player".
*/
// [WARNING] DON'T send anything if the player is disconnected, because it could jam the channel and cause significant delay upon "battle recovery for reconnected player".
continue
}
if 0 == pR.RenderFrameId {
kickoffFrame := pR.RenderFrameBuffer.GetByFrameId(0).(*pb.RoomDownsyncFrame)
pR.sendSafely(kickoffFrame, nil, DOWNSYNC_MSG_ACT_ROOM_FRAME, playerId)
} else {
// [WARNING] Websocket is TCP-based, thus no need to re-send a previously sent inputFrame to a same player!
toSendInputFrames := make([]*pb.InputFrameDownsync, 0, pR.AllPlayerInputsBuffer.Cnt)
candidateToSendInputFrameId := atomic.LoadInt32(&(pR.Players[playerId].LastSentInputFrameId)) + 1
if candidateToSendInputFrameId < pR.AllPlayerInputsBuffer.StFrameId {
Logger.Warn(fmt.Sprintf("LastSentInputFrameId already popped: roomId=%v, playerId=%v, lastSentInputFrameId=%v, playerAckingInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, candidateToSendInputFrameId-1, player.AckingInputFrameId, pR.AllPlayerInputsBufferString()))
// [WARNING] As "player.LastSentInputFrameId <= lastAllConfirmedInputFrameIdWithChange" for each iteration, and "lastAllConfirmedInputFrameIdWithChange <= lastAllConfirmedInputFrameId" where the latter is used to "applyInputFrameDownsyncDynamics" and then evict "pR.AllPlayerInputsBuffer", thus there's a very high possibility that "player.LastSentInputFrameId" is already evicted.
// Logger.Debug(fmt.Sprintf("LastSentInputFrameId already popped: roomId=%v, playerId=%v, lastSentInputFrameId=%v, playerAckingInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, candidateToSendInputFrameId-1, player.AckingInputFrameId, pR.AllPlayerInputsBufferString(false)))
candidateToSendInputFrameId = pR.AllPlayerInputsBuffer.StFrameId
}
@ -466,12 +463,12 @@ func (pR *Room) StartBattle() {
for candidateToSendInputFrameId <= lastAllConfirmedInputFrameIdWithChange {
tmp := pR.AllPlayerInputsBuffer.GetByFrameId(candidateToSendInputFrameId)
if nil == tmp {
panic(fmt.Sprintf("Required inputFrameId=%v for roomId=%v, playerId=%v doesn't exist! AllPlayerInputsBuffer=%v", candidateToSendInputFrameId, pR.Id, playerId, pR.AllPlayerInputsBufferString()))
panic(fmt.Sprintf("Required inputFrameId=%v for roomId=%v, playerId=%v doesn't exist! AllPlayerInputsBuffer=%v", candidateToSendInputFrameId, pR.Id, playerId, pR.AllPlayerInputsBufferString(false)))
}
f := tmp.(*pb.InputFrameDownsync)
if pR.inputFrameIdDebuggable(candidateToSendInputFrameId) {
debugSendingInputFrameId = candidateToSendInputFrameId
Logger.Info("inputFrame lifecycle#3[sending]:", zap.Any("roomId", pR.Id), zap.Any("playerId", playerId), zap.Any("playerAckingInputFrameId", player.AckingInputFrameId), zap.Any("inputFrameId", candidateToSendInputFrameId), zap.Any("inputFrameId-doublecheck", f.InputFrameId), zap.Any("AllPlayerInputsBuffer", pR.AllPlayerInputsBufferString()), zap.Any("ConfirmedList", f.ConfirmedList))
Logger.Info("inputFrame lifecycle#3[sending]:", zap.Any("roomId", pR.Id), zap.Any("playerId", playerId), zap.Any("playerAckingInputFrameId", player.AckingInputFrameId), zap.Any("inputFrameId", candidateToSendInputFrameId), zap.Any("inputFrameId-doublecheck", f.InputFrameId), zap.Any("AllPlayerInputsBuffer", pR.AllPlayerInputsBufferString(false)), zap.Any("ConfirmedList", f.ConfirmedList))
}
toSendInputFrames = append(toSendInputFrames, f)
candidateToSendInputFrameId++
@ -487,11 +484,12 @@ func (pR *Room) StartBattle() {
continue
}
pR.sendSafely(nil, toSendInputFrames, DOWNSYNC_MSG_ACT_INPUT_BATCH, playerId)
atomic.StoreInt32(&(pR.Players[playerId].LastSentInputFrameId), candidateToSendInputFrameId-1)
if -1 != debugSendingInputFrameId {
Logger.Info("inputFrame lifecycle#4[sent]:", zap.Any("roomId", pR.Id), zap.Any("playerId", playerId), zap.Any("playerAckingInputFrameId", player.AckingInputFrameId), zap.Any("inputFrameId", debugSendingInputFrameId), zap.Any("AllPlayerInputsBuffer", pR.AllPlayerInputsBufferString()))
Logger.Info("inputFrame lifecycle#4[sent]:", zap.Any("roomId", pR.Id), zap.Any("playerId", playerId), zap.Any("playerAckingInputFrameId", player.AckingInputFrameId), zap.Any("inputFrameId", debugSendingInputFrameId), zap.Any("AllPlayerInputsBuffer", pR.AllPlayerInputsBufferString(false)))
}
}
atomic.StoreInt32(&(pR.Players[playerId].LastSentInputFrameId), candidateToSendInputFrameId-1)
}
}
for 0 < pR.RenderFrameBuffer.Cnt && pR.RenderFrameBuffer.StFrameId < pR.CurDynamicsRenderFrameId {
@ -508,10 +506,11 @@ func (pR *Room) StartBattle() {
}
pR.RenderFrameId++
now := utils.UnixtimeNano()
elapsedInCalculation := (now - stCalculation)
totalElapsedNanos = (now - battleMainLoopStartedNanos)
// Logger.Info("Elapsed time statistics:", zap.Any("roomId", pR.Id), zap.Any("elapsedInCalculation", elapsedInCalculation), zap.Any("totalElapsedNanos", totalElapsedNanos))
elapsedInCalculation := (utils.UnixtimeNano() - stCalculation)
totalElapsedNanos = (utils.UnixtimeNano() - battleMainLoopStartedNanos)
if elapsedInCalculation > nanosPerFrame {
Logger.Warn(fmt.Sprintf("SLOW FRAME! Elapsed time statistics: roomId=%v, room.RenderFrameId=%v, elapsedInCalculation=%v, dynamicsDuration=%v, nanosPerFrame=%v", pR.Id, pR.RenderFrameId, elapsedInCalculation, dynamicsDuration, nanosPerFrame))
}
time.Sleep(time.Duration(nanosPerFrame - elapsedInCalculation))
}
}
@ -549,7 +548,8 @@ func (pR *Room) OnBattleCmdReceived(pReq *pb.WsReq) {
for _, inputFrameUpsync := range inputFrameUpsyncBatch {
clientInputFrameId := inputFrameUpsync.InputFrameId
if clientInputFrameId < pR.AllPlayerInputsBuffer.StFrameId {
Logger.Warn(fmt.Sprintf("Obsolete inputFrameUpsync: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString()))
// Obsolete is actually not as concerned as advanced inputFrame.
Logger.Debug(fmt.Sprintf("Obsolete inputFrameUpsync: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString(false)))
return
}
@ -557,19 +557,19 @@ func (pR *Room) OnBattleCmdReceived(pReq *pb.WsReq) {
encodedInput := pR.EncodeUpsyncCmd(inputFrameUpsync)
if clientInputFrameId >= pR.AllPlayerInputsBuffer.EdFrameId {
Logger.Warn(fmt.Sprintf("inputFrame too advanced! is the player cheating?: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString()))
Logger.Warn(fmt.Sprintf("inputFrame too advanced! is the player cheating?: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString(false)))
return
}
tmp2 := pR.AllPlayerInputsBuffer.GetByFrameId(clientInputFrameId)
if nil == tmp2 {
// This shouldn't happen due to the previous 2 checks
Logger.Warn(fmt.Sprintf("Mysterious error getting an input frame: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString()))
Logger.Warn(fmt.Sprintf("Mysterious error getting an input frame: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString(false)))
return
}
inputFrameDownsync := tmp2.(*pb.InputFrameDownsync)
oldConfirmedList := atomic.LoadUint64(&(inputFrameDownsync.ConfirmedList))
if (oldConfirmedList & joinMask) > 0 {
Logger.Warn(fmt.Sprintf("Cmd already confirmed but getting set attempt, omitting this upsync cmd: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString()))
Logger.Warn(fmt.Sprintf("Cmd already confirmed but getting set attempt, omitting this upsync cmd: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.AllPlayerInputsBufferString(false)))
return
}
@ -595,18 +595,22 @@ func (pR *Room) OnBattleCmdReceived(pReq *pb.WsReq) {
}
func (pR *Room) onInputFrameDownsyncAllConfirmed(inputFrameDownsync *pb.InputFrameDownsync, playerId int32) {
clientInputFrameId := inputFrameDownsync.InputFrameId
if false == pR.equalInputLists(inputFrameDownsync.InputList, pR.LastAllConfirmedInputList) {
atomic.StoreInt32(&(pR.LastAllConfirmedInputFrameIdWithChange), clientInputFrameId) // [WARNING] Different from the CAS in "battleMainLoop", it's safe to just update "pR.LastAllConfirmedInputFrameIdWithChange" here, because only monotonic increment is possible here!
Logger.Info(fmt.Sprintf("Key inputFrame change: roomId=%v, playerId=%v, clientInputFrameId=%v, lastInputFrameId=%v, newInputList=%v, lastInputList=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.LastAllConfirmedInputFrameId, inputFrameDownsync.InputList, pR.LastAllConfirmedInputList, pR.AllPlayerInputsBufferString()))
inputFrameId := inputFrameDownsync.InputFrameId
if -1 == pR.LastAllConfirmedInputFrameIdWithChange || false == pR.equalInputLists(inputFrameDownsync.InputList, pR.LastAllConfirmedInputList) {
atomic.StoreInt32(&(pR.LastAllConfirmedInputFrameIdWithChange), inputFrameId) // [WARNING] Different from the CAS in "battleMainLoop", it's safe to just update "pR.LastAllConfirmedInputFrameIdWithChange" here, because only monotonic increment is possible here!
Logger.Info(fmt.Sprintf("Key inputFrame change: roomId=%v, playerId=%v, inputFrameId=%v, lastInputFrameId=%v, newInputList=%v, lastInputList=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, inputFrameId, pR.LastAllConfirmedInputFrameId, inputFrameDownsync.InputList, pR.LastAllConfirmedInputList, pR.AllPlayerInputsBufferString(false)))
}
atomic.StoreInt32(&(pR.LastAllConfirmedInputFrameId), clientInputFrameId) // [WARNING] It's IMPORTANT that "pR.LastAllConfirmedInputFrameId" is NOT NECESSARILY CONSECUTIVE, i.e. if one of the players disconnects and reconnects within a considerable amount of frame delays!
atomic.StoreInt32(&(pR.LastAllConfirmedInputFrameId), inputFrameId) // [WARNING] It's IMPORTANT that "pR.LastAllConfirmedInputFrameId" is NOT NECESSARILY CONSECUTIVE, i.e. if one of the players disconnects and reconnects within a considerable amount of frame delays!
for i, v := range inputFrameDownsync.InputList {
// To avoid potential misuse of pointers
pR.LastAllConfirmedInputList[i] = v
}
if pR.inputFrameIdDebuggable(clientInputFrameId) {
Logger.Info(fmt.Sprintf("inputFrame lifecycle#2[allconfirmed]: roomId=%v, playerId=%v, clientInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, clientInputFrameId, pR.LastAllConfirmedInputFrameId, pR.AllPlayerInputsBufferString()))
if pR.inputFrameIdDebuggable(inputFrameId) {
if -1 == playerId {
Logger.Info(fmt.Sprintf("inputFrame lifecycle#2[forced-allconfirmed]: roomId=%v, inputFrameId=%v, lastAllConfirmedInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, inputFrameId, pR.LastAllConfirmedInputFrameId, pR.AllPlayerInputsBufferString(false)))
} else {
Logger.Info(fmt.Sprintf("inputFrame lifecycle#2[allconfirmed]: roomId=%v, playerId=%v, inputFrameId=%v, lastAllConfirmedInputFrameId=%v, AllPlayerInputsBuffer=%v", pR.Id, playerId, inputFrameId, pR.LastAllConfirmedInputFrameId, pR.AllPlayerInputsBufferString(false)))
}
}
}
@ -1012,7 +1016,7 @@ func (pR *Room) prefabInputFrameDownsync(inputFrameId int32) *pb.InputFrameDowns
} else {
tmp := pR.AllPlayerInputsBuffer.GetByFrameId(inputFrameId - 1)
if nil == tmp {
panic(fmt.Sprintf("Error prefabbing inputFrameDownsync: roomId=%v, AllPlayerInputsBuffer=%v", pR.Id, pR.AllPlayerInputsBufferString()))
panic(fmt.Sprintf("Error prefabbing inputFrameDownsync: roomId=%v, AllPlayerInputsBuffer=%v", pR.Id, pR.AllPlayerInputsBufferString(false)))
}
prevInputFrameDownsync := tmp.(*pb.InputFrameDownsync)
currInputList := prevInputFrameDownsync.InputList // Would be a clone of the values
@ -1033,6 +1037,8 @@ func (pR *Room) forceConfirmationIfApplicable() uint64 {
if 0 > renderFrameId1 || !pR.shouldPrefabInputFrameDownsync(renderFrameId1) {
/*
The backend "shouldPrefabInputFrameDownsync" shares the same rule as frontend "shouldGenerateInputFrameUpsync".
It's also important that "forceConfirmationIfApplicable" is NOT EXECUTED for every renderFrame, such that when a player is forced to resync, it has some time, i.e. (1 << InputScaleFrames) renderFrames, to upsync again.
*/
return 0
}
@ -1040,7 +1046,7 @@ func (pR *Room) forceConfirmationIfApplicable() uint64 {
inputFrameId2 := pR.ConvertToInputFrameId(renderFrameId1, 0) // The inputFrame to force confirmation (if necessary)
tmp := pR.AllPlayerInputsBuffer.GetByFrameId(inputFrameId2)
if nil == tmp {
panic(fmt.Sprintf("inputFrameId2=%v doesn't exist for roomId=%v, this is abnormal because the server should prefab inputFrameDownsync in a most advanced pace, check the prefab logic! AllPlayerInputsBuffer=%v", inputFrameId2, pR.Id, pR.AllPlayerInputsBufferString()))
panic(fmt.Sprintf("inputFrameId2=%v doesn't exist for roomId=%v, this is abnormal because the server should prefab inputFrameDownsync in a most advanced pace, check the prefab logic! AllPlayerInputsBuffer=%v", inputFrameId2, pR.Id, pR.AllPlayerInputsBufferString(false)))
}
inputFrame2 := tmp.(*pb.InputFrameDownsync)
@ -1056,7 +1062,8 @@ func (pR *Room) forceConfirmationIfApplicable() uint64 {
atomic.StoreUint64(&(inputFrame2.ConfirmedList), allConfirmedMask)
pR.onInputFrameDownsyncAllConfirmed(inputFrame2, -1)
return (oldConfirmedList^allConfirmedMask)
unconfirmedMask := (oldConfirmedList ^ allConfirmedMask)
return unconfirmedMask
}
func (pR *Room) applyInputFrameDownsyncDynamics(fromRenderFrameId int32, toRenderFrameId int32) {
@ -1064,6 +1071,8 @@ func (pR *Room) applyInputFrameDownsyncDynamics(fromRenderFrameId int32, toRende
return
}
Logger.Debug(fmt.Sprintf("Applying inputFrame dynamics: roomId=%v, room.RenderFrameId=%v, fromRenderFrameId=%v, toRenderFrameId=%v", pR.Id, pR.RenderFrameId, fromRenderFrameId, toRenderFrameId))
totPlayerCnt := uint32(pR.Capacity)
allConfirmedMask := uint64((1 << totPlayerCnt) - 1)
@ -1072,25 +1081,27 @@ func (pR *Room) applyInputFrameDownsyncDynamics(fromRenderFrameId int32, toRende
if 0 <= delayedInputFrameId {
tmp := pR.AllPlayerInputsBuffer.GetByFrameId(delayedInputFrameId)
if nil == tmp {
panic(fmt.Sprintf("delayedInputFrameId=%v doesn't exist for roomId=%v, this is abnormal because it's to be used for applying dynamics to [fromRenderFrameId:%v, toRenderFrameId:%v) @ collisionSysRenderFrameId=%v! AllPlayerInputsBuffer=%v", delayedInputFrameId, pR.Id, fromRenderFrameId, toRenderFrameId, collisionSysRenderFrameId, pR.AllPlayerInputsBufferString()))
panic(fmt.Sprintf("delayedInputFrameId=%v doesn't exist for roomId=%v, this is abnormal because it's to be used for applying dynamics to [fromRenderFrameId:%v, toRenderFrameId:%v) @ collisionSysRenderFrameId=%v! AllPlayerInputsBuffer=%v", delayedInputFrameId, pR.Id, fromRenderFrameId, toRenderFrameId, collisionSysRenderFrameId, pR.AllPlayerInputsBufferString(false)))
}
delayedInputFrame := tmp.(*pb.InputFrameDownsync)
if swapped := atomic.CompareAndSwapUint64(&(delayedInputFrame.ConfirmedList), allConfirmedMask, allConfirmedMask); !swapped {
panic(fmt.Sprintf("delayedInputFrameId=%v is not yet all-confirmed for roomId=%v, this is abnormal because it's to be used for applying dynamics to [fromRenderFrameId:%v, toRenderFrameId:%v) @ collisionSysRenderFrameId=%v! AllPlayerInputsBuffer=%v", delayedInputFrameId, pR.Id, fromRenderFrameId, toRenderFrameId, collisionSysRenderFrameId, pR.AllPlayerInputsBufferString()))
panic(fmt.Sprintf("delayedInputFrameId=%v is not yet all-confirmed for roomId=%v, this is abnormal because it's to be used for applying dynamics to [fromRenderFrameId:%v, toRenderFrameId:%v) @ collisionSysRenderFrameId=%v! AllPlayerInputsBuffer=%v", delayedInputFrameId, pR.Id, fromRenderFrameId, toRenderFrameId, collisionSysRenderFrameId, pR.AllPlayerInputsBufferString(false)))
}
inputList := delayedInputFrame.InputList
// Ordered by joinIndex to guarantee determinism
for _, player := range pR.PlayersArr {
joinIndex := player.JoinIndex
collisionPlayerIndex := COLLISION_PLAYER_INDEX_PREFIX + joinIndex
playerCollider := pR.CollisionSysMap[collisionPlayerIndex]
encodedInput := inputList[joinIndex-1]
decodedInput := DIRECTION_DECODER[encodedInput]
decodedInputSpeedFactor := DIRECTION_DECODER_INVERSE_LENGTH[encodedInput]
baseChange := player.Speed * pR.RollbackEstimatedDt * decodedInputSpeedFactor
dx := baseChange * float64(decodedInput[0])
dy := baseChange * float64(decodedInput[1])
/*
// The collision lib seems very slow at worst cases, omitting for now
collisionPlayerIndex := COLLISION_PLAYER_INDEX_PREFIX + joinIndex
playerCollider := pR.CollisionSysMap[collisionPlayerIndex]
if collision := playerCollider.Check(dx, dy, "Barrier"); collision != nil {
changeWithCollision := collision.ContactWithObject(collision.Objects[0])
dx = changeWithCollision.X()
@ -1100,16 +1111,17 @@ func (pR *Room) applyInputFrameDownsyncDynamics(fromRenderFrameId int32, toRende
playerCollider.Y += dy
// Update in "collision space"
playerCollider.Update()
*/
player.Dir.Dx = decodedInput[0]
player.Dir.Dy = decodedInput[1]
player.X = playerCollider.X
player.Y = playerCollider.Y
player.X += dx
player.Y += dy
}
}
newRenderFrame := pb.RoomDownsyncFrame{
Id: collisionSysRenderFrameId+1,
Id: collisionSysRenderFrameId + 1,
RefFrameId: collisionSysRenderFrameId,
Players: toPbPlayers(pR.Players),
SentAt: utils.UnixtimeMilli(),
@ -1147,10 +1159,10 @@ func (pR *Room) refreshColliders() {
if i == j {
continue
}
if math.Abs(pj.X - pi.X) > w {
if math.Abs(pj.X-pi.X) > w {
w = math.Abs(pj.X - pi.X)
}
if math.Abs(pj.Y - pi.Y) > h {
if math.Abs(pj.Y-pi.Y) > h {
h = math.Abs(pj.Y - pi.Y)
}
}

View File

@ -122,7 +122,7 @@ func InitRoomHeapManager() {
LastAllConfirmedInputFrameIdWithChange: -1,
LastAllConfirmedInputList: make([]uint64, roomCapacity),
InputDelayFrames: 4,
NstDelayFrames: 2,
NstDelayFrames: 8,
InputScaleFrames: 2,
JoinIndexBooleanArr: joinIndexBooleanArr,
RollbackEstimatedDt: float64(1.0) / 60,

View File

@ -124,6 +124,10 @@ cc.Class({
type: cc.Float,
default: 1.0/60
},
perFrameDtMaxTolerance: {
type: cc.Float,
default: 1.0/600
},
maxChasingRenderFramesPerUpdate: {
type: cc.Integer,
default: 10
@ -787,7 +791,12 @@ cc.Class({
update(dt) {
const self = this;
if (ALL_BATTLE_STATES.IN_BATTLE == self.battleState) {
if (dt < self.rollbackEstimatedDt-self.perFrameDtMaxTolerance) {
console.warn("Avoiding too fast frame@renderFrameId=", self.renderFrameId, ": dt=", dt);
return;
}
try {
let st = performance.now();
let prevSelfInput = null, currSelfInput = null;
const noDelayInputFrameId = self._convertToInputFrameId(self.renderFrameId, 0); // It's important that "inputDelayFrames == 0" here
if (self.shouldGenerateInputFrameUpsync(self.renderFrameId)) {
@ -813,14 +822,8 @@ cc.Class({
// Inside "self.rollbackAndChase", the "self.latestCollisionSys" is ALWAYS ROLLED BACK to "self.recentRenderCache.get(self.renderFrameId)" before being applied dynamics from corresponding inputFrameDownsync, REGARDLESS OF whether or not "self.chaserRenderFrameId == self.renderFrameId" now.
const rdf = self.rollbackAndChase(self.renderFrameId, self.renderFrameId+1, self.latestCollisionSys, self.latestCollisionSysMap);
self.applyRoomDownsyncFrameDynamics(rdf);
let t3 = performance.now();
/*
if (prevChaserRenderFrameId < nextChaserRenderFrameId) {
console.log("Took ", t1-t0, " milliseconds to send upsync cmds, ", t2-t1, " milliseconds to chase renderFrameIds=[", prevChaserRenderFrameId, ", ", nextChaserRenderFrameId, "], @renderFrameId=", self.renderFrameId);
}
*/
} catch (err) {
console.error("Error during Map.update", err);
} finally {