Execution time varies ridiculously

**Slimmo** · May 7th, 2013, 10:40 PM

Hello,

I've been looking to optimize my code because it's not working as fast as I would like it to and I've found something weird. I tried to use a profiler to pinpoint the slow parts of my code but with visualvm in Eclipse I get internal errors so it doesn't run. Instead I just print out a bunch of System.nanoTime()'s to console, paste that into a text file and have a separate java program read them in and show me the slow parts. Not elegant I know but it works.

So here's a code snippet to show the problem where ty and tx are both ints between 0 and 15 inclusive, and cellMap is a 16x16 int array within that object.

...
System.out.print("TIME ty " + System.nanoTime());
cellMap[ty][tx] = 0;
System.out.print("TIME startswitch " + System.nanoTime());
...

This is a typical output from this
ty 1367974976386656000TIME startswitch 1367974976386676000
so it only takes 20,000 nanoseconds which is fine.

This is a ridiculous output from this
ty 1367974977431169000TIME startswitch 1367974977468862000
this version takes 37,693,000 nanoseconds... for just that code snippet...

This isn't an isolated case, every time I run this program there's at least one ridiculous result but it moves around and in consecutive runs, usually won't be in the same spot.

I do have two threads running but I doubt it would swap away from a thread for that long at a time would it? I used two threads to try and get them going simultaneously instead of swapping from one to the other, have I done something wrong here?

How can I further diagnose what's going on?

Any help would be greatly appreciated, thanks.

**helloworld922** · May 7th, 2013, 11:32 PM

Micro-benchmarking Java is tricky at best. The problem is the runtime layer which does an awful lot of work to get your program to run. There are also a lot of issues with modern computers which do a lot of work in the background.

There are a few "tricks" you can do to get accurate timings:

1. Take lots of samples. This is actually important for any experiment. The median of the samples is generally a good representation of what performance to expect as it effectively handles outliers.

2. Test with longer samples. In general, samples in the range of milliseconds or longer are preferable. The idea is that the effects of small variants of all the background work is smaller compared to the actual work you're interested in. A good way to do this is to run your test code multiple times, time the sum period, and divide by the number of times the test code was run.

start_time = System.nanoTime();
for(int i = 0; i < 16; ++i)
{
    doTest();
}
end_time = System.nanoTime();

Some more tips: How do I write a correct micro-benchmark in Java?

**pbrockway2** · May 7th, 2013, 11:51 PM

37 million isn't much... if you're Bill Gates! Isn't the time resolution on Windoze about 15 million ns?

**Slimmo** · May 8th, 2013, 01:09 AM

I just did another test of 115,000 timings of a different function and there are 10 in the 10's of millions (with the largest being 56,528,000), 37 in the millions, 155 in the hundreds of thousands etc etc. On the flip side though the whole bottom 1% is either 2000ns or 3000ns... Not sure how that's working so quickly though.

Having said that the average is 9805ns.
If I remove the top and bottom 1%, the longest runtime is 39,000 which results in a new average of 5999ns.

Still those extra long ones are killing me... I'm building a game tree in real time so those spikes aren't exactly ideal. Is there a way to mitigate them if I can't get rid of them completely or do I just have to deal with it?

Thanks.

**helloworld922** · May 8th, 2013, 12:27 PM

Originally Posted by pbrockway2

37 million isn't much... if you're Bill Gates! Isn't the time resolution on Windoze about 15 million ns?

In relatively recent versions of Windows, no (I think starting with XP, definitely in Vista). Older versions had timer resolutions on the order of ~10ms, but newer Windows have a standard resolution of ~1ms. There's also a performance counter in the sub-microsecond resolution (depending on CPU frequency) which is used by Java's nanoTime if available. My computer has a resolution of ~450ns.

Originally Posted by Slimmo

I just did another test of 115,000 timings of a different function and there are 10 in the 10's of millions (with the largest being 56,528,000), 37 in the millions, 155 in the hundreds of thousands etc etc. On the flip side though the whole bottom 1% is either 2000ns or 3000ns... Not sure how that's working so quickly though.

Having said that the average is 9805ns.
If I remove the top and bottom 1%, the longest runtime is 39,000 which results in a new average of 5999ns.

Still those extra long ones are killing me... I'm building a game tree in real time so those spikes aren't exactly ideal. Is there a way to mitigate them if I can't get rid of them completely or do I just have to deal with it?

Thanks.

I would suggest trying to make each timing period longer still. 39000ns / 450ns = ~87 steps. 5999ns/450ns = ~13 steps, so relatively small irregularities in other processes can drastically effect your timings.

Without looking closer at the code it's difficult to figure out what's going on and whether there's some intrinsic problem with the code, a problem with how your timing setup, or problems with the underlying system.

**Freaky Chris** · May 9th, 2013, 02:53 AM

Another possible point to consider is the state of the JVM. From what I can gather it sounds like you are running a fairly large application with many timings, and along side that it looks like you are doing a lot of object creation and freeing. If this is the case, you might find that the GC is kicking in, as it gets scheduled and then runs pretty much whenever it can be bother (regardless of what is it supposed to do). This could lead to some of you larger spikes if this is the case as the GC is a power hungry monster!

This seems like it is unlikely, but I've had this be a problem in the past and sometimes I have forced GC prior to key execution points to clear this. This allows the moving of the GC to a fixed point in execution to ensure that critically intensive portions don't get bogged down.

**Slimmo** · May 9th, 2013, 03:57 AM

That could be it. I am pruning the tree quite heavily because the branching factor is pretty high (purposefully). I have no idea how to check if it actually is the GC that's causing this but I'll look into it, I'm sure you can do it somehow, thanks. It does seem to be a crazy amount of processing time still to just GC though... If it is, I regret the choice of Java

.

And yeah, this is for my thesis and atm it's ~2500 lines of code so I'm not sure how helpful posting any code would be.

**Freaky Chris** · May 9th, 2013, 04:09 AM

If you can run this in NetBeans if you run it through the NetBeans profiler you will be able to see when the GC gets called by the massive change in allocated memory etc. You can also manually invoike the GC whenever you like whilst in profiler mode just with the click of a button.

2.5k Lines isn't that bad.

I did my Theses in MATLAB, with C implementations of algorithms for even more enhanced speed. It still took me 4 hours on a 4 core AMD running at 4.2GHz to compute my results. Generating well into the 100s of MB of data!

At the end of the day Java is a fast language, and you shouldn't have any serious issues with this.

Thread: Execution time varies ridiculously

LinkBack

Thread Tools

Display

Execution time varies ridiculously

Related threads:

Re: Execution time varies ridiculously

Re: Execution time varies ridiculously

Re: Execution time varies ridiculously

Re: Execution time varies ridiculously

Re: Execution time varies ridiculously

Re: Execution time varies ridiculously

Re: Execution time varies ridiculously

Similar Threads

Hello, first time caller long time programmer....

Time taken for execution is more

java threading execution time question

Question on dependency execution

program execution with warnings