[Oxyd] [0.17.2] [Linux] non-blocking-saving isn't non-blocking any more

[quyxkh]

Nonblocking autosaving's on in the config and the log says it's doing non-blocking saving, but the UI and sim freeze while the save's in progress, and the game's eating keystrokes again.

logfile

Code: Select all

   0.000 2019-02-27 19:08:25; Factorio 0.17.2 (build 43076, linux64, alpha)
   0.041 Operating system: Linux (Arch rolling)
   0.041 Program arguments: "/home/quyxkh/.factorio/bin/x64/factorio" "--load-game" "/home/quyxkh/.factorio/saves/_autosave1.zip" "-c" "/home/quyxkh/.factorio/config/config.ini" 
   0.041 Read data path: /home/quyxkh/libexec/factorio/data
   0.041 Write data path: /home/quyxkh/.factorio [553501/1462487MB]
   0.041 Binaries path: /home/quyxkh/libexec/factorio/bin
   0.046 System info: [CPU:        Intel(R) Core(TM) i5-3570K CPU @ 3.40GHz, 4 cores, RAM: 16023 MB]
   0.047 Environment: DISPLAY=:0, WAYLAND_DISPLAY=<unset>
   0.047 Display options: [FullScreen: 1] [VSync: 1] [UIScale: custom (100.0%)] [MultiSampling: OFF] [Screen: 255] [Lang: en]
   0.426 Available displays: 1
   0.426  [0]: VA2265 SERIES 22" - {[0,0], 1920x1080, SDL_PIXELFORMAT_RGB888, 60Hz}
   0.514 Initialised OpenGL:[0] GeForce GTX 1060 3GB/PCIe/SSE2; driver: 3.3.0 NVIDIA 415.27
   0.514   [Extensions] s3tc:yes; KHR_debug:yes; ARB_clear_texture:yes, ARB_copy_image:yes
   0.514   [Version] 3.3
   0.913 Graphics settings preset: very-high
   0.913   Dedicated video memory size 3072 MB
   0.913 Graphics options: [Graphics quality: high] [Video memory usage: all] [Light scale: 25%] [DXT: none]
   0.913                   [Max load threads: 32] [Max texture size: 0] [Tex.Stream.: 0] [Low quality rotation: 0]
   1.110 Loading mod settings BenchmarkProduction 0.0.10 (settings.lua)
   1.124 Loading mod settings Camera 0.0.1 (settings.lua)
   1.131 Loading mod settings ItemGrouping 0.1.3 (settings.lua)
   1.158 Loading mod core 0.0.0 (data.lua)
   1.219 Loading mod base 0.17.2 (data.lua)
   1.387 Loading mod BenchmarkProduction 0.0.10 (data.lua)
   1.466 Loading mod Camera 0.0.1 (data.lua)
   1.538 Loading mod ItemGrouping 0.1.3 (data.lua)
   1.618 Loading mod base 0.17.2 (data-updates.lua)
   1.718 Checksum for core: 3928040144
   1.718 Checksum of base: 1471520011
   1.718 Checksum of BenchmarkProduction: 2484338777
   1.718 Checksum of Camera: 3191012231
   1.718 Checksum of ItemGrouping: 3637771529
   2.130 Loading sounds...
   2.147 Info PlayerData.cpp:67: Local player-data.json available, timestamp 1551323133
   2.147 Info PlayerData.cpp:74: Cloud player-data.json unavailable
   2.267 Initial atlas bitmap size is 16384
   2.290 Created atlas bitmap 16384x16377 [not-compressed]
   2.294 Created atlas bitmap 16384x10903 [not-compressed]
   2.294 Created atlas bitmap 16384x2107 [decal, not-compressed]
   2.294 Created atlas bitmap 16384x3808 [low-object, not-compressed]
   2.295 Created atlas bitmap 16384x2204 [not-compressed, mipmap, linear-minification, linear-magnification, linear-mip-level, no-crop, no-scale]
   2.296 Created atlas bitmap 16384x6592 [terrain, not-compressed, mipmap, linear-minification, linear-mip-level, no-crop]
   2.296 Created atlas bitmap 16384x476 [smoke, not-compressed, mipmap, linear-minification, linear-magnification]
   2.296 Created atlas bitmap 16384x748 [alpha-mask]
   2.298 Created atlas bitmap 16384x12644 [shadow, linear-magnification, alpha-mask]
   2.298 Created atlas bitmap 16384x1264 [shadow, mipmap, linear-magnification, alpha-mask]
   4.309 Atlases loaded from disk cache.
   4.312 Parallel Sprite Loader initialized (threads: 0)
   4.350 Sprites loaded
   4.425 Generated mipmaps for atlas of size 16384x3808
   4.463 Generated mipmaps for atlas of size 16384x2204
   4.559 Generated mipmaps for atlas of size 16384x6592
   4.575 Generated mipmaps for atlas of size 16384x476
   4.582 Generated mipmaps for atlas of size 16384x1264
   4.588 Custom inputs active: 29
   4.653 Factorio initialised
   4.653 Loading map /home/quyxkh/.factorio/saves/_autosave1.zip: 43832163 bytes.
   4.667 Loading Level.dat: 80530274 bytes.
   4.674 Info Scenario.cpp:147: Map version 0.17.2-4
   6.460 Loading script.dat: 3104 bytes.
   6.462 Checksum for script /home/quyxkh/.factorio/temp/currently-playing/control.lua: 2366710471
   6.464 Checksum for script __BenchmarkProduction__/control.lua: 3178165421
   6.465 Checksum for script __Camera__/control.lua: 3020293925
   6.466 Checksum for script __ItemGrouping__/control.lua: 3787529194
 443.180 Info AppManager.cpp:246: Saving to _autosave2 (non-blocking).
 443.397 Info AsyncScenarioSaver.cpp:144: Saving process PID: 6906
 447.634 Info AppManager.cpp:247: Saving finished
 747.621 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
 747.812 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7108
 752.020 Info AppManager.cpp:247: Saving finished
1052.005 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
1052.218 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7158
1056.483 Info AppManager.cpp:247: Saving finished
1356.492 Info AppManager.cpp:246: Saving to _autosave2 (non-blocking).
1356.705 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7304
1360.976 Info AppManager.cpp:247: Saving finished
1660.964 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
1661.169 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7347
1665.330 Info AppManager.cpp:247: Saving finished
1965.321 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
1965.524 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7402
1969.702 Info AppManager.cpp:247: Saving finished
2298.108 Info AppManager.cpp:246: Saving to _autosave2 (non-blocking).
2298.322 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7484
2302.491 Info AppManager.cpp:247: Saving finished
2602.471 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
2602.679 Info AsyncScenarioSaver.cpp:144: Saving process PID: 7895
2606.829 Info AppManager.cpp:247: Saving finished
2906.833 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
2907.026 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8086
2911.216 Info AppManager.cpp:247: Saving finished
3211.204 Info AppManager.cpp:246: Saving to _autosave2 (non-blocking).
3211.436 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8190
3215.921 Info AppManager.cpp:247: Saving finished
3515.926 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
3516.154 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8312
3520.609 Info AppManager.cpp:247: Saving finished
3820.588 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
3820.804 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8523
3825.280 Info AppManager.cpp:247: Saving finished
4125.271 Info AppManager.cpp:246: Saving to _autosave2 (non-blocking).
4125.478 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8570
4129.902 Info AppManager.cpp:247: Saving finished
4429.873 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
4430.097 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8653
4434.623 Info AppManager.cpp:247: Saving finished
4735.645 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
4735.877 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8778
4740.379 Info AppManager.cpp:247: Saving finished
4994.571 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
4994.773 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8838
4999.281 Info AppManager.cpp:247: Saving finished
5119.254 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
5119.484 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8854
5124.017 Info AppManager.cpp:247: Saving finished
5244.004 Info AppManager.cpp:246: Saving to _autosave2 (non-blocking).
5244.241 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8872
5248.869 Info AppManager.cpp:247: Saving finished
5368.854 Info AppManager.cpp:246: Saving to _autosave3 (non-blocking).
5369.088 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8895
5373.604 Info AppManager.cpp:247: Saving finished
5493.589 Info AppManager.cpp:246: Saving to _autosave1 (non-blocking).
5493.824 Info AsyncScenarioSaver.cpp:144: Saving process PID: 8928
5498.372 Info AppManager.cpp:247: Saving finished

[Syhn]

Does it say the server is not responding while saving? This may be what I am encountering, but wasn's sure if it was something wrong with my hardware.

[quyxkh]

I'm doing this singleplayer, but if they introduced an unexpected lock around the saving it wouldn't be surprising if the server stopped responding for the duration too.

[Syhn]

Ah, I see. Yeah, I'm seeing the server halt for the duration of the save which causes the client to see the server "dropping."

[klugemonkey]

017.23, I'm still getting 'Server not responding' message to all users when autosave occurs in non-blocking mode. It is so ridiculous, I've had all players get the watchdog dialog to exit or reconnect.

The performance of saving in general is much worse than 16.51. Anytime a player joins the delay for all other players is a significant interruption on the order of 3-10 seconds. It was annoying on 16.51 unless non-blocking saves were used and a ramdisk was utilized to minimize saves for the players joining, but now on 17.23, autosaves are blocking.

Not sure if ramdisk will improve on 17.23, but will test further to see if the issue is disk I/O or a synchronization issue.

Using linux as well.

Seems to be happening in AsyncScenarioSaver.cpp:144

[SNACKaJACK]

Is there any news on this issue? I'm encountering the same problems right now while setting up a server for 0.17.25. I would love for this feature to work again, I think it's an awesome quality of life improvement for multiplayer. Being interrupted every time someone joins or an auto-save is made gets frustrating really fast

[enoh]

Hey,

Same issue on 0.17.28.

[pickscrape]

This appears to still be happening in 0.17.36.

Anyone know if the devs are aware of this or not, and if so, is it being worked on?

[pickscrape]

I just did a little digging into the release notes, based on this thread initially referencing 0.17.2. In that release, we have this entry:

"Fixed a crash when trying to use async-saving when hosting multiplayer games on Windows" (which links to this thread: 65146)

I wonder if the fix inadvertently made linux also fall back to blocking saves, even when non-blocking saves are enabled (and show as such in the log)?

[Oxyd]

Sorry about the delay. Fixed in 0.17.48.