Farms cause significant frame rate drops

[rezecib]

@Onirian It contains a timeline recording how long each part of the update took, with a hierarchical breakdown. It's.... technically human-readable, but very difficult to make any sense of without the GUI.

[Onirian]

Ok, I will see this and try to understand something ^^.

[Onirian]

So, the logs !

Here are two json logs. For the "far", I just go far from my base (fps 60), launch the command given by @rezecib, wait near 10 second and quit game. For the second, I do the same, but from the center of my base.

Because it's json, it's very hard to read it directly, so I wrote a little php program to extract some information from theses logs (I will maybe put it online later if anybody wants to do some tests).

The goal was to calculate for each function, how many time, in average (according to the fact the two logs are not during exactly the same among of time) are spend in each function.

If I do no mistake (for example, I do not take in account the fact lines appears two times with ph:B and ph:E, I estimated alls methods have the same behaviour and appears two times each times), here is the result :

For the log in the base :

Spoiler

[cEntityManager::CheckSleepers] - nbCall=338 - totalTime=1034349 - averageTime=3060.204
[CollectNodes] - nbCall=158 - totalTime=382202 - averageTime=2419
[Physics] - nbCall=156 - totalTime=306485 - averageTime=1964.647
[Normal] - nbCall=158 - totalTime=276581 - averageTime=1750.513
[mOnlyForAwakeEntities - Regular] - nbCall=312 - totalTime=474023 - averageTime=1519.304
[CacheRenderUI] - nbCall=158 - totalTime=96764 - averageTime=612.43
[Garbage Collection] - nbCall=156 - totalTime=76349 - averageTime=489.417
[CacheRenderDebugDraw] - nbCall=158 - totalTime=53913 - averageTime=341.222
[GroundCreep] - nbCall=182 - totalTime=44461 - averageTime=244.291
[Swap] - nbCall=158 - totalTime=32892 - averageTime=208.177
[update widgets] - nbCall=160 - totalTime=26264 - averageTime=164.15
[MiniMapComponent::CacheForRender] - nbCall=158 - totalTime=23614 - averageTime=149.456
[updating components] - nbCall=182 - totalTime=21715 - averageTime=119.313
[WORLD CHECK] - nbCall=112 - totalTime=10283 - averageTime=91.813
[CacheOrthoSceneGraph] - nbCall=158 - totalTime=14464 - averageTime=91.544
[DontStarveInputHandler::Update] - nbCall=182 - totalTime=15818 - averageTime=86.912
[DrawNodes] - nbCall=158 - totalTime=12461 - averageTime=78.867
[cNetworkReplicaManager::Update] - nbCall=258 - totalTime=18320 - averageTime=71.008
[AutoConstructByQuery] - nbCall=52 - totalTime=3642 - averageTime=70.038
[ReplicaManager3::Update::OnUserReplicaPreSerializeTick] - nbCall=52 - totalTime=3243 - averageTime=62.365
[EndFrame] - nbCall=158 - totalTime=9157 - averageTime=57.956
[MiniMapRender] - nbCall=158 - totalTime=8209 - averageTime=51.956
[Debug Render] - nbCall=158 - totalTime=8076 - averageTime=51.114
[metadata] - nbCall=2 - totalTime=100 - averageTime=50
[mSoundSystem] - nbCall=158 - totalTime=7875 - averageTime=49.842
[spawners] - nbCall=6 - totalTime=261 - averageTime=43.5
[TileUpdate] - nbCall=6 - totalTime=162 - averageTime=27
[WorldCleanup] - nbCall=158 - totalTime=3414 - averageTime=21.608
[CacheRender] - nbCall=158 - totalTime=2738 - averageTime=17.329
[PostProcess] - nbCall=158 - totalTime=2418 - averageTime=15.304
[scheduler:OnTick] - nbCall=180 - totalTime=2707 - averageTime=15.039
[mGameService] - nbCall=158 - totalTime=2048 - averageTime=12.962
[camera] - nbCall=156 - totalTime=1898 - averageTime=12.167
[DrawCacheRender] - nbCall=158 - totalTime=1612 - averageTime=10.203
[mixer] - nbCall=156 - totalTime=1335 - averageTime=8.558
[updating wall components] - nbCall=156 - totalTime=1315 - averageTime=8.429
[scheduler] - nbCall=180 - totalTime=1436 - averageTime=7.978
[HUD CHECK] - nbCall=156 - totalTime=1101 - averageTime=7.058
[cNetworkManager::Update] - nbCall=158 - totalTime=1000 - averageTime=6.329
[Simulation::luaPostUpdate] - nbCall=182 - totalTime=1095 - averageTime=6.016
[RPC queue] - nbCall=156 - totalTime=737 - averageTime=4.724
[Lua Wall Update] - nbCall=156 - totalTime=643 - averageTime=4.122
[MessagePump] - nbCall=158 - totalTime=549 - averageTime=3.475
[input] - nbCall=156 - totalTime=473 - averageTime=3.032
[updaters] - nbCall=182 - totalTime=332 - averageTime=1.824
[LuaBrain] - nbCall=182 - totalTime=296 - averageTime=1.626
[ActualCacheRender] - nbCall=158 - totalTime=213 - averageTime=1.348
[scheduler:Run] - nbCall=182 - totalTime=228 - averageTime=1.253
[CacheWorld] - nbCall=158 - totalTime=193 - averageTime=1.222
[EntityManagerPostPhysicsWallUpdate] - nbCall=156 - totalTime=177 - averageTime=1.135
[CacheWorldRender] - nbCall=158 - totalTime=154 - averageTime=0.975
[CacheDebugLayer] - nbCall=316 - totalTime=253 - averageTime=0.801
[EntityManagerUpdate] - nbCall=182 - totalTime=125 - averageTime=0.687
[events] - nbCall=182 - totalTime=122 - averageTime=0.67
[static components] - nbCall=182 - totalTime=98 - averageTime=0.538
[fe] - nbCall=156 - totalTime=81 - averageTime=0.519
[LuaSG] - nbCall=182 - totalTime=91 - averageTime=0.5
[ReplicaManager3::Update::AutoConstructByQuery] - nbCall=52 - totalTime=24 - averageTime=0.462
[ReplicaManager3::Update::SendSerializeIfChanged Loop] - nbCall=52 - totalTime=24 - averageTime=0.462
[Update] - nbCall=157 - totalTime=67 - averageTime=0.427
[EntityManagerWallUpdate] - nbCall=156 - totalTime=63 - averageTime=0.404
[TwitchManager::Update] - nbCall=158 - totalTime=60 - averageTime=0.38
[CameraUpdate] - nbCall=158 - totalTime=59 - averageTime=0.373
[CacheWorldSceneGraph] - nbCall=158 - totalTime=58 - averageTime=0.367
[ParticleBuffer::Update] - nbCall=1092 - totalTime=372 - averageTime=0.341
[cNetworkComponent::ComponentWallUpdate] - nbCall=156 - totalTime=49 - averageTime=0.314
[Simulation::luaUpdate] - nbCall=180 - totalTime=55 - averageTime=0.306
[DSS:DoPostUpdate] - nbCall=182 - totalTime=55 - averageTime=0.302
[cNetworkComponent] - nbCall=156 - totalTime=45 - averageTime=0.288
[EntityManagerPostUpdate] - nbCall=182 - totalTime=51 - averageTime=0.28
[Other] - nbCall=312 - totalTime=78 - averageTime=0.25
[mOnlyForAwakeEntities - WallUpdateHandler] - nbCall=156 - totalTime=17 - averageTime=0.109
[ReplicaManager3::Update::OnUserReplicaPostSerializeTick] - nbCall=52 - totalTime=5 - averageTime=0.096

 

For the log far from my base :

Spoiler

[MessagePump] - nbCall=360 - totalTime=1512729 - averageTime=4202.025
[Swap] - nbCall=360 - totalTime=376497 - averageTime=1045.825
[Normal] - nbCall=360 - totalTime=200057 - averageTime=555.714
[CacheRenderUI] - nbCall=360 - totalTime=192467 - averageTime=534.631
[Garbage Collection] - nbCall=358 - totalTime=174497 - averageTime=487.422
[CollectNodes] - nbCall=360 - totalTime=74369 - averageTime=206.581
[Physics] - nbCall=358 - totalTime=48085 - averageTime=134.316
[updating components] - nbCall=180 - totalTime=23043 - averageTime=128.017
[update widgets] - nbCall=364 - totalTime=39519 - averageTime=108.569
[mOnlyForAwakeEntities - Regular] - nbCall=716 - totalTime=74199 - averageTime=103.63
[cEntityManager::CheckSleepers] - nbCall=718 - totalTime=71776 - averageTime=99.967
[MiniMapComponent::CacheForRender] - nbCall=360 - totalTime=32731 - averageTime=90.919
[DontStarveInputHandler::Update] - nbCall=360 - totalTime=27891 - averageTime=77.475
[CacheOrthoSceneGraph] - nbCall=360 - totalTime=24632 - averageTime=68.422
[TileUpdate] - nbCall=6 - totalTime=394 - averageTime=65.667
[metadata] - nbCall=2 - totalTime=100 - averageTime=50
[MiniMapRender] - nbCall=360 - totalTime=17074 - averageTime=47.428
[EndFrame] - nbCall=360 - totalTime=16126 - averageTime=44.794
[cNetworkReplicaManager::Update] - nbCall=452 - totalTime=17892 - averageTime=39.584
[AutoConstructByQuery] - nbCall=60 - totalTime=2296 - averageTime=38.267
[HUD CHECK] - nbCall=358 - totalTime=13380 - averageTime=37.374
[mSoundSystem] - nbCall=360 - totalTime=8541 - averageTime=23.725
[GroundCreep] - nbCall=180 - totalTime=3816 - averageTime=21.2
[PostProcess] - nbCall=360 - totalTime=5631 - averageTime=15.642
[ReplicaManager3::Update::OnUserReplicaPreSerializeTick] - nbCall=60 - totalTime=938 - averageTime=15.633
[DrawNodes] - nbCall=360 - totalTime=5433 - averageTime=15.092
[WORLD CHECK] - nbCall=196 - totalTime=2593 - averageTime=13.23
[CacheRender] - nbCall=360 - totalTime=4177 - averageTime=11.603
[camera] - nbCall=358 - totalTime=4108 - averageTime=11.475
[DrawCacheRender] - nbCall=360 - totalTime=3836 - averageTime=10.656
[mixer] - nbCall=358 - totalTime=2359 - averageTime=6.589
[scheduler:OnTick] - nbCall=178 - totalTime=1050 - averageTime=5.899
[Simulation::luaPostUpdate] - nbCall=180 - totalTime=1049 - averageTime=5.828
[Debug Render] - nbCall=360 - totalTime=1638 - averageTime=4.55
[scheduler] - nbCall=178 - totalTime=785 - averageTime=4.41
[WorldCleanup] - nbCall=360 - totalTime=1582 - averageTime=4.394
[RPC queue] - nbCall=358 - totalTime=1556 - averageTime=4.346
[updating wall components] - nbCall=358 - totalTime=1300 - averageTime=3.631
[cNetworkManager::Update] - nbCall=360 - totalTime=1185 - averageTime=3.292
[DSS:DoPostUpdate] - nbCall=360 - totalTime=1058 - averageTime=2.939
[Lua Wall Update] - nbCall=358 - totalTime=1050 - averageTime=2.933
[input] - nbCall=358 - totalTime=921 - averageTime=2.573
[EntityManagerWallUpdate] - nbCall=358 - totalTime=714 - averageTime=1.994
[LuaBrain] - nbCall=180 - totalTime=300 - averageTime=1.667
[ActualCacheRender] - nbCall=360 - totalTime=518 - averageTime=1.439
[EntityManagerPostPhysicsWallUpdate] - nbCall=358 - totalTime=497 - averageTime=1.388
[updaters] - nbCall=180 - totalTime=224 - averageTime=1.244
[events] - nbCall=180 - totalTime=199 - averageTime=1.106
[scheduler:Run] - nbCall=180 - totalTime=196 - averageTime=1.089
[CacheWorld] - nbCall=360 - totalTime=380 - averageTime=1.056
[CacheWorldRender] - nbCall=360 - totalTime=310 - averageTime=0.861
[EntityManagerUpdate] - nbCall=180 - totalTime=124 - averageTime=0.689
[fe] - nbCall=358 - totalTime=237 - averageTime=0.662
[EntityManagerPostUpdate] - nbCall=360 - totalTime=234 - averageTime=0.65
[static components] - nbCall=180 - totalTime=103 - averageTime=0.572
[LuaSG] - nbCall=180 - totalTime=92 - averageTime=0.511
[mGameService] - nbCall=360 - totalTime=172 - averageTime=0.478
[ReplicaManager3::Update::SendSerializeIfChanged Loop] - nbCall=60 - totalTime=25 - averageTime=0.417
[ReplicaManager3::Update::AutoConstructByQuery] - nbCall=60 - totalTime=24 - averageTime=0.4
[cNetworkComponent::ComponentWallUpdate] - nbCall=358 - totalTime=127 - averageTime=0.355
[Update] - nbCall=359 - totalTime=119 - averageTime=0.331
[TwitchManager::Update] - nbCall=360 - totalTime=115 - averageTime=0.319
[cNetworkComponent] - nbCall=358 - totalTime=106 - averageTime=0.296
[CacheWorldSceneGraph] - nbCall=360 - totalTime=102 - averageTime=0.283
[Simulation::luaUpdate] - nbCall=178 - totalTime=50 - averageTime=0.281
[ParticleBuffer::Update] - nbCall=900 - totalTime=253 - averageTime=0.281
[CameraUpdate] - nbCall=360 - totalTime=85 - averageTime=0.236
[Other] - nbCall=716 - totalTime=137 - averageTime=0.191
[ReplicaManager3::Update::OnUserReplicaPostSerializeTick] - nbCall=60 - totalTime=9 - averageTime=0.15
[mOnlyForAwakeEntities - WallUpdateHandler] - nbCall=358 - totalTime=37 - averageTime=0.103

To be honnest, now, I need help to interpret them, because I have no idea of what is doing each method ^^ (for example : "MessagePump", which is the most called "far".

But we can see interresing things, for example :

• cEntityManager::CheckSleepers : 3060 in my base => only 99 far.
• CollectNodes 2419 => 206
• Physics 1964 => 134
• Normal 1750 => 555
• mOnlyForAwakeEntities 1519 => 103

Cache renderer and garbage collection have near value, and most of other values takes less times.

With this information in addition, anybody have an idea of what is the problem and how fix it ?

ps :

• cEntityManager::CheckSleepers  : args":{"src_file":"EntityManager.cpp","src_line":592}
• CollectNodes : args":{"src_file":"game.cpp","src_line":1504}
• Physics : args":{"src_file":"simulation.cpp","src_line":1161}
• normal : args":{"src_file":"game.cpp","src_line":890}
• mOnlyForAwakeEntities  : {"src_file":"EntityManager.cpp","src_line":336}

far_profile (fps60).json

base_profile (fps25).json

[rezecib]

@Onirian So game updates (ticks) occur 30 times a second, so each update has a "budget" of about 33ms. We can see in the base profile that it's using ~23ms for the Update, ~5ms for the CacheRender, and ~4.5 ms for the DrawCacheRender. This puts it right at the budget... I'm guessing this means that it's splitting the rendering of frames between updates because it runs out of time, but I'm not sure.

I think you have an error in your php script, though, MessagePump is called before each update, but looking at it in chrome://tracing it takes almost no time (had to zoom into microsecond level to even see it). It should have an average time of around 0.003 ms, while CheckSleepers should have an average of 0.2ms far from base and 6ms close to base. Trying to compare the GUI with the json by hand I figured out that the actual time isn't stored directly, but you must find pairs of lines with "ph":"B" ("Begin"?) and "ph":"E" ("End"?) and take the difference in their "ts".

[Onirian]

Hummm. Begin and end... It sounds good. I will modify my script to take that in account and see the new result. 

[rezecib]

@Onirian Also, try the launch option -threaded_render for the game. From your profile it looks like it's using about 10ms for the rendering, so putting that on a separate thread may help a lot.

[Onirian]

Yes, I will try that. Considering I have a 8 core, anything that can be threaded is a good idea.

I will modify my script today, I will normaly post the new result later in the day.

[Onirian]

So, here is the new result, which seems really more coherent (now, MessagePump takes near 5, it's really better ^^) .

In the base (fps = 25)  :

Spoiler

[Update] - nbCall=78 - totalTime=2053546 - averageTime=26327.513
[EntityManagerWallUpdate] - nbCall=78 - totalTime=950058 - averageTime=12180.231
[EntityManagerPostUpdate] - nbCall=91 - totalTime=558564 - averageTime=6138.066
[cEntityManager::CheckSleepers] - nbCall=169 - totalTime=1025054 - averageTime=6065.408
[DrawCacheRender] - nbCall=79 - totalTime=441478 - averageTime=5588.329
[CacheRender] - nbCall=79 - totalTime=433473 - averageTime=5487
[ActualCacheRender] - nbCall=79 - totalTime=433395 - averageTime=5486.013
[CacheWorld] - nbCall=79 - totalTime=418363 - averageTime=5295.734
[CacheWorldSceneGraph] - nbCall=79 - totalTime=394678 - averageTime=4995.924
[CollectNodes] - nbCall=79 - totalTime=382117 - averageTime=4836.924
[Physics] - nbCall=78 - totalTime=306443 - averageTime=3928.756
[CacheWorldRender] - nbCall=79 - totalTime=290680 - averageTime=3679.494
[Normal] - nbCall=79 - totalTime=265486 - averageTime=3360.582
[Other] - nbCall=156 - totalTime=474054 - averageTime=3038.808
[mOnlyForAwakeEntities - Regular] - nbCall=156 - totalTime=474010 - averageTime=3038.526
[CacheRenderUI] - nbCall=79 - totalTime=96357 - averageTime=1219.709
[Garbage Collection] - nbCall=78 - totalTime=76193 - averageTime=976.833
[CacheRenderDebugDraw] - nbCall=79 - totalTime=53864 - averageTime=681.823
[Lua Wall Update] - nbCall=78 - totalTime=41114 - averageTime=527.103
[EntityManagerUpdate] - nbCall=91 - totalTime=44976 - averageTime=494.242
[Swap] - nbCall=79 - totalTime=32878 - averageTime=416.177
[cNetworkManager::Update] - nbCall=79 - totalTime=25922 - averageTime=328.127
[fe] - nbCall=78 - totalTime=23874 - averageTime=306.077
[Simulation::luaUpdate] - nbCall=90 - totalTime=26659 - averageTime=296.211
[MiniMapComponent::CacheForRender] - nbCall=79 - totalTime=22924 - averageTime=290.177
[update widgets] - nbCall=80 - totalTime=21332 - averageTime=266.65
[updating components] - nbCall=91 - totalTime=21629 - averageTime=237.681
[DSS:DoPostUpdate] - nbCall=91 - totalTime=17002 - averageTime=186.835
[DontStarveInputHandler::Update] - nbCall=91 - totalTime=16919 - averageTime=185.923
[WORLD CHECK] - nbCall=56 - totalTime=10273 - averageTime=183.446
[CacheOrthoSceneGraph] - nbCall=79 - totalTime=14397 - averageTime=182.241
[DrawNodes] - nbCall=79 - totalTime=12427 - averageTime=157.304
[input] - nbCall=78 - totalTime=11697 - averageTime=149.962
[ReplicaManager3::Update::AutoConstructByQuery] - nbCall=26 - totalTime=3645 - averageTime=140.192
[AutoConstructByQuery] - nbCall=26 - totalTime=3628 - averageTime=139.538
[ReplicaManager3::Update::OnUserReplicaPreSerializeTick] - nbCall=26 - totalTime=3237 - averageTime=124.5
[EndFrame] - nbCall=79 - totalTime=9026 - averageTime=114.253
[Debug Render] - nbCall=79 - totalTime=8068 - averageTime=102.127
[metadata] - nbCall=1 - totalTime=100 - averageTime=100
[mSoundSystem] - nbCall=79 - totalTime=7866 - averageTime=99.57
[cNetworkReplicaManager::Update] - nbCall=129 - totalTime=7048 - averageTime=54.636
[TileUpdate] - nbCall=3 - totalTime=162 - averageTime=54
[WorldCleanup] - nbCall=79 - totalTime=3389 - averageTime=42.899
[scheduler] - nbCall=90 - totalTime=2948 - averageTime=32.756
[PostProcess] - nbCall=79 - totalTime=2405 - averageTime=30.443
[scheduler:OnTick] - nbCall=90 - totalTime=2605 - averageTime=28.944
[MiniMapRender] - nbCall=79 - totalTime=2002 - averageTime=25.342
[camera] - nbCall=78 - totalTime=1804 - averageTime=23.128
[mixer] - nbCall=78 - totalTime=1293 - averageTime=16.577
[Simulation::luaPostUpdate] - nbCall=91 - totalTime=976 - averageTime=10.725
[HUD CHECK] - nbCall=78 - totalTime=801 - averageTime=10.269
[updating wall components] - nbCall=78 - totalTime=720 - averageTime=9.231
[MessagePump] - nbCall=79 - totalTime=443 - averageTime=5.608
[LuaSG] - nbCall=91 - totalTime=476 - averageTime=5.231
[GroundCreep] - nbCall=91 - totalTime=464 - averageTime=5.099
[RPC queue] - nbCall=78 - totalTime=174 - averageTime=2.231
[scheduler:Run] - nbCall=91 - totalTime=190 - averageTime=2.088
[LuaBrain] - nbCall=91 - totalTime=177 - averageTime=1.945
[EntityManagerPostPhysicsWallUpdate] - nbCall=78 - totalTime=131 - averageTime=1.679
[cNetworkComponent] - nbCall=78 - totalTime=74 - averageTime=0.949
[mOnlyForAwakeEntities - WallUpdateHandler] - nbCall=78 - totalTime=54 - averageTime=0.692
[CacheDebugLayer] - nbCall=158 - totalTime=103 - averageTime=0.652
[mGameService] - nbCall=79 - totalTime=50 - averageTime=0.633
[events] - nbCall=91 - totalTime=52 - averageTime=0.571
[static components] - nbCall=91 - totalTime=50 - averageTime=0.549
[updaters] - nbCall=91 - totalTime=46 - averageTime=0.505
[CameraUpdate] - nbCall=79 - totalTime=30 - averageTime=0.38
[ReplicaManager3::Update::SendSerializeIfChanged Loop] - nbCall=26 - totalTime=9 - averageTime=0.346
[spawners] - nbCall=3 - totalTime=1 - averageTime=0.333
[cNetworkComponent::ComponentWallUpdate] - nbCall=78 - totalTime=22 - averageTime=0.282
[ParticleBuffer::Update] - nbCall=546 - totalTime=142 - averageTime=0.26
[TwitchManager::Update] - nbCall=79 - totalTime=17 - averageTime=0.215
[ReplicaManager3::Update::OnUserReplicaPostSerializeTick] - nbCall=26 - totalTime=3 - averageTime=0.115

 

Far from the base (fps = 60) :

Spoiler

[Update] - nbCall=179 - totalTime=528911 - averageTime=2954.81
[DrawCacheRender] - nbCall=180 - totalTime=417225 - averageTime=2317.917
[Swap] - nbCall=180 - totalTime=376467 - averageTime=2091.483
[CacheWorldRender] - nbCall=180 - totalTime=224451 - averageTime=1246.95
[Normal] - nbCall=180 - totalTime=195717 - averageTime=1087.317
[CacheRenderUI] - nbCall=180 - totalTime=192309 - averageTime=1068.383
[Garbage Collection] - nbCall=179 - totalTime=174215 - averageTime=973.268
[CacheRender] - nbCall=180 - totalTime=138184 - averageTime=767.689
[ActualCacheRender] - nbCall=180 - totalTime=137938 - averageTime=766.322
[CacheWorld] - nbCall=180 - totalTime=112689 - averageTime=626.05
[EntityManagerWallUpdate] - nbCall=179 - totalTime=109804 - averageTime=613.43
[CacheWorldSceneGraph] - nbCall=180 - totalTime=79839 - averageTime=443.55
[CollectNodes] - nbCall=180 - totalTime=74209 - averageTime=412.272
[Lua Wall Update] - nbCall=179 - totalTime=63014 - averageTime=352.034
[Simulation::luaUpdate] - nbCall=89 - totalTime=25725 - averageTime=289.045
[Physics] - nbCall=179 - totalTime=48023 - averageTime=268.285
[updating components] - nbCall=90 - totalTime=23013 - averageTime=255.7
[EntityManagerPostUpdate] - nbCall=180 - totalTime=37395 - averageTime=207.75
[Other] - nbCall=358 - totalTime=74236 - averageTime=207.363
[mOnlyForAwakeEntities - Regular] - nbCall=358 - totalTime=74136 - averageTime=207.084
[fe] - nbCall=179 - totalTime=36530 - averageTime=204.078
[cEntityManager::CheckSleepers] - nbCall=359 - totalTime=67742 - averageTime=188.696
[MiniMapComponent::CacheForRender] - nbCall=180 - totalTime=31313 - averageTime=173.961
[update widgets] - nbCall=182 - totalTime=31155 - averageTime=171.181
[DSS:DoPostUpdate] - nbCall=180 - totalTime=29985 - averageTime=166.583
[DontStarveInputHandler::Update] - nbCall=180 - totalTime=29825 - averageTime=165.694
[CacheOrthoSceneGraph] - nbCall=180 - totalTime=24376 - averageTime=135.422
[cNetworkManager::Update] - nbCall=180 - totalTime=21631 - averageTime=120.172
[metadata] - nbCall=1 - totalTime=100 - averageTime=100
[input] - nbCall=179 - totalTime=16575 - averageTime=92.598
[EndFrame] - nbCall=180 - totalTime=15923 - averageTime=88.461
[ReplicaManager3::Update::AutoConstructByQuery] - nbCall=30 - totalTime=2299 - averageTime=76.633
[AutoConstructByQuery] - nbCall=30 - totalTime=2277 - averageTime=75.9
[HUD CHECK] - nbCall=179 - totalTime=12917 - averageTime=72.162
[EntityManagerUpdate] - nbCall=90 - totalTime=4304 - averageTime=47.822
[mSoundSystem] - nbCall=180 - totalTime=8524 - averageTime=47.356
[ReplicaManager3::Update::OnUserReplicaPreSerializeTick] - nbCall=30 - totalTime=936 - averageTime=31.2
[PostProcess] - nbCall=180 - totalTime=5611 - averageTime=31.172
[DrawNodes] - nbCall=180 - totalTime=5383 - averageTime=29.906
[TileUpdate] - nbCall=3 - totalTime=88 - averageTime=29.333
[MiniMapRender] - nbCall=180 - totalTime=5211 - averageTime=28.95
[WORLD CHECK] - nbCall=98 - totalTime=2571 - averageTime=26.235
[camera] - nbCall=179 - totalTime=3949 - averageTime=22.061
[cNetworkReplicaManager::Update] - nbCall=226 - totalTime=3346 - averageTime=14.805
[scheduler] - nbCall=89 - totalTime=1262 - averageTime=14.18
[mixer] - nbCall=179 - totalTime=2288 - averageTime=12.782
[scheduler:OnTick] - nbCall=89 - totalTime=971 - averageTime=10.91
[Simulation::luaPostUpdate] - nbCall=90 - totalTime=935 - averageTime=10.389
[Debug Render] - nbCall=180 - totalTime=1615 - averageTime=8.972
[WorldCleanup] - nbCall=180 - totalTime=1521 - averageTime=8.45
[MessagePump] - nbCall=180 - totalTime=950 - averageTime=5.278
[LuaSG] - nbCall=90 - totalTime=449 - averageTime=4.989
[GroundCreep] - nbCall=90 - totalTime=413 - averageTime=4.589
[LuaBrain] - nbCall=90 - totalTime=271 - averageTime=3.011
[RPC queue] - nbCall=179 - totalTime=458 - averageTime=2.559
[EntityManagerPostPhysicsWallUpdate] - nbCall=179 - totalTime=424 - averageTime=2.369
[updating wall components] - nbCall=179 - totalTime=357 - averageTime=1.994
[scheduler:Run] - nbCall=90 - totalTime=159 - averageTime=1.767
[cNetworkComponent] - nbCall=179 - totalTime=176 - averageTime=0.983
[mOnlyForAwakeEntities - WallUpdateHandler] - nbCall=179 - totalTime=147 - averageTime=0.821
[mGameService] - nbCall=180 - totalTime=112 - averageTime=0.622
[updaters] - nbCall=90 - totalTime=54 - averageTime=0.6
[static components] - nbCall=90 - totalTime=51 - averageTime=0.567
[events] - nbCall=90 - totalTime=40 - averageTime=0.444
[ReplicaManager3::Update::SendSerializeIfChanged Loop] - nbCall=30 - totalTime=10 - averageTime=0.333
[ParticleBuffer::Update] - nbCall=450 - totalTime=127 - averageTime=0.282
[CameraUpdate] - nbCall=180 - totalTime=48 - averageTime=0.267
[TwitchManager::Update] - nbCall=180 - totalTime=44 - averageTime=0.244
[ReplicaManager3::Update::OnUserReplicaPostSerializeTick] - nbCall=30 - totalTime=7 - averageTime=0.233
[cNetworkComponent::ComponentWallUpdate] - nbCall=179 - totalTime=40 - averageTime=0.223

Interessing points :

• Update (base) : 26327 => (far) : 2954
• EntityManagerWallUpdate : 12180 => 613
• EntityManagerPostUpdate : 6138 => 207
• cEntityManager::CheckSleepers : 6065 => 188
• CacheRender 5487 : => 767
• other cache...

DrawCacheRender, CacheRender, ActualCacheRender, CacheWorld, CacheWorldSceneGraph, CacheWorldRender takes all a lot more time.

In fact, there is not one method which are taking all the times, but the most are slower... Even if look at other value with very low impact, "scheduler" for example, "32" in "base" and "14" "far".

I'm pretty sure that it's possible to improve the "update" phase and "cache" management, but it will probably not be easy.

I will try the -threaded_render option, according to DrawCacheRender, CacheRender, ActualCacheRender, CacheWorldRender and CacheRenderUI, maybe the gain can be very significant.

 

 

[Onirian]

With the option -threaded_render , in my base I was near 30fps, so there is maybe a gain (25fps at my last test) but very little.

Not yet the solution

[calculuschild]

Wow.  That's a pretty big difference between the two.  I put this together as a comparison using the chrome://trace gui:

So it looks like in the base (top graph,) the processing for each frame is run to completion despite overrunning the budget rather than splitting up the animation between frames as you suggested, @rezecib.  It just takes an entire 1/25 of a second to complete, and thus, 25 FPS.  Not only does this mean graphics are updating at 25 FPS, but physics and the other items are also updated at 25 FPS, which I could see causing issues with collisions behaving incorrectly, player input not registering, network data not being sent or received from clients on time (or dropping data entirely), etc., depending how it is handled.

We can see that it is definitely the Update portion which sees the biggest percentage increase, with EntityManagerWallUpdate being the biggest item within that.  So here's two thoughts I have:

1) There's a separate "EntityManagerUpdate" which is much smaller on both graphs than the "EntityManagerWallUpdate."  Is the Wall Manager just handling walls, and everything else goes under the other updater?  Why are walls so slow in comparison, even when away from base (where I presume there are few to zero walls).

2) Within "EntityManagerWallUpdate" we see a call to "cEntityManager::CheckSleepers" on line 592 of EntityManager.cpp.  Then we see under "EntityManagerPostUpdate" a call to the same function (same name, same line) for approximately the same time.  Why is this code being run twice per frame?  Could be they are handling totally separate items to support their respective parent functions, but where their execution times are so similar, I wonder if they aren't redundantly doing the same thing, rather than caching the results the first time.

[rezecib]

@calculuschild "Wall" refers to "Wall Time" or real-time, as opposed to game-time. It doesn't actually relate to in-game walls, the only special handling they would get is in the Physics portion.

[Onirian]

@calculuschild , your diagram is really clear (the next time I will definively download your tool ^^), and really coherent. The update takes sooo many times (and why ? most of my object doen't need any update, they are just "here" and doesn't have any interaction (wall, chest, objects...)

So... Klei ?

[calculuschild]

14 hours ago, rezecib said:

"Wall" refers to "Wall Time" or real-time

Ah.  Yep.  That makes more sense.  So we can't necessarily pin down the slowdown on any one game object with the data we have?

I haven't looked much into the files for this game, but I'd like to help with some more investigation; this is the kind of stuff I did all day at my last job fixing up some old server code (not saying I'm a specialist or have any special skill.)  How much of the update code is C++ and how much is Lua that we can dig deeper into?

[rezecib]

6 hours ago, calculuschild said:

How much of the update code is C++ and how much is Lua that we can dig deeper into?

Unfortunately, it looks to me like almost the entirety of the slowdown for clients is C++ side-- if you look closely at the updates in tracing you can see LuaUpdate in there, but it really doesn't do much on clients. I've heard that CheckSleepers is being investigated for optimization on PS4, so hopefully that will also translate to gains on PC.

I think one of the really mystifying things here is that as a client-server, I can have 4k logs before I get 25-30fps, but as a client I can only have 2k.

But as for a potential remaining Lua mystery, it looked from Onirian's prefab counts that farm decor prefabs still weren't getting deleted when they should be.

Edit: Here are some more profiles from my computer for anyone who wants to play with them:

My DxDiag (for specs). Most important part: 4-core 3.3GHz processor (and a decent graphics card).

For all of these I created a server, went into the middle of the ocean, created a tile of land, restarted the server, and then c_spawned 1-4 thousand logs. I used Nvidia's Shadowplay (without any recording) to check my fps, and took the profiles after the fps stabilized.

ClientOnly-1klogs-58fps-profile.json

ClientOnly-2klogs-25fps-profile.json

ClientServer-2klogs-58fps-profile.json

ClientServer-4klogs-30fps-profile.json

From the fps perspective, it looks like logs have twice the performance impact on clients. It also appears in my profiles that the Physics part is changing the most, aside from the rendering steps.

[calculuschild]

Yep, that is really odd.  @rezecib, looking at your logs (hahahahaha...) I compared both of the 2k setups.  You say these are identical in every way, and supposedly are just the middle of the ocean with one square of land?  From what I can see, the two have 3 main sections that are vastly different:

1) EntityManagerWallUpdate: About 17.7 times slower on just the client.

2) Physics: About 11.7 times slower on just the client.

3) EntityManagerPostupdate: About 11.2 times slower on just the client.

Besides these, the only other noticeable difference was CacheRender at about 2 times slower on just the client.

The other items from what I could see are approximately the same time on both setups.

 

Edit:

Also comparing the two 58 FPS setups, its interesting to see that the client-only will spend about twice as long on Physics and EntityManagerWallUpdate, where the server-client spends more time on the Lua Wall Update and Simulation::LuaUpdate.

I wonder what makes the server-client side slow down first with Lua but the client-only slows down first with physics.