Game gets slower

Newbie & Debugging Questions
#1

Hey guys
I just finished the basic engine for my game, but the longer I play, the slower it gets. I checked if I create a huge amount of Objects somewhere that blocks the memory but I couldn’t find any. Only some local Variables that should be removed by the GC after the method is finished. Could it be that the GC is too slow?
I have absolut no idea where the problem could be.

Are there some typical noob problems that cause such a behaviour?

Here is the github link if anybody wants to take a deeper look

Any help is appreciated!

#2

If you’re getting intermittent performance spikes, it could be gc. If it’s steady performance degradation, then it’s probably something else (though it could be a memory leak making gc eat 99% CPU).

Run jvisualvm (it comes with the JDK) and attach it to your process. Open the profiler tab and let it run for a while, and it’ll tell you what’s taking the most time.

Also look at the heap usage graphs. If you see a sawtooth pattern in the heap graph, that’s gc working as normal. If it goes up and up and never goes down and the orange area gets thin, that’s a memory leak that’s over-stressing gc and causing your performance problems.

#3

One thing I’ve done in the past to locate a memory leak is to implement the finalize method of particularly large objects and have them print out their last words before they get gc’d. This worked for me because every time I transitioned from room to room in my game, I expected the last room to be gc’d. When one wasn’t, I checked to see what could be hanging on to the room that was also connected to the root of the program. Just kept deleting elements from the room until that finalize method was called. I also forced the gc to run to get more immediate results. I dunno if this will help you, but I just thought I might give you my two cents.

#4

By implementing a finalize method, you interfered with the normal gc process and delayed it by a generation. I guess if you’re requesting gc, then you compensated for it somewhat. Still, the finalizer is not something you want to keep around in production code. If you want to fire off an event when something is gc’d in its normal cycle, you should use a PhantomReference and register it on a ReferenceQueue. With that approach, you can keep the same code in production, just turn off generating the phantomrefs.

If you do that, you’ll probably want to subclass PhantomReference and stick an informative name on the instance when you create it, since there’s no way of getting at the referent (otherwise it would be a Weak/SoftReference, and those delay gc the same as finalizers).

All of this is way too twisty for a beginner: I just recommend using the heap profiler if you see memory not being gc’d, then using the Mk.I Eyeball on the codebase for whatever it tells you is leaking.

#5

Thank you very much. That was exactly what I was looking for.
The heap usage is going up, then the GC comes and it drops a little bit. Then it rises again. So the GC is working but after every run it’s less then after the last.

The profiler says that there is a char[] that takes about 25% of the total memory used. That’s weird, because I never use a char[].Also I get a huge amount of Object[]. I guess it’s used internally by lwjgl or slick. Is there a way to find out where it’s used?

@DrewLols
I never worked with the finalize method. In general, that’s a good idea but in my case I don’t have things like rooms that have to be removed. The whole map is created at the beginning and doesn’t change at all.

#6

char[] is usually the internal storage of String. Permgen tends to have tons of them, but don’t worry about those. The heap profiler in jvisualvm doesn’t always make that obvious, but if you take a heap snapshot, you can use the Eclipse Memory Analyzer Tool on it (it’s a plugin or you can run it standalone) which gives you a much nicer view of things. I’d try to get used to jvisualvm’s output though, since MAT is not exactly fast. I believe jvisualvm can give you some reference hierarchy details on a snapshot too … it’s been a while, I can’t remember.

Object[] is typically the underlying storage of an ArrayList, and again something you need to find the containing object of to be meaningful. Again, either use MAT or visualvm on a snapshot to chase up the reference hierarchy to find out who owns it.

Stick with the top few items. Let it profile for a while, then go with the things that are much too large/numerous and don’t worry about the rest.

#7

This MAT is a neat little tool =)
It showed me that most of the memory goes to the storage of the chunks. That makes sense, because I have 64 of them. They take up 16MB of memory which isn’t that much, right?
The char[] is the input queue of the keyboard.

Then again the weird thing is that it gets slower with the time. (In fact it gets slower, then when the gc runs, a little faster again)
How can I find out what exactly is removed by the gc?

#8

Nothing’s going to tell you exactly what got removed by gc when, but you can turn on verbose GC that tells you how much (and whether it was a full gc or not). If you’re steadily leaking memory, you trigger full gc’s more often as the JVM searches for space, and it has a bigger heap to fruitlessly search every time, and eventually you get OOMEs as the gc thread times out looking for more space. So if your memory usage graph doesn’t eventually trend out to some steady baseline (I wish visualvm had trend lines), your performance will get worse and worse for those reasons.

BTW, profile memory after the program’s run for a few minutes: the JIT takes up a fair chunk of ram itself, but it does get released eventually (you’ll usually see the thread graph drop by 1 at that time).

Anyway, 16 megs of memory total is not a whole lot for chunks, and if that’s not growing, I doubt that’s your problem. If chunk storage is your problem, it could be the way you’re accessing them and have nothing to do with gc.

#9

I made a heap dump closely before the memory peek and another directly after the gc and everything that got removed were some of those char[] and a few HashMap Entries.

All this is really weird. I know that 16MB is not much and I use a single array to store the data in the chunks, so I have constant time to acces the single Blocks inside the chunk. The chunks themself are stored in an ArrayList but there are only 64 of them so this shouldn’t be too bad.

Thanks for your help! If anyone has another idea or took a look at the code and found something, please tell me!

#10

I’m wondering, is it purely a function of how long you play, or is it more about how far you advance into the game?

I’m going to be shallow and just speculate about things that cause slowups without looking at the code.

Some processes just scale badly. For example, if a brute force collision check is used, as the number of objects to be checked grows, the time required to process them will grow exponentially.

#11

At the moment it’s not a real game. It’s only a world where I can walk around. And the longer I walk around, the slower everything gets.
The collision detection takes the Objects in the direct surrounding and only checks them. Afterwards the Objects are cleared again. So this should be the same every cycle too.

#12

Maybe it’s not memory related. Did you do execution time profiling or try printing the number of collision test per update?

#13

[quote]…this should be the same…
[/quote]
Maybe check it. I like Best’s suggestion.

Your description suggests to me that “something” is growing exponentially while you walk around your world. Are you making a map of what your character sees, for example? (I see a reference to a labyrinth.) Maybe a long shot, but if there are algorithms that deal with a progressively larger map, that could cause an exponential growth.

#14

Well this is my collision code:

	public void checkCollision(){
		
		/*
		 * -> get Blocks in question
		 * -> check Collision for every block
		 * -> if true set pos to oldPos
		 * 
		 */
		
		if(currentChunk == null)
			return;
		
		//Get the player coordinates
		int x = (int)Math.floor(this.position.x);
		int y = (int)Math.floor(this.position.y);
		int z = (int)Math.floor(this.position.z);
		y--;
		
		// Get the blocks
		surrounding.add(currentChunk.getBlock(x-1, y+1, z-1));
		surrounding.add(currentChunk.getBlock(x-1, y+1, z));
		surrounding.add(currentChunk.getBlock(x-1, y+1, z+1));
		surrounding.add(currentChunk.getBlock(x, y+1, z-1));
		surrounding.add(currentChunk.getBlock(x, y+1, z));
		surrounding.add(currentChunk.getBlock(x, y+1, z+1));
		surrounding.add(currentChunk.getBlock(x+1, y+1, z-1));
		surrounding.add(currentChunk.getBlock(x+1, y+1, z));
		surrounding.add(currentChunk.getBlock(x+1, y+1, z+1));

		surrounding.add(currentChunk.getBlock(x-1, y+2, z-1));
		surrounding.add(currentChunk.getBlock(x-1, y+2, z));
		surrounding.add(currentChunk.getBlock(x-1, y+2, z+1));
		surrounding.add(currentChunk.getBlock(x, y+2, z-1));
		surrounding.add(currentChunk.getBlock(x, y+2, z));
		surrounding.add(currentChunk.getBlock(x, y+2, z+1));
		surrounding.add(currentChunk.getBlock(x+1, y+2, z-1));
		surrounding.add(currentChunk.getBlock(x+1, y+2, z));
		surrounding.add(currentChunk.getBlock(x+1, y+2, z+1));
		
		//Check collision for every block
		
		boolean collision = false;
		
		for(Block b : surrounding){
			if(b != null && this.getBounds().intersects(b.getBounds())){
				collision = true;
				break;
			}
		}
		
		surrounding.clear();
		
		//Reset position
		
		if(collision){
			this.position.x = oldPos.x;
			this.position.z = oldPos.z;
		}
		
	}

surrounding is a HashSet, so there are at most 18 checks every cycle (I know that this isn’t optimal. I just did this to brute force a basic collision). I clear the Set afterwards so no growth here.

I never intentionally save any data for a longer period so there should be no growth especially no exponential :stuck_out_tongue:
It has to be internally or I oversee something…

EDIT: I just found the source of the huge amount of char[]'s. It’s because I set the title of my window to the current player position every update cycle. I removed it, but it’s still the same problem.
Also the execution time profiling told me that most of the time goes into glCallList. That’s reasonable because I call one list for every chunk, which is 64 lists every update. I probably should find an algorithm for that too. Still I don’t think that this is the reason for the growth. The lists are generated only once in the beginning and then kept in the memory and never touched.

#15 

	long t1 = System.nanoTime();
	Label:{
		if(check_Block(x - 1, y + 1, z - 1)) break Label;
		if(check_Block(x - 1, y + 1, z    )) break Label;
		if(check_Block(x - 1, y + 1, z + 1)) break Label;
		if(check_Block(x    , y + 1, z - 1)) break Label;
		if(check_Block(x    , y + 1, z    )) break Label;
		if(check_Block(x    , y + 1, z + 1)) break Label;
		if(check_Block(x + 1, y + 1, z - 1)) break Label;
		if(check_Block(x + 1, y + 1, z    )) break Label;
		if(check_Block(x + 1, y + 1, z + 1)) break Label;

		if(check_Block(x - 1, y + 2, z - 1)) break Label;
		if(check_Block(x - 1, y + 2, z    )) break Label;
		if(check_Block(x - 1, y + 2, z + 1)) break Label;
		if(check_Block(x    , y + 2, z - 1)) break Label;
		if(check_Block(x    , y + 2, z    )) break Label;
		if(check_Block(x    , y + 2, z + 1)) break Label;
		if(check_Block(x + 1, y + 2, z - 1)) break Label;
		if(check_Block(x + 1, y + 2, z    )) break Label;
		if(check_Block(x + 1, y + 2, z + 1)) break Label;
	}
	long t2 = System.nanoTime();
	System.out.println("Debug Colis time: " + (t2 - t1));/////!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
	
	public boolean check_Block(int x, int y, int z){
		Block b = currentChunk.getBlock(x, y, z);
		if(b != null && this.getBounds().intersects(b.getBounds())){
			this.position.x = oldPos.x;
			this.position.z = oldPos.z;
			return true;
		}
		return false;
	}
#16

Thanks for the code!
I tested it and all values are around 9000. There are some outliers around 28000 and a few even at 40000 but they are rare. That’s not too bad, right?

#17

Yes, problem somewhere else, you need check other main functions, you must look on 100 000ns + that 0.1 ms
In game with 60 fps 1 frame take 15 ms – 15 000 000 ns

If you have random crazy slow down that don’t have direct place that maybe
Java memory manager (GC, allocate more memory)
Its easy to detect: because you have crazy time on simple functions like 1ms+ or so.

#18

You may use something like this


abstract public class D{
	static private long last_Time_N;
	static private long last_Time_M;
	
	static public long T(){
		return System.nanoTime();
	}
	static public void T_Start(){
		last_Time_N = System.nanoTime();
	}
	static public void T_Print(){
		System.out.println(System.nanoTime() - last_Time_N);
	}
	static public void T_Print(String text){
		System.out.println(text + (System.nanoTime() - last_Time_N));
	}
	
	static public long M(){
		return System.currentTimeMillis();
	}
	static public void M_Start(){
		last_Time_M = System.currentTimeMillis();
	}
	static public void M_Print(){
		System.out.println(System.currentTimeMillis() - last_Time_M);
	}
	static public void M_Print(String text){
		System.out.println(text + (System.currentTimeMillis() - last_Time_M));
	}
	
	static public long Mem(){
		Runtime runtime = Runtime.getRuntime();
		return runtime.totalMemory() - runtime.freeMemory();
	}
}

	{//game function
	D.T_Start();
	//code
	D.T_Print("code fifi time : ");
	}
#19

Nice idea. I’ll definitely will include this! Thanks =)

#20

Good stuff, Icecore!

I am reminded of making a similar helper class once. With something like this, you can test the timing metrics of different portions of the game loop, and progressively narrow down the location of the culprit.

Another idea: store a set of baseline readings and then have the code continue to monitor and only alert you if/when the readings drop significantly from the baseline (after playing the game a while). That way you don’t have an overflowing amount of data to sort through.