Welcome to the Java Programming Forums


The professional, friendly Java community. 21,500 members and growing!


The Java Programming Forums are a community of Java programmers from all around the World. Our members have a wide range of skills and they all have one thing in common: A passion to learn and code Java. We invite beginner Java programmers right through to Java professionals to post here and share your knowledge. Become a part of the community, help others, expand your knowledge of Java and enjoy talking with like minded people. Registration is quick and best of all free. We look forward to meeting you.


>> REGISTER NOW TO START POSTING


Members have full access to the forums. Advertisements are removed for registered users.

Results 1 to 8 of 8

Thread: Execution time varies ridiculously

  1. #1
    Junior Member
    Join Date
    May 2013
    Posts
    3
    Thanks
    0
    Thanked 0 Times in 0 Posts

    Default Execution time varies ridiculously

    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.


  2. #2
    Super Moderator helloworld922's Avatar
    Join Date
    Jun 2009
    Posts
    2,896
    Thanks
    23
    Thanked 619 Times in 561 Posts
    Blog Entries
    18

    Default Re: Execution time varies ridiculously

    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?

  3. #3
    Super Moderator pbrockway2's Avatar
    Join Date
    Jan 2012
    Posts
    1,069
    Thanks
    7
    Thanked 215 Times in 191 Posts

    Default Re: Execution time varies ridiculously

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

  4. #4
    Junior Member
    Join Date
    May 2013
    Posts
    3
    Thanks
    0
    Thanked 0 Times in 0 Posts

    Default Re: Execution time varies ridiculously

    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.

  5. #5
    Super Moderator helloworld922's Avatar
    Join Date
    Jun 2009
    Posts
    2,896
    Thanks
    23
    Thanked 619 Times in 561 Posts
    Blog Entries
    18

    Default Re: Execution time varies ridiculously

    Quote Originally Posted by pbrockway2 View Post
    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.

    Quote Originally Posted by Slimmo View Post
    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.

  6. #6
    Senile Half-Wit Freaky Chris's Avatar
    Join Date
    Mar 2009
    Location
    Wales, Bangor & England, Warwickshire
    Posts
    820
    My Mood
    Cynical
    Thanks
    7
    Thanked 104 Times in 90 Posts

    Default Re: Execution time varies ridiculously

    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.
    chris[at]javaprogrammingforums[dot]com

    Prifysgol Bangor University, North Wales

  7. #7
    Junior Member
    Join Date
    May 2013
    Posts
    3
    Thanks
    0
    Thanked 0 Times in 0 Posts

    Default Re: Execution time varies ridiculously

    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.

  8. #8
    Senile Half-Wit Freaky Chris's Avatar
    Join Date
    Mar 2009
    Location
    Wales, Bangor & England, Warwickshire
    Posts
    820
    My Mood
    Cynical
    Thanks
    7
    Thanked 104 Times in 90 Posts

    Default Re: Execution time varies ridiculously

    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.
    chris[at]javaprogrammingforums[dot]com

    Prifysgol Bangor University, North Wales

Similar Threads

  1. Hello, first time caller long time programmer....
    By P2C2N in forum Member Introductions
    Replies: 3
    Last Post: December 10th, 2012, 11:53 AM
  2. Time taken for execution is more
    By rameshiit19 in forum What's Wrong With My Code?
    Replies: 5
    Last Post: December 6th, 2011, 09:48 AM
  3. java threading execution time question
    By centenial in forum Threads
    Replies: 4
    Last Post: September 9th, 2010, 12:32 AM
  4. Question on dependency execution
    By back2grave in forum Algorithms & Recursion
    Replies: 2
    Last Post: May 2nd, 2010, 01:50 AM
  5. program execution with warnings
    By prince joseph in forum What's Wrong With My Code?
    Replies: 1
    Last Post: March 28th, 2010, 04:53 PM