View Issue Details

Jump to NotesJump to History
IDProjectCategoryDate SubmittedLast Update
0023444AI War 2Gameplay IssueJul 22, 2020 6:41 pmJul 23, 2020 12:24 pm
ReporterGreatYng Assigned ToChris_McElligottPark  
Status resolvedResolutionduplicate 
Product Version2.105 Selection Hotfix 
Fixed in Version2.106 Immortals and Unresponsiveness 
Summary0023444: Movement orders lagged/didn't register before saving no longer worked
DescriptionI don't have any evidence of this on account of the game not saving, but this really happened.
I started this campaign last weekend so it has seen several patches during my time playing.

I noticed movement orders were not always being immediately carried out, or seemingly not carried out at all. I continued playing.
I then decided to save several minutes later, so I could exit the game and do other things for a bit. Upon restarting the game I noticed my new save wasn't there.
Upon reloading the latest autosave/manual save the lag/non-responsiveness I noticed for some units was no longer present. I was playing the game for about 90 minutes straight or more when this happened.
I also kept getting an exception pop-up when saving (autosave or otherwise) which may or may not be related, but I attached it anyway.
TagsNo tags attached.

Relationships

duplicate of 0023439 resolvedChris_McElligottPark Extreme delays in UI 
has duplicate 0023446 resolvedChris_McElligottPark Bug report -- Commands are delayed or not executed 

Activities

GreatYng

Jul 22, 2020 6:41 pm

reporter  

DebugLog.txt (3,410 bytes)    
7/22/2020 9:48:05 PM
Tried to write Int16 NonNeg, but passed value was: -8, which is out of range!  Value set to 0 so your save would work.   (Unknown field being saved)

  at System.Environment.get_StackTrace () [0x00000] in <1f0c1ef1ad524c38bbc5536809c46b48>:0 
  at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.DebugLogDestination Destination, System.Boolean IncludeStackTrace, Arcen.Universal.Verbosity Verbosity) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.DebugLogDestination Destination, Arcen.Universal.Verbosity Verbosity) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.Universal.ArcenDebugging.ArcenDebugLog (System.String Message, Arcen.Universal.Verbosity Verbosity) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.Universal.ArcenSerializationBuffer.AddInt16 (Arcen.Universal.ReadStyle RStyle, System.Int16 Item, System.String FieldNameForErrors) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.AIW2.External.RiskAnalyzerData.SerializeExternalData (System.Object[] Source, Arcen.Universal.ArcenSerializationBuffer Buffer) [0x00000] in <d5ef3c726c0d4a8e959766005f7cc0d4>:0 
  at Arcen.Universal.ArcenExternalData.SerializeTo (Arcen.Universal.ArcenSerializationBuffer Buffer, System.String ExternalDataHeader) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.Universal.ArcenExternalDataLookup.SerializeTo (Arcen.Universal.ArcenSerializationBuffer Buffer, System.String ExternalDataHeader) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.AIW2.Core.Faction.SerializeTo (Arcen.Universal.ArcenSerializationBuffer Buffer) [0x00000] in <a41cc2ea19a54cb58cc3478986c396dc>:0 
  at Arcen.AIW2.Core.World_AIW2.SerializeTo (Arcen.Universal.ArcenSerializationBuffer Buffer) [0x00000] in <a41cc2ea19a54cb58cc3478986c396dc>:0 
  at Arcen.Universal.World.SerializeTo (Arcen.Universal.ArcenSerializationBuffer Buffer) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.Universal.World.SaveWorldToDisk (System.String SaveName, System.Collections.Generic.List`1[T] SavegameMetadata) [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.AIW2.External.GameCommand_SaveGame.Execute (Arcen.AIW2.Core.GameCommand command, Arcen.AIW2.Core.ArcenSimContext context) [0x00000] in <d5ef3c726c0d4a8e959766005f7cc0d4>:0 
  at Arcen.AIW2.Core.GameCommand.Execute (Arcen.AIW2.Core.ArcenSimContext Context) [0x00000] in <a41cc2ea19a54cb58cc3478986c396dc>:0 
  at Arcen.AIW2.Core.World_AIW2.OnClient_ExecuteGameCommandsReceivedFromServer (Arcen.AIW2.Core.ArcenSimContext Context) [0x00000] in <a41cc2ea19a54cb58cc3478986c396dc>:0 
  at Arcen.AIW2.External.SimPlannerImplementation.DoActualSimStep (System.Boolean& stalledWaitingOnConnections, System.Boolean& mayUpdateVisuals) [0x00000] in <d5ef3c726c0d4a8e959766005f7cc0d4>:0 
  at Arcen.AIW2.Core.Engine_AIW2.ProcessSimStep (System.Boolean& stalledWaitingOnConnections) [0x00000] in <a41cc2ea19a54cb58cc3478986c396dc>:0 
  at Arcen.Universal.Engine_Universal.OnUpdateFromMainThread () [0x00000] in <80187922c10b4abea95461ef4430f38a>:0 
  at Arcen.AIW2.Core.ArcenGameControllerBase.BaseUpdate () [0x00000] in <a41cc2ea19a54cb58cc3478986c396dc>:0 
  at ArcenGameController.Update () [0x00000] in <342846c60ad043638e2ec80b42611e65>:0
DebugLog.txt (3,410 bytes)   

Chris_McElligottPark

Jul 22, 2020 6:48 pm

administrator   ~0057794

First thing, from the log, separate from the rest:

* Put in field names for the risk analyzers saving, so if they have trouble serializing we can see which field it was.
** Also then made it so that the total increase and net increase both are automatically clamped to 0 instead of a negative number so that they won't throw an exception when trying to save.

Thanks on that! Will respond to the rest in a moment.

Chris_McElligottPark

Jul 22, 2020 6:51 pm

administrator   ~0057795

I think that what you're seeing is the same issue as 0023439. It's possible that there's a problem with regard to the gamecommands getting clogged up in some fashion; I just recently changed those to queues instead of lists, and there is some protective code that hangs onto certain GameCommands into the future if the intended frame number is wrong. This behavior that you and the others are seeing may be a side effect of that.

Overall the changes I made should have yielded higher performance in the central command processing area, but it seems like there is also a problem with them not being processed correctly under some certain circumstances.

I will investigate in the next couple of hours.

Chris_McElligottPark

Jul 22, 2020 9:57 pm

administrator   ~0057798

Unfortunately, despite instrumenting quite a few things, I can't duplicate the issue. I'm issuing tons of commands, but seeing them all happen properly and they are not getting caught up in the queues. I need to get some sleep, unfortunately, but if there are any methods to reproduce the problem via one of the savegames, then I'm sure I can knock it out quickly in the morning. I simply need a way to actually see the problem happen in a reasonable amount of time with some save, and then I can knock it out. I've tried 5+ minutes of rapid clicking and looking at things in battle and moving between planets, and I can't get anything to even slightly leak right now.

Chris_McElligottPark

Jul 23, 2020 12:24 pm

administrator   ~0057813

Thanks!

* Fixed a bug where it was possible that a client would send more commands to the host than it would tell the host about, and thus the host would not know to read the extra ones (or vice-versa). In single-player you are both the host and client, so it still applies.
** This was happening because of multiple threads adding to the queues of commands at the same time that the queue was being drawn down.
** This was actually something that probably could have happened since more or less forever, but it was substantially more likely in the last few versions because of some efficiency improvements we made.
** Additionally, we have now switched to using a ConcurrentQueue for each of those collections, rather than a regular Queue. This shoudl also help with potential contention.
** There was also the possibility that we might not be able to get enough commands out of the list for some reason to then send more, and we are also now guarding against that.
** Previously, this problem was manifesting as orders not being carried out when you gave them, sometimes or all the time. And things like "save my game" and "pause or unpause" not working anymore.
** We were able to duplicate this in one savegame after some time, but no longer can. Given the intermittent nature of this sort of thing, we can't say for sure that it is solved -- but the logic of what was going on makes sense, and the fix we put in should hold that at bay. It's one of those "can't prove a negative" things, at the moment, so fingers crossed it just never shows up again.
** The characteristics that we observed while this happens, if it happens to you and you want to see what you can tell us:
*** In the escape menu, under the memory pooling performance, the number of raw commands were steadily climbing. One or two every few seconds. This should never happen in that way. Increases happen, but not a steady drain flow like that.
*** In the escape menu, further down under the Commands Queued By Type, you may see some null warnings up at the top of that list, now. That wasn't there when we observed it, but it would be if it ever happened now.

Issue History

Date Modified Username Field Change
Jul 22, 2020 6:41 pm GreatYng New Issue
Jul 22, 2020 6:41 pm GreatYng File Added: DebugLog.txt
Jul 22, 2020 6:48 pm Chris_McElligottPark Note Added: 0057794
Jul 22, 2020 6:48 pm Chris_McElligottPark Assigned To => Chris_McElligottPark
Jul 22, 2020 6:48 pm Chris_McElligottPark Status new => assigned
Jul 22, 2020 6:49 pm Chris_McElligottPark Relationship added duplicate of 0023439
Jul 22, 2020 6:51 pm Chris_McElligottPark Note Added: 0057795
Jul 22, 2020 9:37 pm Chris_McElligottPark Relationship added has duplicate 0023446
Jul 22, 2020 9:57 pm Chris_McElligottPark Note Added: 0057798
Jul 23, 2020 12:24 pm Chris_McElligottPark Status assigned => resolved
Jul 23, 2020 12:24 pm Chris_McElligottPark Resolution open => duplicate
Jul 23, 2020 12:24 pm Chris_McElligottPark Fixed in Version => 2.106 Immortals and Unresponsiveness
Jul 23, 2020 12:24 pm Chris_McElligottPark Note Added: 0057813