Fractal Softworks Forum

Please login or register.

Login with username, password and session length
Advanced search  

News:

Starsector 0.97a is out! (02/02/24); New blog post: Simulator Enhancements (03/13/24)

Pages: 1 2 [3] 4 5 ... 7

Author Topic: [Late Game] Battles & Colony Management ruin FPS gradually & permanently.  (Read 16958 times)

Wyvern

  • Admiral
  • *****
  • Posts: 3784
    • View Profile

One possibly-new data point: I got the slowdown to trigger off of not-the-end-of-a-real-battle.  I'm not sure exactly what did it, though, as I was at my colony, tinkering around with variants, so there was a lot of swapping between inventory, fleet, and variant screens - plus a bunch of simulator battles.

(Next game I start I'll turn Vayra's Sector off, just to see if we can eliminate it from the list; my mods list otherwise includes everything in the latest shared batch.  I only run Vayra's Sector for its special bounty mechanics... and y'know, if I really want those unique hulls, I can always use console commands instead.)
Logged
Wyvern is 100% correct about the math.

Alex

  • Administrator
  • Admiral
  • *****
  • Posts: 23986
    • View Profile

Hmm - that might actually be a different issue. IIRC in vanilla there is (a now fixed) issue where it was possible for very large numbers of tooltips to accumulate in the interface without them being visible, and IIRC the refit screen (along with some specific circumstances) was involved here.
Logged

Wyvern

  • Admiral
  • *****
  • Posts: 3784
    • View Profile

Possible!  Same symptom, though - an overall game slowdown that lasted until I restarted the game.  (...Okay, I'll admit, I didn't bother checking to see if the slowdown went away from just backing out to the main menu and then re-loading the save; I've gotten used to that not working.)
Logged
Wyvern is 100% correct about the math.

Ced Riggs

  • Ensign
  • *
  • Posts: 43
    • View Profile



So... is this a leak?

Edit: 15 minutes later, letting it sit for a while, GC seems to have cleaned up some, but not all of them. Performance has recovered from 1 FPS to ~8FPS. At this time Starsector us using 5.6GB out of 7GB assigned.

« Last Edit: August 09, 2020, 01:05:42 AM by Ced Riggs »
Logged

Nick XR

  • Admiral
  • *****
  • Posts: 712
    • View Profile

Great work.

Now you just need to determine what is still rooting those objects.  If you have a heap dump I'd happily take a look at it for you.

Alex

  • Administrator
  • Admiral
  • *****
  • Posts: 23986
    • View Profile

Ah - this is not a leak, though I can see how that could look like one. What you're looking for is the number of instances of "CampaignEngine", exactly - and of those, your screenshots show only one.

CampaignEngine$1, CampaignEngine$2, CampaignEngine$3 etc are different classes - that's how Java names anonymous classes inlined within another class. It's totally fine to have multiple instances of these and does not indicate a memory leak or any other problem. Offhand, the animation for a fleet transitioning to hyperspace is one of these, etc - it's various minor things. So basically, despite the name similarity, these are a completely different thing.


Edit: 15 minutes later, letting it sit for a while, GC seems to have cleaned up some, but not all of them. Performance has recovered from 1 FPS to ~8FPS. At this time Starsector us using 5.6GB out of 7GB assigned.

Hmm, I'd really recommend trying the thread dumps. It looks more and more like a different sort of problem - where it's not leaking a CampaignEngine instance, but instead creating a bunch of... something. Probably some kind of script that gets added many times instead of once and tanks performance.

As far as the 5.6 gb usage - is this the number from jvisualvm in the "Monitor" tab (preferably after pressing the "Perform GC" button there, to get the true memory use), or from task manager? The task manager numbers can be very unreliable and I wouldn't want to draw any conclusions based on that.
Logged

Ced Riggs

  • Ensign
  • *
  • Posts: 43
    • View Profile

5.6GB came from task manager. Nevermind that number then!

I did save my dumps, just in case someone was curious, and also because navigating the Thread dump or finding the GC root has been largely elusive to me. I don't know enough to execute Alex' instructions, since VisualVM seemingly has slightly different menu structure.
  • Heap Dump, ~5 secs after event. (Warning: 3GB)
  • Heap Dump, 15 minutes later. Performance is still impacted. (Warning: 2.5GB)
  • Thread Dump from second time heap dump was made.
Maybe one of y'all can interpret these dumps. :(
Logged

Alex

  • Administrator
  • Admiral
  • *****
  • Posts: 23986
    • View Profile

Looking at the thread dump:

Code
"Thread-4" prio=6 tid=0x0000000019fa8800 nid=0x59cc runnable [0x000000001a87e000]
   java.lang.Thread.State: RUNNABLE
at com.fs.starfarer.settings.StarfarerSettings$1.getCommoditySpec(Unknown Source)
at com.fs.starfarer.campaign.Faction.isIllegal(Unknown Source)
at com.fs.starfarer.campaign.econ.Market.isIllegal(Unknown Source)
at exerelin.campaign.intel.missions.Nex_ProcurementMissionIntel.pickMarket(Nex_ProcurementMissionIntel.java:82)
at com.fs.starfarer.api.impl.campaign.intel.ProcurementMissionIntel.<init>(ProcurementMissionIntel.java:81)
at exerelin.campaign.intel.missions.Nex_ProcurementMissionIntel.<init>(Nex_ProcurementMissionIntel.java:24)
at exerelin.campaign.intel.missions.Nex_ProcurementMissionCreator.createMissionIntel(Nex_ProcurementMissionCreator.java:10)
at com.fs.starfarer.api.impl.campaign.intel.GenericMissionManager.createEvent(GenericMissionManager.java:132)
at com.fs.starfarer.api.impl.campaign.intel.BaseEventManager.advance(BaseEventManager.java:141)
at com.fs.starfarer.campaign.CampaignEngine.advance(Unknown Source)
at com.fs.starfarer.campaign.CampaignState.advance(Unknown Source)
at com.fs.starfarer.BaseGameState.traverse(Unknown Source)
at com.fs.state.AppDriver.begin(Unknown Source)
at com.fs.starfarer.combat.CombatMain.main(Unknown Source)
at com.fs.starfarer.StarfarerLauncher$1.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

Looks like what the game was currently doing is trying to generate a Nex procurement mission - Nex_ProcurementMissionIntel. But, per what I was saying earlier, it's just a snapshot in time - if, say, we had 10 or 20 of these, and half of those show the game doing that, then that would be an indicator that this specific thing is taking a long time to do, since a bunch of random samples all showed it as the "thing currently being done", if that makes sense.

But it being a single snapshot... I mean, it's in some sense an indicator that there might be a problem there, but it's also just one roll of the dice.

As far as generating a thread dump - hmm, looked at some instructions for Visual VM (which is what you have, right?) here:
https://www.infoworld.com/article/2072865/thread-analysis-with-visualvm.html

The relevant thing seems to be:
Quote from: infoworld
The first way to do this is to right-click on the appropriate Java process and select the option "Thread Dump." This will generate a thread dump file whose name appears under the selected Java process as shown in the following screen snapshot.

Another thing you could try is start the CPU sampler in visualvm. I'm not sure exactly what the steps would be for visual vm specifically, but for jvisualvm there's a "sampler" tab where you can press a "CPU" button to begin sampling. It's a more efficient (but probably a bit harder to interpret?) way of doing the same thing, basically. It'll show which methods are taking up the most CPU time by doing sampling (rather than full-on profiling, which is more exact in some circumstances but also bogs the application down by a factor of 10 or more).
Logged

Nick XR

  • Admiral
  • *****
  • Posts: 712
    • View Profile

Another thing you could try is start the CPU sampler in visualvm. I'm not sure exactly what the steps would be for visual vm specifically, but for jvisualvm there's a "sampler" tab where you can press a "CPU" button to begin sampling. It's a more efficient (but probably a bit harder to interpret?) way of doing the same thing, basically. It'll show which methods are taking up the most CPU time by doing sampling (rather than full-on profiling, which is more exact in some circumstances but also bogs the application down by a factor of 10 or more).

FWIW I've tried that whith this issue and any of the high-accuracy options would effectively crash my computer and the low accuracy stuff just pointed to the general game event loop that already has developer instrumentation with a bunch of noise. 

I know this will sound low-tech, but just getting a bunch of stack dumps via CTRL-BREAK (or from visualvm ) and looking at what stuff comes up frequently has worked for me at least 90% of the time historically.

Wyvern

  • Admiral
  • *****
  • Posts: 3784
    • View Profile

So, I have, one, reproduced this issue with Vayra's Sector disabled.

And, two, gotten jvisualvm sampling working.  Unfortunately, it didn't immediately tell me where the problem is; according to sampling, about 50% of the time is going to sound.H$2.run... but further testing shows that that's entirely normal and not symptomatic of performance issues.
Logged
Wyvern is 100% correct about the math.

Alex

  • Administrator
  • Admiral
  • *****
  • Posts: 23986
    • View Profile

Just, worth noting again that your issue could very well be a different one! This time around, did you also spend a bunch of time in refit?

How long did you spend sampling, btw? I woudn't expect  sound.H$2.run to take much time, that's kind of odd - it's the music player which is on a different thread and spends much of its time sleeping. Turning in-game music off should remove it from the picture.
Logged

Wyvern

  • Admiral
  • *****
  • Posts: 3784
    • View Profile

This time was the classic after-a-battle slowdown, not whatever-it-was I reported earlier.  (I mean, okay, -some- time spent in refit, since I basically started a new game and then ran with that until I had problems, but nothing really excessive, and that's not when I started seeing performance issues.)

From what you mentioned, I think the sound.H$2.run thing is just because it is multithreaded - it's spending a lot of time there just because it's in a different thread and there's nothing competing for that CPU.  Good tip on how to turn it off, though; that should make it easier to look through everything else.
Logged
Wyvern is 100% correct about the math.

Alex

  • Administrator
  • Admiral
  • *****
  • Posts: 23986
    • View Profile

Ah, gotcha, thank you for elaborating - this does sound more like the same issue, then. And, yeah, you're probably right about it being a % of that one thread, that makes sense.
Logged

Wyvern

  • Admiral
  • *****
  • Posts: 3784
    • View Profile

Still not definitive, but here's some more data:

Baseline, flying around with no slowdown, I see:
54% of time is in com.fs.starfarer.campaign.CampaignEngine.advance()
35% of time is in org.lwjgl.opengl.Display.update()
7.5% of time is in com.fs.starfarer.campaign.CampaignState.render()

With slowdown, the breakdown is instead:
54% CampaignEngine.advance()
25% Display.update()
14% CampaignState.render()

Hm.  Looks like there's something suspicious under CampaignState.render().  Let's break that down another level.

Baseline, no slowdown:
com.fs.starfarer.campaign.CampaignEngine.render(): 3.2%
com.fs.starfarer.ui.interface.render: 3%
and a few other smaller things make it all round up to 7.5% total for CampaignState.render.

With slowdown:
com.fs.starfarer.ui.interface.render: 8.6%

...Okay, so it looks like whatever the problem is, it's something to do with UI rendering?  (Trying to track the stack traces down further did not, unfortunately, yield any further information or any sort of obvious smoking gun.)

This was, again, a slowdown triggered after end of battle.  Though, with your comment on invisible tooltips hanging around, I'm wondering if there's a way for such a thing to be generated by an end-of-battle collection screen or something?  Looks like I may need to do memory sampling in addition to CPU sampling...  but not tonight.   This morning?  Whichever; I need to get some sleep.
Logged
Wyvern is 100% correct about the math.

Cyan Leader

  • Admiral
  • *****
  • Posts: 718
    • View Profile

I get a lot of slowdowns after a certain point of the game just by going to markets. Hell, even surveying planets take like a 3 seconds longer than usual. While the big battle one also happens, it's not the only source of the problem I feel.
Logged
Pages: 1 2 [3] 4 5 ... 7