View Issue Details

IDProjectCategoryLast Update
0025832AI War 2Bug - OtherNov 16, 2021 4:42 pm
ReporterColdPrototype Assigned ToChris_McElligottPark  
Status resolvedResolutionfixed 
Fixed in VersionBeta 3.752 Pathfinding Efficiency 
Summary0025832: Pathfinder error for DZS
DescriptionNot reliably reproducible from a save. Rarely occurs, but has happened multiple times.

11/15/2021 10:55:27 PM 3.751 SINGLEP DELAYED14 TID61 Called Dark Zenith Svikari FireteamGetDangerOfPath2 pathfinder again before it finished finding the first path! This probably means it's being called by two threads! Run started: 0 ticks ago (0ms)
  at System.Environment.get_StackTrace () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.Verbosity Verbosity) [0x00000] in <213b58ccdbaa4596ac7ad7e33d9b50e4>:0
  at Arcen.AIW2.External.ArcenPathfinder`1[N].FindPathInner (Arcen.AIW2.Core.Faction Fac, System.String DebugAddendum, Arcen.Universal.List`1[T] PathToFill, N Origin, N Target, System.Int32 NeedToGetWithinXRangeOfTarget, System.Int32 RequiresNoMoreThanXRangeFromOrigin, System.Boolean DoDebugLog, Arcen.AIW2.Core.ArcenSimContextAnyStatus Context) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.ArcenPathfinder`1[N].FindPath (Arcen.AIW2.Core.Faction Fac, System.String DebugAddendum, Arcen.Universal.List`1[T] PathToFill, N Origin, N Target, System.Int32 NeedToGetWithinXRangeOfTarget, System.Int32 RequiresNoMoreThanXRangeFromOrigin, System.Boolean DoDebugLog, Arcen.AIW2.Core.ArcenSimContextAnyStatus Context) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.PathingHelper.InnerFindPath_Raw (Arcen.AIW2.Core.Faction faction, System.String DebugAddendum, Arcen.AIW2.Core.Planet Origin, Arcen.AIW2.Core.Planet Target, Arcen.AIW2.External.PathingMode mode, Arcen.AIW2.Core.ArcenSimContextAnyStatus Context) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.PathingHelper.FindPathFreshOrFromCache (Arcen.AIW2.Core.Faction ForFaction, System.String DebugAddendum, Arcen.AIW2.Core.Planet Origin, Arcen.AIW2.Core.Planet Target, Arcen.AIW2.External.PathingMode mode, Arcen.AIW2.Core.ArcenSimContextAnyStatus Context) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.Fireteam.GetDangerOfPath (Arcen.AIW2.Core.Faction faction, Arcen.AIW2.Core.ArcenSimContextAnyStatus Context, Arcen.AIW2.Core.Planet source, Arcen.AIW2.Core.Planet destination, System.Boolean includeDestination, System.Int16& hops) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.FireteamHonoraryDeepInfo.CanISafelyGetToLurkPlanet (Arcen.AIW2.Core.Faction faction, Arcen.AIW2.Core.ArcenSimContextAnyStatus Context) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.FireteamUtility+<>c__DisplayClass7_0.<UpdateFireteams>b__3 (Arcen.AIW2.External.Fireteam team) [0x00000] in <62f8a4c46c01499aa9179e48996bc652>:0
  at Arcen.AIW2.External.Fireteam.DoFor (Arcen.Universal.ArcenLessLinkedList`1[ItemType] List, Arcen.AIW2.External.Fireteam+ProcessorDelegate Processor) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.FireteamUtility.UpdateFireteams (Arcen.AIW2.Core.Faction faction, Arcen.AIW2.External.ArcenLongTermIntermittentPlanningContext Context, Arcen.Universal.ArcenLessLinkedList`1[ItemType] Teams, Arcen.Universal.ProtectedValDictionary`2[TKey,TValue] TeamsAimedAtPlanet, Arcen.Universal.ArcenCharacterBuffer tracingBuffer, Arcen.Universal.FInt attackingStrengthMultiplier, Arcen.Universal.List`1[T] PlanetsToDefendInput, Arcen.Universal.List`1[T] ShipsThatNeedEscorting) [0x00000] in <62f8a4c46c01499aa9179e48996bc652>:0
  at Arcen.AIW2.External.DarkZenithFactionDeepInfoRoot.DoLongRangePlanning_OnBackgroundNonSimThread_Subclass (Arcen.AIW2.External.ArcenLongTermIntermittentPlanningContext Context) [0x00000] in <62f8a4c46c01499aa9179e48996bc652>:0
  at Arcen.AIW2.External.ExternalFactionDeepInfoRoot.DoLongRangePlanning_OnBackgroundNonSimThread_HostOnly (Arcen.AIW2.Core.ILongRangePlanningHostContext Context) [0x00000] in <62f8a4c46c01499aa9179e48996bc652>:0
  at Arcen.AIW2.Core.Faction.Safe_DeepInfo_DoLongRangePlanning_OnBackgroundNonSimThread_HostOnly (Arcen.AIW2.Core.ILongRangePlanningHostContext Context) [0x00000] in <4a1815a6dff24fc7a1ebc7682fdef1f7>:0
  at Arcen.AIW2.External.SpecialFactionPlanning.Execute () [0x00000] in <62f8a4c46c01499aa9179e48996bc652>:0
  at Arcen.AIW2.External.ArcenHostOnlySimPlanningContext.BackgroundThreadRunHandler (System.Boolean FailSilentlyIfNotFinishedYet) [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at Arcen.AIW2.External.ArcenHostOnlySimPlanningContext+<>c__DisplayClass14_0.<RunOnBackgroundThread>b__0 () [0x00000] in <7e6027227b9c4d9695d042e8bf47664e>:0
  at System.Threading.Tasks.Task.InnerInvoke () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.Tasks.Task.Execute () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.Tasks.Task.ExecutionContextCallback (System.Object obj) [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.ExecutionContext.RunInternal (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.ExecutionContext.Run (System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, System.Object state, System.Boolean preserveSyncCtx) [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.Tasks.Task.ExecuteWithThreadLocal (System.Threading.Tasks.Task& currentTaskSlot) [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.Tasks.Task.ExecuteEntry (System.Boolean bPreventDoubleExecution) [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.Tasks.Task.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading.ThreadPoolWorkQueue.Dispatch () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
  at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback () [0x00000] in <695d1cc93cca45069c528c15c9fdd749>:0
TagsNo tags attached.

Activities

BadgerBadger

Nov 15, 2021 11:22 pm

manager   ~0063313

To confirm, this is happening on today's steam build, right? There were some important changes in this code in 3.751

ColdPrototype

Nov 15, 2021 11:27 pm

reporter   ~0063314

Yes.

BadgerBadger

Nov 16, 2021 1:10 am

manager   ~0063316

What factions did you have in the game? A save might be useful if only for reference as to what the game settings were.

ColdPrototype

Nov 16, 2021 1:45 am

reporter   ~0063317

Attached. It occurred twice thus far.
Next.save (735,941 bytes)

Chris_McElligottPark

Nov 16, 2021 9:52 am

administrator   ~0063318

I've been running this save for about 14 minutes so far, and have not seen it. You had said that it is hard to reproduce, however. What is interesting about this one has moved from being super frequent for you, to being something comparably rare.

Ultimately I think that this comes down to me needing to rework how the LRP threads handle pathfinders and caching, which I don't mind because it will also yield some RAM usage benefits. Right now, there are various worker methods that have threadstatic internal variables. I really need to move away from that for a lot of reasons. Instead, what I can do is make it so that the variables are pulled out of a general pool at the start of the LRP process, and then put back in when complete.

Because of the way the contexts are being set up, though, I might not even have to do that -- I might be able to just make these objects live in the context, thus bypassing the need for a pool.

I guess the short version is that this is one of a few places where accidentally-multiple-running threads cause a "oh no" when they should ideally cause a "didn't even notice." This pairs nicely with the goal to keep ram usage from climbing. Because of all the many many background task threads now, I see that it looks like there's about 300-400 MB of RAM that gets used within 20 minutes of play that probably is an excess. It's a fair bet that only will climb over time, despite everything else I've done to stem that.

The good news is that all of these goals converge on a single methodology for code updates, and I've already done the larger bulk of that work from what I can tell (knock on wood).

Chris_McElligottPark

Nov 16, 2021 9:53 am

administrator   ~0063319

(By the time I posted that, I'd been running that save a couple of times for 25 minutes.)

Chris_McElligottPark

Nov 16, 2021 4:42 pm

administrator   ~0063323

Thanks!

* PathCache has been converted to be concurrent-poolable, rather than between-mapgen pooled.
** The idea is that various threads only need these for a while and can give them back.
** Since CacheForPathingMode is a subcomponent of this, it also now has the same behavior as well.
** ...and PathBetweenPlanetsForFaction also gets the same treatment, goodness.
** GetOrAddPathCacheForFactionInThisThread in PathingHelper has been removed, and a new PerFactionPathCache concurrent-poolable object has taken its place.
** This whole rework basically keeps all the logic the same, but makes the "pathfinder didn't finish before it was run again" bug impossible to hit now. Apparently it became more rare in the prior build, but was still possible. Exactly why is hard for me to tell, but it's hard to be sure why.
** The secondary effect of this is that there had been a pretty massive amount of RAM being used for pathfinding cache data, 300MB or so after maybe 20 minutes of play from what I can tell, and it might actually have qualified as a memory leak, temporarily. The number of tracked objects was into the hundreds and climbing. In the same sort of scenario, the number of tracked objects is now... 3. And RAM stays stable.

Issue History

Date Modified Username Field Change
Nov 15, 2021 11:05 pm ColdPrototype New Issue
Nov 15, 2021 11:22 pm BadgerBadger Note Added: 0063313
Nov 15, 2021 11:27 pm ColdPrototype Note Added: 0063314
Nov 16, 2021 1:09 am BadgerBadger Assigned To => Chris_McElligottPark
Nov 16, 2021 1:09 am BadgerBadger Status new => assigned
Nov 16, 2021 1:10 am BadgerBadger Note Added: 0063316
Nov 16, 2021 1:45 am ColdPrototype Note Added: 0063317
Nov 16, 2021 1:45 am ColdPrototype File Added: Next.save
Nov 16, 2021 9:52 am Chris_McElligottPark Note Added: 0063318
Nov 16, 2021 9:53 am Chris_McElligottPark Note Added: 0063319
Nov 16, 2021 4:42 pm Chris_McElligottPark Status assigned => resolved
Nov 16, 2021 4:42 pm Chris_McElligottPark Resolution open => fixed
Nov 16, 2021 4:42 pm Chris_McElligottPark Fixed in Version => Beta 3.752 Pathfinding Efficiency
Nov 16, 2021 4:42 pm Chris_McElligottPark Note Added: 0063323