search

MovingBlocks / Terasology

Terasology - open source voxel world
http://terasology.org
Apache License 2.0
3.67k stars 1.34k forks source link

Performance issue when auto-save triggers in constrained memory situations #1929

Open Cervator opened 9 years ago

Cervator commented 9 years ago

We've had some reports lately about performance issues when the auto-save runs and I think I've found more closely what makes it happen.

If you push the game to near the memory limit, by increasing the view distance and flying around loading chunks a lot, then while you may be low FPS due to the memory churn when auto-save kicks in it gets really bad

In my case I started from source in a Cities world and just flew around with ghost + hspeed. Was able to push to the 1 gb default limit pretty easily and keep the memory used hovering constantly near the max. I increased to 2 gb max instead and with ample space from current use to max limit the auto-save was barely noticeable again.

@flo you around with any time to take a look at some point convenient to you? Although I'm not really sure what the solution is, since saving is going to need some memory. During auto-save shave off some view distance dynamically to have enough memory if low?

Maybe related: http://forum.terasology.org/threads/delta-too-great.1374/

flo commented 9 years ago

I think we should increase the default memory maximum to 2 GB.

Cervator commented 9 years ago

That'll help in some causes (and hurt in others - like trying to run on 32-bit), but wouldn't we want to harden the process to degrade more gracefully under pressure? With the right settings you could still put the game under strain at 2 GB.

zertrin commented 8 years ago

I found this bug report after trying Terasology for the first time and experiencing similar issues at autosave times.

I had initially set min 768M and max 1G for the RAM. In the core mode I don't have too much problems, but in TTA2 the memory gets quickly up to the max and as soon as the auto-save kicks in, the FPS just collapse and the game gets pretty quickly unplayable (0.5 FPS or less). The problem is made worse by the fact that when one autosave eventually finishes (after as much as 1 minute), another one starts a few seconds/milliseconds after and there we go for another round of extremely degraded performance.

After setting the limit to 2GB, the game was mostly playable for about 5 minutes until it crashed. However the crash may be due to another issue. In case it helps, here are the links to the uploaded logs from the crash reporter: https://zerobin.zertrin.org/?18c5e7dbc0f24dba#R4FZpH1W8jJlkRFdQBQ0zavSTP+8c6M7IYaJjYRgpm8= (link valid one year)

Cervator commented 8 years ago

Thanks for the details @zertrin :-)

Snippet from the game-killing error:

orageManager - Saving - Snapshot created: Writing phase starts
23:12:42.878 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (3074), capping to 1000
23:12:55.013 [Saving-0] INFO  o.t.p.internal.SaveTransaction - Save game finished
23:12:55.016 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (3463), capping to 1000
23:13:38.293 [main] INFO  o.t.p.i.ReadWriteStorageManager - Saving - Creating game snapshot
23:13:38.295 [main] INFO  o.t.p.i.ReadWriteStorageManager - Saving - Snapshot created: Writing phase starts
23:13:42.914 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (3187), capping to 1000
23:13:51.470 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (3589), capping to 1000
23:13:55.537 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (3251), capping to 1000
23:13:58.155 [Saving-0] INFO  o.t.p.internal.SaveTransaction - Save game finished
23:14:02.197 [main] ERROR o.terasology.engine.TerasologyEngine - Uncaught exception, attempting clean game shutdown
java.lang.NullPointerException: null
    at org.terasology.logic.delay.DelayedActionSystem.invokeDelayedOperations(DelayedActionSystem.java:74) ~[engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.logic.delay.DelayedActionSystem.update(DelayedActionSystem.java:53) ~[engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.engine.modes.StateIngame.update(StateIngame.java:178) ~[engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:414) ~[engine-0.54.4.jar:61, origin/master, 61]
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:369) ~[engine-0.54.4.jar:61, origin/master, 61]
    at org.terasology.engine.Terasology.main(Terasology.java:154) [Terasology.jar:61, origin/master, 61]
23:14:02.198 [main] INFO  o.terasology.engine.TerasologyEngine - Shutting down Terasology...
23:14:02.761 [main] INFO  o.t.p.i.ReadWriteStorageManager - Saving - Creating game snapshot
23:14:02.765 [main] INFO  o.t.p.i.ReadWriteStorageManager - Saving - Snapshot created: Writing phase starts
23:14:02.767 [main] INFO  o.t.n.internal.NetworkSystemImpl - Client disconnected: Zertrin

Not a super informative error, but yeah it may be something other than the auto save. Three times earlier this error occurs, which looks familiar, but wasn't the same as https://github.com/Terasology/Cities/issues/28 as I thought at first. 

23:02:32.688 [main] INFO  o.t.r.world.RenderableWorldImpl - New Viewing Distance: Moderate
23:02:49.041 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (2164), capping to 1000
23:02:52.470 [main] ERROR o.t.e.event.internal.EventSystemImpl - Failed to invoke event
java.lang.NullPointerException: null
    at org.terasology.logic.players.LocalPlayerSystem.onTargetChanged(LocalPlayerSystem.java:243) ~[engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.logic.players.LocalPlayerSystemMethodAccess.invoke(Unknown Source) ~[reflectasm-1.11.0.jar:61, master, 61, pre-alpha]
    at org.terasology.entitySystem.event.internal.EventSystemImpl$ByteCodeEventHandlerInfo.invoke(EventSystemImpl.java:502) ~[engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.entitySystem.event.internal.EventSystemImpl.sendStandardEvent(EventSystemImpl.java:270) [engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.entitySystem.event.internal.EventSystemImpl.send(EventSystemImpl.java:261) [engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.entitySystem.entity.internal.BaseEntityRef.send(BaseEntityRef.java:144) [engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.input.cameraTarget.PlayerTargetSystem.update(PlayerTargetSystem.java:74) [engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.engine.modes.StateIngame.update(StateIngame.java:178) [engine-0.54.4.jar:61, master, 61, pre-alpha]
    at org.terasology.engine.TerasologyEngine.mainLoop(TerasologyEngine.java:414) [engine-0.54.4.jar:61, origin/master, 61]
    at org.terasology.engine.TerasologyEngine.run(TerasologyEngine.java:369) [engine-0.54.4.jar:61, origin/master, 61]
    at org.terasology.engine.Terasology.main(Terasology.java:154) [Terasology.jar:61, origin/master, 61]
23:02:56.656 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (2868), capping to 1000
23:03:07.434 [main] WARN  o.t.engine.internal.TimeBase - Delta too great (1120), capping to 1000

Maybe that's related to the lag? I'm not sure.

Hopefully we can dig deeper in this sometime, but we may need @flo to take a look. Or maybe @msteiger would have some clues.