Weird update loop burst behavior

A video is uploading showing the weirdness… Please be patient. :wink: I’ll put the link when it’s done processing.



So, in the solar system scene on the screen things are updating in a weird way. The scene is “simple” You have planets that rotate around a sun and moon(s) that rotate around planets. But, as the scene gets rendered, you see the FPS go from its “max” then slowly comes down, then goes back to “max”. You’ll see in the video what it looks like. It’s like things are sped up in fast-forward for a second or two.



In the AppSettings I had set it up to a maximum of 500 FPS. Completely removing that didn’t change anything. The update loops are pretty simple too. Nothing fancy really, just a node and spatial rotation going on.



At this point I’m wondering if the GC isn’t screwing things up. That’s my guess at this point.



Here’s the two loops that are run while in a SolarSystemScene.



SolarSystemScene.java

[java]



@Override

public void update(float tpf) {

for (GameNode n : planetSystemNodeList) {

rotateSpatial(n);

}



for (Spatial s : sceneNode.getChildren()) {

rotateSpatial(s);

}

super.update(tpf);

}



private void rotateSpatial(Spatial spatial) {

if (spatial instanceof Geometry) {

// rotate spatials

float rotation = 0;

try {

rotation = spatial.getUserData(“RotationPeriod”);

} catch (Exception e) {

if (e instanceof NullPointerException) {

}

}

if (rotation > 0) {

spatial.rotate(0, 0, 1f / rotation / GameConstants.SECONDS_PER_DAY);

}

} else if (spatial instanceof GameNode) {

GameNode node = (GameNode) spatial;



if (node.getUserData(“OrbitalPeriod”) != null) {

float rotation = node.getUserData(“OrbitalPeriod”);

node.rotate(0, 1f / rotation / GameConstants.SECONDS_PER_DAY, 0);

for (Spatial sp : node.getChildren()) {

rotateSpatial(sp);

}

}

}

}

[/java]



All scenes are extending my game’s Scene.java. Here’s the update loop.

[java]

@Override

public void update(float tpf) {

// Only run if no menu is opened

if (!gMgrs.getGameState().getIsMenuOpen()) {

updateShipMoving(tpf);

}



sceneNode.updateLogicalState(tpf);

sceneNode.updateGeometricState();

}

[/java]



Except for the garbage collector, I’m at a loss to explain that behavior. Anyone has a suggestion or something to offer? I guess in the worst case scenario I could force a maximum of 60 FPS, but that’s something I’d rather avoid, although I guess it shouldn’t make a difference. Maybe I should use a proper timer so the rotation isn’t done more than X times per seconds? Hmm. Yeah, I think that would be the solution. Still I’m interested in knowing what the thoughts on this is.



Thanks.



Oh and here’s the video:

http://www.youtube.com/watch?v=XZb6_53mk50



It might be a bit hard to notice on the first play through though.

You are using tpf to determine rotation amount, right? If so, fps shouldn’t impact speed. I don’t know why your FPS is changing though.

1 Like

Ah right. tpf. It probably got discarded when I made my big changes. Things are much better thanks to you @kidneytrader, but there still some stuttering happening.



I’ll run some tests and see how that goes. I’m wondering if this is caused by texture caching/loading since it seems to happen at the loading phase the first time a SolarSystemScene is done. Alternatively I could cache all the needed textures when the game loads. Hmmm.



At this point it doesn’t matter that much, most of the hiccups seem to be gone.



Thanks.

Does the fps “normalize” after a while or keeps changing?

Can you maybe check the CPU/Memory/IO usage over time to see if maybe something is going on?

Another thing it could be is the graphics driver

I’ve just ran the game a couple of times and it seems to be timed somewhat… Happens about every 4 seconds…



CPU usage seems to be stable around 14-16 percent.

Memory usage seems to go up and down quite a lot although not by a lot. Around 6225 GB to 6330 GB, so a differential of about 100 MB being allocated and deallocated but that is constant. Goes up for about 2/3 second then down. This might be the problem.



The game isn’t doing anything though. It’s just sitting there, camera isn’t moving. It doesn’t even have the focus. With the focus on the game, there’s no change.



The obvious thing I can see though is the FPS. It goes from ~230 FPS down to ~95 then goes back up.

FPS dips seem to be timed with stuttering.



@Momoko_fan

Sorry I didn’t answer your question. No, it doesn’t normalize. When I left it run for almost 15 mins it still was doing it.

isn’t tpf the frametime from last frame? if framerate is constantly slowing down it would always rotated a bit wrong am i false? over the time this probably sums up.

It could be the garbage collection. 100 MB could actually be a lot of small objects to collect. I suggest you profile your garbage collection to make sure the issue is not there.



Also there was a few memory churn issues fixed in one of the recent nightly builds, you may want to update if you haven’t yet and see if that helps.

EmpirePhoenix said:
isn't tpf the frametime from last frame? if framerate is constantly slowing down it would always rotated a bit wrong am i false? over the time this probably sums up.

The FPS slows down but it doesn't last more than 2-3 seconds. It goes back up as soon as, it seems, the gc has done its thing. As far as the "wrong" rotation the only effect the TPF will do, at least afaik, is slow/accelerate the rotation as I use it as a modifier (1f / rotation / scale * tpf) If there is some visual distortion, it's invisible to my eyes. I might be able to see it if I were, for example, tracing the object's path. If I see something going on that looks like path distortion I will definitively path it to check it out, but short of that, I'll keep it that way.

Momoko_Fan said:
It could be the garbage collection. 100 MB could actually be a lot of small objects to collect. I suggest you profile your garbage collection to make sure the issue is not there.

Also there was a few memory churn issues fixed in one of the recent nightly builds, you may want to update if you haven't yet and see if that helps.

1 - I'll check what profiling has to say. I have to admit I'm pretty clueless as to how the gc works except for the obvious. I also have to say that this is beyond weird to me. I would get it if there was activity going on, textures churning in/out, fields and methods being called all over the place but it's not so. I use 1 class global variable (the scene "rootNode") inside the update method and that's it. The rest is stuff that is already set inside the classes and shouldn't be swapped in/out of memory. I'm sure there's something obvious I'm not getting here.

2 - I keep my jME updated daily (sometimes several times daily), but I don't remember when was the last time I rebuild the whole thing. Maybe a couple/three days ago...

I'll rebuild and see if there's any improvement.
Then I'll run profiling and see how that goes.

I'll repost later (or tomorrow) with the results.

I was thinking the issue could be in your code. But if you say its all jME3 then its harder to do that

Every 3-4 seconds would sound a lot like GPU. You can turn on verbose GC logging to see it. When I run mythruna with default JVM memory settings I can see this freeze every three seconds as a full GC is run.



Just for fun… I’m assuming you are using a nifty GUI. Is there some way that you can test with it disabled it and see if things improve greatly? I don’t expect it to but there is reallocation going on there. And it’s per-frame so maybe it could grow pretty quickly at high frame rates.

@Momoko_Fan

Rebuilding didn’t fix the problem. Same result. The only thing running in the update loops are what are the snippets in the first post, nothing else.



@pspeed

Yeah, I use Nifty. Disabling Nifty will take a lot of commenting. :confused: I’ll check up on that, it shouldn’t be too bad. Hopefully…



As for the GPU, you’re losing me. I didn’t know the GC was the one triggering the GPU’s garbage collection, or is there something I’m misunderstanding? So how did you fix that problem with Mythruna? Increased the XMS? As I said, I’m pretty noob when it comes to the GC. :smiley:

I mistyped. I meant GC.

Yes, I increased -Xmx to 1024m… but depending on what is churning you may need to up the direct memory as well.



But you can try -Xmx1024m and see what that does.

And if you want to see what GC is doing, you can put:

-verbose:gc -Xloggc:gc.log -XX:+PrintGCTimeStamps



On your command line near where you’d but -Xmx, etc.

Ok… Ran the profiler and this thing is scary to look at in Live mode. 8O



From what I have seen the Moon class is what is taking the most memory, but, the number of allocated object is stable once the whole galaxy has been generated with the solar systems. The same goes for Planet, SolarSystem, etc.



Now, the things that goes up and down constantly are:



java.util.HashMap$Entry

java.lang.Float

java.util.HashMap$Entry[]

java.lang.Object

java.util.HashMap

java.util.ArrayList



Those classes are the worst. I only use HashMap at one place and it’s used during solar systems generation and it holds the atmosphere gases for each object (if applicable). They’re pretty much static (not in the pure static sense) once they’re done. So this is not my doing.



As Paul suggested I think Nifty is the culprit here. I don’t see what else could generate those.



Now, cranking up the Xmx to 1024 greatly helped. There is still a slightly noticeable hitch though, but you have to be zoomed-in to really notice it and it’s worse with moons that orbit their planet rapidly.



The problem here is what do I do with that? Do I ditch Nifty and make a GUI of my own? Are there alternatives? Can that be fixed in Nifty itself? Or do I crank Xmx even higher possibly ditching possible customers?



To make sure I will do as Paul suggested and remove the game’s HUD once the game has been started. I’d hate myself to think it was Nifty when it was not. :confused:

Yeah, test it. Don’t take my word for it as I was just guessing. Any number of things can create hashmap entries, Floats, etc. for all sorts of reasons. And the jme-nifty related reallocation isn’t hashmap related, as I recall. Though if you really have churn in HashMap and ArrayList creation that’s an issue… but otherwise, you will have quite a lot of those but I’d expect them to be stable.



I’d think the profiler should be able to tell you where they are coming from.

This will have to wait until tomorrow though. I’m spent for the day. Be sure to tune in and see the result! :wink:



Before I forget, I tried to use the profiler to check where those calls were coming from but my noobness made it so that I couldn’t do it. I’ll delve deeper into that tomorrow too.

The world of profilers is a scary and magical place.

Results!



Commenting out Nifty made things sailing on a silk-smooth sea. Now the huge question is, wtf do I do to fix that? If it can be fixed… It also seems Nifty is responsible for the FPS drop. Without nifty, I’m pretty much at 499 FPS all the time. With it, I get around 230-300 depending on the scene but as before, the thing goes up/down.



In short, Nifty has a definite and major impact on the game and I’m having a hard time with this.