Page 1 of 1

[Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Wed May 25, 2016 11:34 pm
by malk0lm
We enter a desync loop once the CPU hits 100%, on future connections even if the CPU is <100% it still desyncs.

Code: Select all

161372.992 Error NetworkInputHandler.cpp:360: Multiplayer desynchronisation: crc test(CheckCRCHeuristic) failed for mapTick(43347000) peer(7) testCrc(-237165950) testCrcPeerID(0) currentCrc(2090073090)
161372.993 Info NetworkInputHandler.cpp:402: Desync specification: Reference CRC = 4057801346, reference peers = {0}; desynced CRC = 2090073090, desynced peer = 7 (malk0lm)
161373.409 Info MultiplayerManager.cpp:1060: networkTick(9664556) mapTick(43347028) received stateChanged peerID(7) oldState(InGame) newState(Desynced)
161373.410 Info MultiplayerManager.cpp:913: networkTick(9664556) mapTick(43347028) changing state from(InGame) to(InGameAligning)
161373.411 Info MultiplayerManager.cpp:1719: networkTick(9664556) mapTick(43347028) starting mapAlign
161373.623 Info MultiplayerManager.cpp:1060: networkTick(9664568) mapTick(43347028) received stateChanged peerID(0) oldState(InGame) newState(InGameAligning)
161373.624 Info MultiplayerManager.cpp:1060: networkTick(9664568) mapTick(43347028) received stateChanged peerID(7) oldState(Desynced) newState(DesyncedAligning)
161373.624 Info MultiplayerManager.cpp:1653: networkTick(9664568) mapTick(43347028) sending mapAlignAction
161373.823 Info MultiplayerManager.cpp:1307: networkTick(9664580) mapTick(43347028) received MapAlignAction from peer(0), mapAlignTick(43347029) appliedTickClosuresCount(0)
161373.824 Info MultiplayerManager.cpp:1307: networkTick(9664580) mapTick(43347028) received MapAlignAction from peer(7), mapAlignTick(43347016) appliedTickClosuresCount(42)
161373.824 Info MultiplayerManager.cpp:1735: networkTick(9664581) mapTick(43347028) mapAlign finished targetTick(43347029) updating map and running the tasks ...
161373.824 Info MultiplayerManager.cpp:1607: networkTick(9664581) mapTick(43347028) peerID(0) fullStateLog: local state(InGameAligning) local peers(((peerID(0) state(InGameAligning) mapAlignTick(43347029))
((peerID(7) state(DesyncedAligning) mapAlignTick(43347016))
)
161373.852 Info MultiplayerManager.cpp:1754: maptick(43347029) crc before applying all ticks: 1644269338
161373.852 Info NetworkInputHandler.cpp:661: applyAllTickClosures: expectedMapTick(43347029) lastTickApplied(43347014) referenceMapTick(43347029) networkTick(9664581)
161373.853 Info MultiplayerManager.cpp:1762: maptick(43347029) crc after applying all ticks: 1644269338
161373.853 Info MultiplayerManager.cpp:913: networkTick(9664581) mapTick(43347029) changing state from(InGameAligning) to(InGameAligned)
161374.240 Info MultiplayerManager.cpp:1060: networkTick(9664593) mapTick(43347029) received stateChanged peerID(0) oldState(InGameAligning) newState(InGameAligned)
161374.241 Info MultiplayerManager.cpp:1060: networkTick(9664593) mapTick(43347029) received stateChanged peerID(7) oldState(DesyncedAligning) newState(DesyncedAligned)
161374.440 Info MultiplayerManager.cpp:1324: networkTick(9664605) mapTick(43347029) received playerReconnect
161374.441 Info MultiplayerManager.cpp:2121: NetworkTick(9664605) MapTick(43347029) disconnecting player(0) from the user.
161374.443 Info NetworkInputHandler.cpp:544: expectedMapTick(43347029) removing peer(7) success(true).
161374.443 Info NetworkInputHandler.cpp:520: expectedMapTick(43347029) adding peer(7).
161374.443 Info MultiplayerManager.cpp:1060: networkTick(9664605) mapTick(43347029) received stateChanged peerID(7) oldState(DesyncedAligned) newState(DesyncedCreatingReport)
161386.489 Info Synchronizer.cpp:444: NetworkTick(9665248) peer(7) drop detection state(100/900).
161388.156 Info Synchronizer.cpp:444: NetworkTick(9665248) peer(7) drop detection state(200/900).
161389.207 Info MultiplayerManager.cpp:1060: networkTick(9665248) mapTick(43347029) received stateChanged peerID(7) oldState(DesyncedCreatingReport) newState(DesyncedWaitingForMap)
161389.212 Info MultiplayerManager.cpp:913: networkTick(9665248) mapTick(43347029) changing state from(InGameAligned) to(InGameSavingMap)
161389.406 Info MultiplayerManager.cpp:1060: networkTick(9665260) mapTick(43347029) received stateChanged peerID(0) oldState(InGameAligned) newState(InGameSavingMap)
161426.190 Info MultiplayerManager.cpp:913: networkTick(9667468) mapTick(43347029) changing state from(InGameSavingMap) to(InGameSendingMap)
161426.313 Info MultiplayerManager.cpp:1177: MapTick(43347029) Serving map(/srv/factorio/temp/mp-download.zip) for peer(7) size(21896450) crc(-1796873536)
161426.397 Info MultiplayerManager.cpp:1060: networkTick(9667480) mapTick(43347029) received stateChanged peerID(0) oldState(InGameSavingMap) newState(InGameSendingMap)
161426.605 Info MultiplayerManager.cpp:1060: networkTick(9667492) mapTick(43347029) received stateChanged peerID(7) oldState(DesyncedWaitingForMap) newState(DesyncedDownloadingMap)
161438.221 Info MultiplayerManager.cpp:1060: networkTick(9668172) mapTick(43347029) received stateChanged peerID(7) oldState(DesyncedDownloadingMap) newState(DesyncedLoadingMap)
161438.222 Canceling serving for peer 7
161438.227 Info MultiplayerManager.cpp:913: networkTick(9668172) mapTick(43347029) changing state from(InGameSendingMap) to(InGameWaitingForOthers)
161438.421 Info MultiplayerManager.cpp:1060: networkTick(9668184) mapTick(43347029) received stateChanged peerID(0) oldState(InGameSendingMap) newState(InGameWaitingForOthers)
161450.204 Info MultiplayerManager.cpp:1060: networkTick(9668891) mapTick(43347029) received stateChanged peerID(7) oldState(DesyncedLoadingMap) newState(InGameWaitingForOthers)
161450.212 Info MultiplayerManager.cpp:1259: networkTick(9668891) mapTick(43347029) stopping mapAlign
161450.212 Info MultiplayerManager.cpp:913: networkTick(9668891) mapTick(43347029) changing state from(InGameWaitingForOthers) to(InGame)
161450.213 Info MultiplayerManager.cpp:1607: networkTick(9668891) mapTick(43347029) peerID(0) fullStateLog: local state(InGame) local peers(((peerID(0) state(InGameWaitingForOthers) mapAlignTick(-1))
((peerID(7) state(InGameWaitingForOthers) mapAlignTick(-1))
)
161450.443 Info MultiplayerManager.cpp:1060: networkTick(9668903) mapTick(43347030) received stateChanged peerID(0) oldState(InGameWaitingForOthers) newState(InGame)
161450.443 Info MultiplayerManager.cpp:1060: networkTick(9668903) mapTick(43347030) received stateChanged peerID(7) oldState(InGameWaitingForOthers) newState(InGame)
161451.056 Info NetworkInputHandler.cpp:599: assigning playerIndex(0) to peer(7)
161451.057 Info GameActionHandler.cpp:1949: MapTick(43347044) processed PlayerJoinGame peerID(7) playerIndex(0) mode(connect)
161453.487 Error NetworkInputHandler.cpp:360: Multiplayer desynchronisation: crc test(CheckCRCHeuristic) failed for mapTick(43347120) peer(7) testCrc(18953913) testCrcPeerID(0) currentCrc(-579860020)
161453.488 Info NetworkInputHandler.cpp:402: Desync specification: Reference CRC = 18953913, reference peers = {0}; desynced CRC = 3715107276, desynced peer = 7 (malk0lm)

Re: 12.33 Desyncing due to 100% CPU spike

Posted: Thu May 26, 2016 9:03 am
by Loewchen
I would not give much thought to the CPU utilization. Please upload mod-list and the desync-report from the desynced peer.

Greetings Loewchen

Re: [Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Tue Jun 07, 2016 11:42 am
by Klonan
Thanks for the report,

Can you provide a save game, mods and any steps to reproduce the issue?
Does it still desync without mods?

Re: [Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Tue Jun 07, 2016 5:53 pm
by malk0lm
With no mods the CPU never reaches 100%

We have a savegame which uses about two dozen belts in a bus, and no one can connect. We think the rendering thread is utilizing 100% cpu which leads to the netcode not being able to keep up with the peer traffic. We updated the savegame to use underground belts and now we can connect.

Mod list is here: https://aerodo.me/

Re: [Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Wed Jun 08, 2016 7:37 am
by Rseding91
If the hardware can't process the game fast enough then it's not going to work - it's as simple as that. Who ever is hitting 100% CPU usage and lagging behind the rest needs to get better hardware to keep playing with the rest - that's not something we can fix.

Re: [Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Wed Jun 08, 2016 8:07 am
by sillyfly
Rseding91 wrote:If the hardware can't process the game fast enough then it's not going to work - it's as simple as that. Who ever is hitting 100% CPU usage and lagging behind the rest needs to get better hardware to keep playing with the rest - that's not something we can fix.
Err... isn't a more elegant behavior to have the others wait for the slowest peer? I thought that was what the game is already doing to account for network latency etc.

Re: [Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Wed Jun 08, 2016 9:03 am
by Loewchen
sillyfly wrote:
Rseding91 wrote:If the hardware can't process the game fast enough then it's not going to work - it's as simple as that. Who ever is hitting 100% CPU usage and lagging behind the rest needs to get better hardware to keep playing with the rest - that's not something we can fix.
Err... isn't a more elegant behaviour to have the others wait for the slowest peer? I thought that was what the game is already doing to account for network latency etc.
Not only that, we had games running at a fraction of the normal speed because of one peer having slow hardware, this works without error until the drop detection kicks in, but It is unplayable way before that and certainly does not cause desyncs.

Re: [Pending] 12.33 Desyncing due to 100% CPU spike

Posted: Wed Jun 08, 2016 4:08 pm
by malk0lm
Rseding91 wrote:If the hardware can't process the game fast enough then it's not going to work - it's as simple as that. Who ever is hitting 100% CPU usage and lagging behind the rest needs to get better hardware to keep playing with the rest - that's not something we can fix.
It's not a peer issue. You can desync from the headless server even when it is only you connected to the server. It's a 2.3Ghz Xenon E5-2630.