[0.15.9] Very long catching up and mini-freezes

[Fank]

After updating to 0.15.6 -> 0.15.9 we noticed long "catching up" and it looks like there are some CRC failures ("mini"-freezes with recover), but no desyncs.

Logs does not show something usefull.

Code: Select all

   0.000 2017-05-07 17:54:54; Factorio 0.15.9 (build 29504, linux64, headless)
   0.000 Operating system: Linux
   0.000 Not rotating logs.
   0.000 Program arguments: "/opt/factorio/bin/x64/factorio" "--port" "34197" "--start-server-load-latest" "--server-settings" "/factorio/config/server-settings.json" "--server-whitelist" "/factorio/config/server-whitelist.json" "--rcon-port" "27015" "--rcon-password" "Va3ge2aixiShiew" 
   0.000 Read data path: /opt/factorio/data
   0.000 Write data path: /opt/factorio
   0.000 Binaries path: /opt/factorio/bin
   0.006 System info: [CPU: Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz, 8 cores, RAM: 64224MB]
   0.007 Running in headless mode
   0.011 Loading mod core 0.0.0 (data.lua)
   0.015 Loading mod base 0.15.9 (data.lua)
   0.078 Loading mod base 0.15.9 (data-updates.lua)
   0.123 Checksum for core: 3409166051
   0.123 Checksum of base: 3769930138
   0.202 Info PlayerData.cpp:57: Local player-data.json unavailable
   0.202 Info PlayerData.cpp:62: Cloud player-data.json unavailable
   0.202 Custom inputs active: 0
   0.203 Factorio initialised
   0.204 Info ServerSynchronizer.cpp:27: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
   0.204 Info ServerMultiplayerManager.cpp:663: mapTick(-1) changing state from(Ready) to(PreparedToHostGame)
   0.204 Info ServerMultiplayerManager.cpp:663: mapTick(-1) changing state from(PreparedToHostGame) to(CreatingGame)
   0.204 Loading map /opt/factorio/saves/_autosave18.zip: 22121937 bytes.
   0.204 Error FileUtil.cpp:291: Can't remove /opt/factorio/temp/currently-playing: No such file or directory
   0.212 Loading Level.dat: 55514219 bytes.
   0.217 Info Scenario.cpp:133: Map version 0.15.9-0
   1.313 Loading script.dat: 190 bytes.
   1.314 Checksum for script /opt/factorio/temp/currently-playing/control.lua: 76911248
   1.381 Info UDPSocket.cpp:27: Opening socket at (0.0.0.0:34197)
   1.381 Hosting game at 0.0.0.0:34197
   1.381 Info ServerMultiplayerManager.cpp:663: mapTick(32271659) changing state from(CreatingGame) to(InGame)
   1.381 Info ServerRouter.cpp:581: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197) for own address
   1.387 Info UDPSocket.cpp:39: Opening socket for broadcast
   1.408 Error InterruptibleStdioStream.cpp:53: Reading stdin failed
   1.408 Info RemoteCommandProcessor.cpp:122: Starting RCON interface at port 27015
   2.438 Info ServerRouter.cpp:474: Own address is 88.99.195.101:4387
   2.455 Error ServerMultiplayerManager.cpp:597: Matching server connection failed: Error when creating server game: Missing token.
  10.505 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(84.169.156.182:35882)
  10.505 Info ServerRouter.cpp:389: Replying to connectionRequest for address(84.169.156.182:35882).
  10.508 Info ServerSynchronizer.cpp:542: nextHeartbeatSequenceNumber(274) adding peer(1)
  10.525 Info ServerMultiplayerManager.cpp:663: mapTick(32272204) changing state from(InGame) to(InGameSavingMap)
  10.575 Info ServerMultiplayerManager.cpp:747: mapTick(32272204) received stateChanged peerID(1) oldState(Ready) newState(ConnectedWaitingForMap)
  11.481 Info ServerMultiplayerManager.cpp:801: MapTick(32272204) Serving map(/opt/factorio/temp/mp-save-0.zip) for peer(1) size(22139660) crc(806717408)
  11.481 Info ServerMultiplayerManager.cpp:663: mapTick(32272204) changing state from(InGameSavingMap) to(InGame)
  11.572 Info ServerMultiplayerManager.cpp:747: mapTick(32272210) received stateChanged peerID(1) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  15.963 Info ServerMultiplayerManager.cpp:747: mapTick(32272475) received stateChanged peerID(1) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
  17.291 Info ServerMultiplayerManager.cpp:747: mapTick(32272554) received stateChanged peerID(1) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
  25.029 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(217.227.234.83:57905)
  25.029 Info ServerRouter.cpp:389: Replying to connectionRequest for address(217.227.234.83:57905).
  25.029 Info ServerSynchronizer.cpp:542: nextHeartbeatSequenceNumber(708) adding peer(2)
  25.046 Info ServerMultiplayerManager.cpp:663: mapTick(32273019) changing state from(InGame) to(InGameSavingMap)
  25.096 Info ServerMultiplayerManager.cpp:747: mapTick(32273019) received stateChanged peerID(2) oldState(Ready) newState(ConnectedWaitingForMap)
  26.019 Info ServerMultiplayerManager.cpp:801: MapTick(32273019) Serving map(/opt/factorio/temp/mp-save-1.zip) for peer(2) size(22141894) crc(2157559668)
  26.019 Info ServerMultiplayerManager.cpp:663: mapTick(32273019) changing state from(InGameSavingMap) to(InGame)
  26.115 Info ServerMultiplayerManager.cpp:747: mapTick(32273025) received stateChanged peerID(2) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  54.607 Info ServerMultiplayerManager.cpp:747: mapTick(32274708) received stateChanged peerID(2) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
  56.460 Info ServerMultiplayerManager.cpp:747: mapTick(32274817) received stateChanged peerID(2) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
  65.430 Info ServerMultiplayerManager.cpp:747: mapTick(32275341) received stateChanged peerID(1) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
  65.431 Info GameActionHandler.cpp:3243: MapTick (32275341) processed PlayerJoinGame peerID(1) playerIndex(0) mode(connect ) 
  65.518 Info ServerMultiplayerManager.cpp:747: mapTick(32275346) received stateChanged peerID(1) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
2017-05-07 17:55:59 [JOIN] Fank joined the game
  72.583 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(95.90.248.79:1042)
  72.583 Info ServerRouter.cpp:389: Replying to connectionRequest for address(95.90.248.79:1042).
  72.583 Info ServerSynchronizer.cpp:542: nextHeartbeatSequenceNumber(2108) adding peer(3)
  72.600 Info ServerMultiplayerManager.cpp:663: mapTick(32275764) changing state from(InGame) to(InGameSavingMap)
  72.667 Info ServerMultiplayerManager.cpp:747: mapTick(32275764) received stateChanged peerID(3) oldState(Ready) newState(ConnectedWaitingForMap)
  73.574 Info ServerMultiplayerManager.cpp:801: MapTick(32275764) Serving map(/opt/factorio/temp/mp-save-2.zip) for peer(3) size(22261984) crc(1966930152)
  73.574 Info ServerMultiplayerManager.cpp:663: mapTick(32275764) changing state from(InGameSavingMap) to(InGame)
  74.003 Info ServerMultiplayerManager.cpp:747: mapTick(32275789) received stateChanged peerID(3) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  82.419 Info ServerMultiplayerManager.cpp:747: mapTick(32276277) received stateChanged peerID(3) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
  83.973 Info ServerMultiplayerManager.cpp:747: mapTick(32276366) received stateChanged peerID(3) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 207.655 Info ServerMultiplayerManager.cpp:747: mapTick(32283654) received stateChanged peerID(3) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 207.655 Info GameActionHandler.cpp:3243: MapTick (32283654) processed PlayerJoinGame peerID(3) playerIndex(2) mode(connect ) 
 207.840 Info ServerMultiplayerManager.cpp:747: mapTick(32283665) received stateChanged peerID(3) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
2017-05-07 17:58:22 [JOIN] BusyBeever joined the game
 223.167 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(31.16.88.93:34935)
 223.167 Info ServerRouter.cpp:389: Replying to connectionRequest for address(31.16.88.93:34935).
 223.167 Info ServerSynchronizer.cpp:542: nextHeartbeatSequenceNumber(6551) adding peer(4)
 223.184 Info ServerMultiplayerManager.cpp:663: mapTick(32284585) changing state from(InGame) to(InGameSavingMap)
 223.234 Info ServerMultiplayerManager.cpp:747: mapTick(32284585) received stateChanged peerID(4) oldState(Ready) newState(ConnectedWaitingForMap)
 224.229 Info ServerMultiplayerManager.cpp:801: MapTick(32284585) Serving map(/opt/factorio/temp/mp-save-3.zip) for peer(4) size(23998930) crc(3173148722)
 224.229 Info ServerMultiplayerManager.cpp:663: mapTick(32284585) changing state from(InGameSavingMap) to(InGame)
 224.324 Info ServerMultiplayerManager.cpp:747: mapTick(32284591) received stateChanged peerID(4) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
 266.593 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(217.247.162.168:56826)
 266.593 Info ServerRouter.cpp:389: Replying to connectionRequest for address(217.247.162.168:56826).
 266.593 Info ServerSynchronizer.cpp:542: nextHeartbeatSequenceNumber(7803) adding peer(5)
 266.611 Info ServerMultiplayerManager.cpp:663: mapTick(32287029) changing state from(InGame) to(InGameSavingMap)
 266.662 Info ServerMultiplayerManager.cpp:747: mapTick(32287029) received stateChanged peerID(5) oldState(Ready) newState(ConnectedWaitingForMap)
 267.587 Info ServerMultiplayerManager.cpp:801: MapTick(32287029) Serving map(/opt/factorio/temp/mp-save-4.zip) for peer(5) size(22585807) crc(2790889805)
 267.587 Info ServerMultiplayerManager.cpp:663: mapTick(32287029) changing state from(InGameSavingMap) to(InGame)
 267.669 Info ServerMultiplayerManager.cpp:747: mapTick(32287034) received stateChanged peerID(5) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
 270.344 Info ServerMultiplayerManager.cpp:747: mapTick(32287184) received stateChanged peerID(4) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 271.842 Info ServerMultiplayerManager.cpp:747: mapTick(32287267) received stateChanged peerID(4) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 278.265 Info ServerMultiplayerManager.cpp:747: mapTick(32287627) received stateChanged peerID(5) oldState(ConnectedDownloadingMap) newState(ConnectedLoadingMap)
 279.595 Info ServerMultiplayerManager.cpp:747: mapTick(32287702) received stateChanged peerID(5) oldState(ConnectedLoadingMap) newState(TryingToCatchUp)
 310.016 Info ServerMultiplayerManager.cpp:747: mapTick(32289456) received stateChanged peerID(5) oldState(TryingToCatchUp) newState(WaitingForCommandToStartSendingTickClosures)
 310.016 Info GameActionHandler.cpp:3243: MapTick (32289456) processed PlayerJoinGame peerID(5) playerIndex(4) mode(connect ) 
 310.120 Info ServerMultiplayerManager.cpp:747: mapTick(32289462) received stateChanged peerID(5) oldState(WaitingForCommandToStartSendingTickClosures) newState(InGame)
2017-05-07 18:00:04 [JOIN] XIII joined the game

[Loewchen]

The catch-up-phase is as long as the client takes to simulate what he missed while downloading the map, if a client is as slow simulating the game as the server is he can try to catch up indefinitely.
How did you determine that there are CRC failures?

[Fank]

Before the update we had a catch up time about 5-10 sec. after the update the catch up time is about 1-5min. And the catch up "bar" moves back and forward. e.g. 50% -> 60% -> 55% -> 65% -> 70% -> 65% -> 60% ...
The CRC failures like if you watch e.g. belts, you will noticed they will stop shortly, will catch up and work again. Same is notice able with robots train and everything that moves (play animation).
Some testings:
- Try to run the savegame in singleplayer works fine.
- Try to run the savegame in multiplayer, causes the problem. (And i also have huge fps drops (avg 20fps), but its only me, all other guys have being dropped from the game or other issues)

[Fank]

Maybe not related but here a debug screenshot of my fps issues.

[Loewchen]

(...)the catch up "bar" moves back and forward. e.g. 50% -> 60% -> 55% -> 65% -> 70% -> 65% -> 60% ...

This is what you will see when the client can not simulate faster/as fast as the server.

The CRC failures like if you watch e.g. belts, you will noticed they will stop shortly, will catch up and work again. Same is notice able with robots train and everything that moves (play animation).

Those are jumps, the client skips updates and only simulates them in the background if he can not keep up with the server. You will see very low FPS (about 5) when this is happening.
See the Performance Issue section in the Technical Help FAQ on how to keep slower clients on board. NaB.

[Fank]

I've tried the fast fix "/c game.forces["enemy"].kill_all_units()" and my fps issues are done and the catching up issue is much faster than before, thanks for that.
A temp solution for faster catching up is pausing the game
But we still have some clients (with a good hardware) which still get a "is beeing dropped from the game", it looks like as you describe they simulate slower than the server, tested with pause and unpause game and watch the bar moving.

[Fank]

Ah nvm it looks like he has ISP issues.