Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Measure long frameEndActions #20903

Open
anvilvapre opened this issue Jun 6, 2023 · 4 comments
Open

Measure long frameEndActions #20903

anvilvapre opened this issue Jun 6, 2023 · 4 comments
Labels
Performance

Comments

@anvilvapre
Copy link
Contributor

anvilvapre commented Jun 6, 2023 •
edited

Activities that take over 1ms (by default) are logged as long tasks.

With the growing number of frame end task I was curious to see how long they would take.

It appears often enough they exeed 1 to 4 ms.

Shell map, logging of frame end tasks actions that took over 1ms to execute, sorted by slowest, trimmed at 20 values.

    26 ms [491] FrameEndTask: System.Action`1[OpenRA.World]
    19 ms [126] FrameEndTask: System.Action`1[OpenRA.World]
    13 ms [751] FrameEndTask: System.Action`1[OpenRA.World]
    13 ms [61] FrameEndTask: System.Action`1[OpenRA.World]
    12 ms [1] FrameEndTask: System.Action`1[OpenRA.World]
    12 ms [1626] FrameEndTask: System.Action`1[OpenRA.World]
    11 ms [876] FrameEndTask: System.Action`1[OpenRA.World]
    11 ms [0] FrameEndTask: System.Action`1[OpenRA.World]
    10 ms [1] FrameEndTask: System.Action`1[OpenRA.World]
     9 ms [1751] FrameEndTask: System.Action`1[OpenRA.World]
     8 ms [894] FrameEndTask: System.Action`1[OpenRA.World]
     7 ms [1] FrameEndTask: System.Action`1[OpenRA.World]
     7 ms [1] FrameEndTask: System.Action`1[OpenRA.World]
     7 ms [1501] FrameEndTask: System.Action`1[OpenRA.World]
     6 ms [896] FrameEndTask: System.Action`1[OpenRA.World]
     6 ms [790] FrameEndTask: System.Action`1[OpenRA.World]
     6 ms [1501] FrameEndTask: System.Action`1[OpenRA.World]
     6 ms [1501] FrameEndTask: System.Action`1[OpenRA.World]
     5 ms [1] FrameEndTask: System.Action`1[OpenRA.World]
     5 ms [1081] FrameEndTask: System.Action`1[OpenRA.World]


World.cs Tick()

....
                        ExecuteFrameEndActions();                                                                       
                }                                                                                                       
                                                                                                                        
                void ExecuteFrameEndActions()                                                                           
                {                                                                                                       
                        var perfLogger = new PerfTickLogger();                                                          
                                perfLogger.Start();                                                                     
                        while (frameEndActions.Count != 0)                                                              
                        {                                                                                               
                                var action = frameEndActions.Dequeue();                                                 
                                action(this);                                                                           
                                perfLogger.LogTickAndRestartTimer("FrameEndTask", action);                              
                        }                                                                                               
                }
@anvilvapre
Copy link
Contributor Author

I noticed there are two types of frame end actions.

For non game world related tasks/actions there is an action queue being used - mostly for gui related stuff. Here the ActionQueue is used which is good as it sorts actions by tick time.

For world related - in game logic - tasks no action queue is used. Actions are added to a list and each game tick executed. I.e. a delayed action will substract a counter each tick. Depending on the amount of frame end tasks it may be beneficial to use the ActionQueue here as well.

ActionQueue uses a binary search - i.e. to find all expired - to be run - tasks. This seems unneeded assuming that in most cases those tasks that are in front of the queue need to be queried. But since the queue is likely never to big - the current solution may be acceptable.

@anvilvapre
Copy link
Contributor Author

anvilvapre commented Dec 19, 2023 •
edited

See last column source file + line number. Placebuilding seems expensive along with prod queue.

    28 ms [208] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69  
    22 ms [0] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409                                                                     
    21 ms [126] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedAction.cs:$32             
    17 ms [4357] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69 
    16 ms [1] FrameEndTask: TraitEnabled, $ OpenRA.Mods.Common/Traits/Buildings/FreeActor.cs:$73
    16 ms [0] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedAction.cs:$32               
    15 ms [24375] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409            
    15 ms [1447] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/ProductionQueue.cs:$448
    14 ms [8620] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90           
    14 ms [44167] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
    14 ms [2803] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90           
    14 ms [1500] FrameEndTask: SpawnCrate, $ OpenRA.Mods.Common/Traits/World/CrateSpawner.cs:$140
    14 ms [13698] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38                   
    13 ms [31108] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
    13 ms [21505] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
    13 ms [12829] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
    12 ms [25741] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
    12 ms [14] FrameEndTask: DoTransform, $ OpenRA.Mods.Common/Activities/Transform.cs:$83
    11 ms [9595] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
    11 ms [4479] FrameEndTask: Tick, $ OpenRA.Mods.Common/Effects/ContrailFader.cs:$34
    11 ms [3523] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/ProductionQueue.cs:$448
    11 ms [30782] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
    10 ms [5296] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
    10 ms [47437] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
    10 ms [4036] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
    10 ms [34504] FrameEndTask: Activate, $ OpenRA.Mods.Common/Traits/Crates/GiveUnitCrateAction.cs:$79
    10 ms [21952] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
    10 ms [21074] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
    10 ms [1] FrameEndTask: WorldLoaded, $ OpenRA.Mods.Common/Traits/Player/PlayerRadarTerrain.cs:$71
    10 ms [19185] FrameEndTask: Tick, $ OpenRA.Mods.Common/Effects/SpriteEffect.cs:$65
    10 ms [16447] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
    10 ms [14467] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
    10 ms [0] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
     9 ms [61] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     9 ms [30782] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
     9 ms [1] FrameEndTask: WorldLoaded, $ OpenRA.Mods.Common/Traits/Player/PlayerRadarTerrain.cs:$71
     9 ms [14] FrameEndTask: DoTransform, $ OpenRA.Mods.Common/Activities/Transform.cs:$83
     9 ms [12413] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/ProductionQueue.cs:$448
     8 ms [9913] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     8 ms [4234] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     8 ms [40667] FrameEndTask: DoImpact, $ OpenRA.Mods.Common/Warheads/CreateEffectWarhead.cs:$130
     8 ms [37228] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
     8 ms [32839] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     8 ms [31872] FrameEndTask: DoTransform, $ OpenRA.Mods.Common/Activities/Transform.cs:$83
     8 ms [2635] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     8 ms [24301] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     8 ms [19324] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     8 ms [1711] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     8 ms [13698] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     8 ms [0] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
     7 ms [7384] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     7 ms [7222] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     7 ms [5650] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     7 ms [43807] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     7 ms [3956] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/ProductionQueue.cs:$448
     7 ms [39551] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
     7 ms [3155] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     7 ms [30222] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     7 ms [29054] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
     7 ms [28702] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     7 ms [2701] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
     7 ms [24610] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     7 ms [1] FrameEndTask: .ctor, $ OpenRA.Mods.Common/Traits/Buildings/LegacyBridgeHut.cs:$38
     7 ms [1516] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     7 ms [12601] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     7 ms [12500] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
     7 ms [0] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [8576] FrameEndTask: LayMine, $ OpenRA.Mods.Common/Activities/LayMines.cs:$206
     6 ms [8167] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     6 ms [6740] FrameEndTask: Impact, $ OpenRA.Game/GameRules/WeaponInfo.cs:$243
     6 ms [5250] FrameEndTask: Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
     6 ms [4843] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     6 ms [41285] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
     6 ms [33448] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [27298] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [26488] FrameEndTask: Dispose, $ OpenRA.Game/Actor.cs:$409
     6 ms [26161] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [25708] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [2212] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     6 ms [21802] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [21247] FrameEndTask: DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     6 ms [20713] FrameEndTask: ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69

@anvilvapre
Copy link
Contributor Author

[
20231219_time_frame_end_tasks_diff.txt
](url)

+               public void AddFrameEndTask(Action<World> a,
+                               [System.Runtime.CompilerServices.CallerMemberName] string memberName = "",
+                               [System.Runtime.CompilerServices.CallerFilePath] string sourceFilePath = "",
+                               [System.Runtime.CompilerServices.CallerLineNumber] int sourceLineNumber = 0)
+               {
+                       frameEndActions.Enqueue((a, $"{memberName}, ${sourceFilePath}:${sourceLineNumber}"));
+               }

@anvilvapre
Copy link
Contributor Author

anvilvapre commented Dec 19, 2023 •
edited

summary:

number of occurences in perf log. after bot game.

     27 DoProduction, $ OpenRA.Mods.Common/Traits/Production.cs:$90
     26 ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/PlaceBuilding.cs:$69
     11 Dispose, $ OpenRA.Game/Actor.cs:$409
      8 Tick, $ OpenRA.Game/Effects/DelayedImpact.cs:$38
      7 WorldLoaded, $ OpenRA.Mods.Common/Traits/Player/PlayerRadarTerrain.cs:$71
      4 ResolveOrder, $ OpenRA.Mods.Common/Traits/Player/ProductionQueue.cs:$448
      3 Tick, $ OpenRA.Game/Effects/DelayedAction.cs:$32
      3 DoTransform, $ OpenRA.Mods.Common/Activities/Transform.cs:$83
      1 TraitEnabled, $ OpenRA.Mods.Common/Traits/Buildings/FreeActor.cs:$73
      1 Tick, $ OpenRA.Mods.Common/Effects/SpriteEffect.cs:$65
      1 Tick, $ OpenRA.Mods.Common/Effects/ContrailFader.cs:$34
      1 SpawnCrate, $ OpenRA.Mods.Common/Traits/World/CrateSpawner.cs:$140
      1 SendParatroopers, $ OpenRA.Mods.Common/Traits/SupportPowers/ParatroopersPower.cs:$199
      1 RemovedFromWorld, $ OpenRA.Mods.Common/Traits/SpawnActorOnDeath.cs:$143
      1 LayMine, $ OpenRA.Mods.Common/Activities/LayMines.cs:$206
      1 Impact, $ OpenRA.Game/GameRules/WeaponInfo.cs:$243
      1 DoImpact, $ OpenRA.Mods.Common/Warheads/CreateEffectWarhead.cs:$130
      1 .ctor, $ OpenRA.Mods.Common/Traits/Buildings/LegacyBridgeHut.cs:$38
      1 Activate, $ OpenRA.Mods.Common/Traits/Crates/GiveUnitCrateAction.cs:$79

@anvilvapre anvilvapre mentioned this issue Mar 30, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Performance
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@abcdefg30 @anvilvapre