Java-Gaming.org    
Featured games (81)
games approved by the League of Dukes
Games in Showcase (494)
Games in Android Showcase (114)
games submitted by our members
Games in WIP (563)
games currently in development
News: Read the Java Gaming Resources, or peek at the official Java tutorials
 
    Home     Help   Search   Login   Register   
Pages: [1]
  ignore  |  Print  
  Profiling and optimising - convenience class  (Read 2298 times)
0 Members and 1 Guest are viewing this topic.
Offline CommanderKeith
« Posted 2010-03-31 12:30:14 »

Hi,

I often use the -Xprof virtual machine option to profile and optimise, but it has limitations. For example it can't profile code within a method, it only records time spent in methods.

A while back Riven suggested a clever way to profile using System.nanoTime(), which adjusted for the expense of calling nanoTime(). This worked well, and here I've put it in a class. It handles all of the time adjustments and console outputs in a neat way.

Usage:
1  
2  
3  
4  
5  
6  
7  
8  
9  
10  
static CodeTimer  codeTimer = new CodeTimer();
public void calc(){
   codeTimer.click();
   // do calculations
  longCalc();
   codeTimer.click();
   // do more calculations
  longerCalc();
   codeTimer.lastClick();
 }

Once every 5 seconds the call to codeTimer.lastClick() will print the average time taken from the first click() to the lastClick(). By default the proportion of the time spent between clicks will also be printed to System.out.

It's meant for use in a running game loop. There are setter methods to change the output and other stuff. You can also disable it by calling codeTimer.setEnabled(false).

I hope it comes in handy. Big thanks to Riven for having the idea  Cool  Any comments welcome.

Keith

EDIT: See reply number 9 for the latest source code:
http://www.java-gaming.org/topics/profiling-and-optimising-convenience-class/22175/msg/183456/view.html#msg183456

Offline CommanderKeith
« Reply #1 - Posted 2010-03-31 12:33:02 »

This tests how accurate the CodeTimer is compared to manually timing the code using System.nanoTime(). Run the main method to test.

1  
2  
3  
4  
5  
6  
7  
8  
9  
10  
11  
12  
13  
14  
15  
16  
17  
18  
19  
20  
21  
22  
23  
24  
25  
26  
27  
28  
29  
30  
31  
32  
33  
34  
35  
36  
37  
38  
39  
40  
41  
42  
43  
44  
45  
46  
47  
48  
49  
50  
51  
52  
53  
54  
55  
56  
57  
58  
59  
60  
61  
62  
63  
64  
65  
66  
67  
68  
69  
70  
71  
72  
73  
74  
75  
76  
77  
78  
79  
80  
81  
82  
83  
84  
85  
86  
87  
88  
89  
90  
91  
92  
93  
94  
95  
96  
97  
98  
99  
100  
101  
102  
103  
104  
105  
106  
107  
108  
109  
110  
111  
112  
113  
114  
115  
116  
117  
118  
119  
120  
121  
122  
123  
124  
125  
126  
127  
128  
129  
130  
131  
import static CodeTimer.*;
import java.text.DecimalFormat;
import java.util.*;

/**
 *
 * @author Keith
 */

public class CodeTimerTest {
   public static void main(String[] args){
      // Test to see if the manual profiling method using System.nanoTime()'s gives
     // the same results as the convenience class CodeTimer.
     // The first test does manual profiling and prints the results,
     // the second test uses the CodeTimer.
     long testRunningTimeNanos = 11*NANOS_IN_A_SECOND;   // run each test for 11 seconds.

      Random random = new Random(0);
      // warm the JIT compiler
     for (int i = 0; i < 1024; i++){
         float randomAngle = random.nextFloat();
         long t0 = System.nanoTime();
         // the calculation being timed:
        double sine = Math.sin(randomAngle);
         double cosine = Math.cos(randomAngle+1);
         double tan = Math.tan(randomAngle+2);
         double calc = Math.sqrt(Math.pow(Math.pow(sine, cosine), tan));
         long t1 = System.nanoTime();
      }

      System.out.println(CodeTimer.class.getSimpleName()+": starting test 1.");
      long startNanos = System.nanoTime();
      random = new Random(0);
      long nanoSelfTime = calibrateNanoTime(10000);
      System.out.println(CodeTimer.class.getSimpleName()+": System.nanoTime() selfTime == "+nanoSelfTime);
      long totalNanos = 0;
      double lastPrintOutNanos = System.nanoTime();
      float maxSecondsBeforePrintOut = 5;
      long count = 0;
      while (true){
         float randomAngle = random.nextFloat();
         long t0 = System.nanoTime();
         // the calculation being timed:
        double sine = Math.sin(randomAngle);
         double cosine = Math.cos(randomAngle+1);
         double tan = Math.tan(randomAngle+2);
         double calc = Math.sqrt(Math.pow(Math.pow(sine, cosine), tan));
         long t1 = System.nanoTime();
         totalNanos += t1 - t0 - nanoSelfTime;
         count++;
         if (System.nanoTime() - lastPrintOutNanos > maxSecondsBeforePrintOut*NANOS_IN_A_SECOND){
            double avTotalNanos = (double)totalNanos/(count);
            System.out.println(CodeTimer.class.getSimpleName()+": avTotalNanos == "+decimalFormat.format(avTotalNanos));
            totalNanos = 0;
            count = 0;
            lastPrintOutNanos = System.nanoTime();
         }
         if (System.nanoTime() - startNanos > testRunningTimeNanos){
            break;
         }
      }

      System.out.println(CodeTimer.class.getSimpleName()+": starting test 2.");
      startNanos = System.nanoTime();
      random = new Random(1000);
      CodeTimer codeTimer = new CodeTimer(NANOS, false, NONE);
      System.out.println(CodeTimer.class.getSimpleName()+": CodeTimer.SELF_TIME == "+CodeTimer.SELF_TIME);
      while (true){
         float randomAngle = random.nextFloat();
         codeTimer.click();
         // the calculation being timed:
        double sine = Math.sin(randomAngle);
         double cosine = Math.cos(randomAngle+1);
         double tan = Math.tan(randomAngle+2);
         double calc = Math.sqrt(Math.pow(Math.pow(sine, cosine), tan));
         codeTimer.lastClick();

         if (System.nanoTime() - startNanos > testRunningTimeNanos){
            break;
         }
      }
      System.out.println(CodeTimer.class.getSimpleName()+": finished.");

   }

   // This is only used in the testing of the manual method.
  protected static long calibrateNanoTime(int numTests){
      boolean print = false;
      // warm the JIT
     for(int i=0; i<1024; i++){
         System.nanoTime();
      }

      // find how out long it takes to call click(), so that time can be accounted for
     ArrayList<Long> selfTimeObservations = new ArrayList<Long>(numTests);
      for (int i = 0; i < numTests; i++){
         long nanoSelfTime = -(System.nanoTime() - System.nanoTime());
         if (print){
            System.out.println(CodeTimer.class.getSimpleName()+": nanoSelfTime == "+nanoSelfTime);
         }
         selfTimeObservations.add(nanoSelfTime);
      }
      // sort the times
     Collections.sort(selfTimeObservations);
      if (print){
         for (int i = 0; i < selfTimeObservations.size(); i++){
            System.out.println(CodeTimer.class.getSimpleName()+": selfTimeObservations.get(i) == "+selfTimeObservations.get(i));
         }
      }
      // cut out the slowest 5% which are assumed to be outliers
     for (int i = 0; i < (int)(numTests*0.05); i++){
         selfTimeObservations.remove(0);
      }
      // cut out the fastest 5% which are assumed to be outliers
     for (int i = 0; i < (int)(numTests*0.05); i++){
         selfTimeObservations.remove(selfTimeObservations.size()-1);
      }
      if (print){
         System.out.println(CodeTimer.class.getSimpleName()+": Slimmed list: selfTimeObservations.size() == "+selfTimeObservations.size());
         for (int i = 0; i < selfTimeObservations.size(); i++){
            System.out.println(CodeTimer.class.getSimpleName()+": selfTimeObservations.get(i) == "+selfTimeObservations.get(i));
         }
      }
      // find the average
     long sumOfSelfTimes = 0;
      for (int i = 0; i < selfTimeObservations.size(); i++){
         sumOfSelfTimes += selfTimeObservations.get(i);
      }
      long nanoSelfTime = sumOfSelfTimes/selfTimeObservations.size();
      return nanoSelfTime;
   }
}


This was my output on Windows Vista, java 6 update 17:

CodeTimer: starting test 1.
CodeTimer: System.nanoTime() selfTime == 1381
CodeTimer: avTotalNanos == 1,276.9695         <--- 1st manual method measurement of average nanoseconds to do the calc's
CodeTimer: avTotalNanos == 1,253.9743         <--- 2nd manual method measurement of average nanoseconds to do the calc's
CodeTimer: starting test 2.
CodeTimer: CodeTimer.SELF_TIME == 1375
CodeTimer: avTotalNanos == 1,270.8229         <--- 1st convenience class measurement of average nanoseconds to do the calc's
CodeTimer: avTotalNanos == 1,260.9276         <--- 2nd convenience class measurement of average nanoseconds to do the calc's
CodeTimer: finished.

Which shows that the manual method and the convenience class give pretty similar results. Phew!

Offline ryanm

Senior Member


Projects: 1
Exp: 15 years


Used to be bleb


« Reply #2 - Posted 2010-04-02 14:54:52 »

A lovely bit of code, very convenient! Cheers for sharing!
I've taken the liberty of making it slightly more convenient, but probably at the expense of subtly breaking it somehow.
  • click() takes a string argument that makes it easier to relate the output to sections of code
  • A lastClick( boolean print ) method that lets you specify that you want output immediately. I'm using it to measure my init code and dumping the output before using the same timer to measure the main loop
My version is over here.
Games published by our own members! Check 'em out!
Legends of Yore - The Casual Retro Roguelike
Offline CommanderKeith
« Reply #3 - Posted 2010-04-02 15:21:22 »

Great, I'm glad you find it useful! I like your adjustments, very neat. but I'm going to have to figure out enums again!

The string idea is very good, nice one  Cool

It would be good if the click could spit out the line of code where it is - but it seems Thread.dumpStack() is the only way to print that info and it's obviously too verbose.

I tried using this thing to measure the time spent in a method used by a bullet in my game and the damn thing didn't work! Then I realised that it's because the bullet never survived long enough (5 seconds) to print anything... so i made the CodeTimer static, rather than having one instance per bullet instance and it worked a treat.

By the way, if you can think of a better name for the class I'm all ears, you have a way with words  Smiley


Offline pjt33
« Reply #4 - Posted 2010-04-02 15:26:00 »

I just use VisualVM. It's not perfect, but it gives you a reasonable idea of what's going on.
Offline CommanderKeith
« Reply #5 - Posted 2010-04-02 15:36:04 »

Yes it's a great tool. I often use the NetBeans profiler which uses the same mechanism as VisualVM under the hood AFAIK.

It's really handy for tracking memory usage and leaks and finding problematic garbage collection pauses. I really like the snap-shot memory tool where you can look at the stack traces and number of created vs live objects etc.

But for CPU performance profiling I don't think it's very good. Its results were very different compared to using the -Xprof VM option. The Netbeans profiler over-estimated the time spent in small methods compared to -Xprof. Have you compared the results of VisualVM to -Xprof?



Offline ryanm

Senior Member


Projects: 1
Exp: 15 years


Used to be bleb


« Reply #6 - Posted 2010-04-02 15:43:03 »

By the way, if you can think of a better name for the class I'm all ears, you have a way with words  Smiley
I do? Aw shucks Wink CodeTimer sounds fine to me.

VisualVM's CPU profiler absolutely destroys performance for me, i.e. from ~60 frames per second to ~5 seconds (wildly unstable) per frame. It's great for heap/stack inspections though.
Offline pjt33
« Reply #7 - Posted 2010-04-02 19:58:10 »

Have you compared the results of VisualVM to -Xprof?
Yes. I was simplifying slightly: I actually use both of them and compare the results.
Offline CommanderKeith
« Reply #8 - Posted 2010-04-04 07:28:25 »

Hi Ryan,

I switched over to your code to make use of the great click(String) feature.

A small error that I found was that the method lastClick() called System.nanoTime() before calling click(). That System.nanoTime() was not accounted for so the last interval was being over-estimated. The below code fixes it.

I also changed the printing code a little so that the console output is aligned when there are long click names.

Thanks for posting up your code up, it's great the way we can help each other like this.

Keith

1  
2  
3  
4  
5  
6  
7  
8  
9  
10  
11  
12  
13  
14  
15  
16  
17  
18  
19  
20  
21  
22  
23  
24  
25  
26  
27  
28  
29  
30  
31  
32  
33  
34  
35  
36  
37  
38  
39  
40  
41  
42  
43  
44  
45  
46  
47  
48  
49  
50  
51  
52  
53  
54  
55  
56  
57  
58  
59  
60  
61  
62  
63  
64  
65  
66  
67  
68  
69  
70  
71  
72  
73  
74  
75  
76  
77  
78  
79  
80  
81  
82  
83  
84  
85  
86  
87  
88  
89  
90  
91  
92  
93  
94  
95  
96  
97  
98  
99  
100  
101  
102  
103  
104  
105  
106  
107  
108  
109  
110  
111  
112  
113  
114  
115  
116  
117  
118  
119  
120  
121  
   /**
    * Call to end a profiling period, and print the results if
    * {@link #printFrequencySeconds} have passed since we last printed
    */

   public void lastClick()
   {
      if( enabled )
      {
         click( "end" );
         storeIntervals();
         if (System.nanoTime() - lastPrintOutNanos > printFrequencySeconds * NANOS_IN_A_SECOND)
         {
            printAndResetResults();
         }
         clickNames.clear();
      }
   }

   /**
    * Call to end a profiling period
    *
    * @param print
    *           <code>true</code> to print results, <code>false</code>
    *           no to
    */

   public void lastClick( boolean print )
   {
      if( enabled )
      {
         click( "end" );
         storeIntervals();
         if (print)
         {
            printAndResetResults();
         }
         clickNames.clear();
      }
   }

   protected void storeIntervals(){
      totalNanos += (clicks.get(clicks.size() - 1).longValue() -
               clicks.get(0).longValue()) -
               (clicks.size() - 1) * SELF_TIME;
      for( int i = 0; i < clicks.size() - 1; i++ )
      {
         long newInterval = clicks.get( i + 1 ).longValue() - clicks.get( i ).longValue() - SELF_TIME;
         if( intervalsBetweenClicks.size() == clicks.size() - 1 )
         {
            long sumOfIntervals = intervalsBetweenClicks.get( i ).longValue();
            sumOfIntervals += newInterval;
            intervalsBetweenClicks.set( i, new Long( sumOfIntervals ) );
         }
         else
         {
            intervalsBetweenClicks.add( new Long( newInterval ) );
         }
      }
      clicks.clear();
      count++;
   }
   
   public void printAndResetResults(){
      if( period != null )
      {
         System.out.println( getClass().getSimpleName() + " " + name + " : mean period = "
               + period.format( totalNanos, count ) );
      }

      if( intervalsBetweenClicks.size() > 1 )
      {
         String[][] strings = new String[intervalsBetweenClicks.size()][3];
         int maxLength0 = 0;
         int maxLength1 = 0;
         int maxLength2 = 0;
         for( int i = 0; i < intervalsBetweenClicks.size(); i++ )
         {
            long intervalNanos = intervalsBetweenClicks.get( i ).longValue();
            double intervalAsProportionOfTotal = ( double ) intervalNanos / totalNanos;

            String nameStr = clickNames.get(i);
            String percentStr = percent.format(intervalAsProportionOfTotal);
            String intervalStr = (interval != null ? interval.format( intervalNanos, count ) : "");

            strings[i][0] = nameStr;
            strings[i][1] = percentStr;
            strings[i][2] = intervalStr;
            if (strings[i][0].length() > maxLength0){
               maxLength0 = strings[i][0].length();
            }
            if (strings[i][1].length() > maxLength1){
               maxLength1 = strings[i][1].length();
            }
            if (strings[i][2].length() > maxLength2){
               maxLength2 = strings[i][2].length();
            }
         }
         int extraSpaces = 4;
         for( int i = 0; i < strings.length; i++ )
         {
            System.out.println(strings[i][0]+
                  stringSpaces(maxLength0 - strings[i][0].length() + extraSpaces)+
                  strings[i][1]+
                  stringSpaces(maxLength1 - strings[i][1].length() + extraSpaces)+
                  strings[i][2]);
         }

      }

      totalNanos = 0;
      count = 0;
      lastPrintOutNanos = System.nanoTime();
      intervalsBetweenClicks.clear();
   }

   protected String stringSpaces(int numSpaces){
      StringBuilder spaces = new StringBuilder();
      for (int i = 0; i < numSpaces; i++){
         spaces.append(" ");
      }
      return spaces.toString();
   }




Offline CommanderKeith
« Reply #9 - Posted 2010-04-04 07:36:38 »

Here's the code with Bleb's great additions and my edits:


1  
2  
3  
4  
5  
6  
7  
8  
9  
10  
11  
12  
13  
14  
15  
16  
17  
18  
19  
20  
21  
22  
23  
24  
25  
26  
27  
28  
29  
30  
31  
32  
33  
34  
35  
36  
37  
38  
39  
40  
41  
42  
43  
44  
45  
46  
47  
48  
49  
50  
51  
52  
53  
54  
55  
56  
57  
58  
59  
60  
61  
62  
63  
64  
65  
66  
67  
68  
69  
70  
71  
72  
73  
74  
75  
76  
77  
78  
79  
80  
81  
82  
83  
84  
85  
86  
87  
88  
89  
90  
91  
92  
93  
94  
95  
96  
97  
98  
99  
100  
101  
102  
103  
104  
105  
106  
107  
108  
109  
110  
111  
112  
113  
114  
115  
116  
117  
118  
119  
120  
121  
122  
123  
124  
125  
126  
127  
128  
129  
130  
131  
132  
133  
134  
135  
136  
137  
138  
139  
140  
141  
142  
143  
144  
145  
146  
147  
148  
149  
150  
151  
152  
153  
154  
155  
156  
157  
158  
159  
160  
161  
162  
163  
164  
165  
166  
167  
168  
169  
170  
171  
172  
173  
174  
175  
176  
177  
178  
179  
180  
181  
182  
183  
184  
185  
186  
187  
188  
189  
190  
191  
192  
193  
194  
195  
196  
197  
198  
199  
200  
201  
202  
203  
204  
205  
206  
207  
208  
209  
210  
211  
212  
213  
214  
215  
216  
217  
218  
219  
220  
221  
222  
223  
224  
225  
226  
227  
228  
229  
230  
231  
232  
233  
234  
235  
236  
237  
238  
239  
240  
241  
242  
243  
244  
245  
246  
247  
248  
249  
250  
251  
252  
253  
254  
255  
256  
257  
258  
259  
260  
261  
262  
263  
264  
265  
266  
267  
268  
269  
270  
271  
272  
273  
274  
275  
276  
277  
278  
279  
280  
281  
282  
283  
284  
285  
286  
287  
288  
289  
290  
291  
292  
293  
294  
295  
296  
297  
298  
299  
300  
301  
302  
303  
304  
305  
306  
307  
308  
309  
310  
311  
312  
313  
314  
315  
316  
317  
318  
319  
320  
321  
322  
323  
324  
325  
326  
package geom.util;

import java.text.DecimalFormat;
import java.util.ArrayList;
import java.util.Collections;

/**
 * A convenience class to do code profiling.
 *
 * @author Keith Woodward, Ryan M
 *
 */

public class CodeTimer {

   private static DecimalFormat fourDP = new DecimalFormat("0.####");
   private static DecimalFormat percent = new DecimalFormat("0.##%");
   private static long SELF_TIME;
   public static final long NANOS_IN_A_SECOND = 1000000000;
   public static final long NANOS_IN_A_MILLISECOND = 1000000;

   static {
      recalibrate(10000);
   }
   /**
    * The name of this {@link CodeTimer}, to identify the output
    */

   public final String name;
   /**
    * Defaults to <code>true</code>
    */

   protected boolean enabled = true;
   private long count = 0;
   private long totalNanos = 0;
   private ArrayList<Long> clicks = new ArrayList<Long>();
   private ArrayList<String> clickNames = new ArrayList<String>();
   private ArrayList<Long> intervalsBetweenClicks = new ArrayList<Long>();
   private long lastPrintOutNanos = System.nanoTime();
   /**
    * The number of seconds between prints, defaults to 5
    */

   public int printFrequencySeconds = 5;
   /**
    * The level of information printed for the total time spent in a
    * profiling period
    */

   public Output period;
   /**
    * The level of information printed for time taken in intervals
    */

   public Output interval;

   /**
    * Time unit that is printed
    *
    * @author ryanm
    */

   public enum Output {

      /**
       * Second-level granularity
       */

      Seconds {

         @Override
         public String format(long totalNanos, long count) {
            double avTotalSeconds = (double) totalNanos / (count * NANOS_IN_A_SECOND);
            return fourDP.format(avTotalSeconds) + "s";
         }
      },
      /**
       * Millisecond-level granularity
       */

      Millis {

         @Override
         public String format(long totalNanos, long count) {
            double avTotalMillis = (double) totalNanos / (count * NANOS_IN_A_MILLISECOND);
            return fourDP.format(avTotalMillis) + "ms";
         }
      },
      /**
       * Nanosecond-level granularity
       */

      Nanos {

         @Override
         public String format(long totalNanos, long count) {
            double avTotalNanos = (double) totalNanos / count;
            return fourDP.format(avTotalNanos) + "ns";
         }
      };

      /**
       * @param totalNanos
       * @param count
       * @return A string describing the average time
       */

      public abstract String format(long totalNanos, long count);
   };

   /**
    * Default constructor that uses Nanosecond outputs and is named "Untitled".
    */

   public CodeTimer() {
      this.name = "Untitled";
      this.period = Output.Nanos;
      this.interval = Output.Nanos;
   }

   public CodeTimer(String name) {
      this.name = name;
      this.period = Output.Nanos;
      this.interval = Output.Nanos;
   }

   /**
    * @param name
    *           A name for this {@link CodeTimer}, so as to identify
    *           the output
    * @param period
    *           output for profiling period duration, or
    *           <code>null</code> for none. Note that if you specify
    *           null, you'll be getting output on stdOut that is not
    *           labelled as coming from this class
    * @param interval
    *           output for interval durations, or <code>null</code>
    *           for just the percentage of period time taken
    */

   public CodeTimer(String name, Output period, Output interval) {
      this.name = name;
      this.period = period;
      this.interval = interval;
   }

   /**
    * Call to start a profiling period, or to start an interval in an
    * open period
    *
    * @param name
    *           A helpful name for this interval. Makes it easy to
    *           find what bit of code you're measuring
    */

   public void click(String name) {
//      enabled = false;
     if (enabled) {
         long clickTime = System.nanoTime();
         clicks.add(new Long(clickTime));
         clickNames.add(name);
      }
   }

   /**
    * Call to end a profiling period, and print the results if
    * {@link #printFrequencySeconds} have passed since we last printed
    */

   public void lastClick() {
      if (enabled) {
         click("end");
         storeIntervals();
         if (System.nanoTime() - lastPrintOutNanos > printFrequencySeconds * NANOS_IN_A_SECOND) {
            printAndResetResults();
         }
         clickNames.clear();
      }
   }

   /**
    * Call to end a profiling period
    *
    * @param print
    *           <code>true</code> to print results, <code>false</code>
    *           no to
    */

   public void lastClick(boolean print) {
      if (enabled) {
         click("end");
         storeIntervals();
         if (print) {
            printAndResetResults();
         }
         clickNames.clear();
      }
   }

   protected void storeIntervals() {
      totalNanos += (clicks.get(clicks.size() - 1).longValue()
            - clicks.get(0).longValue())
            - (clicks.size() - 1) * SELF_TIME;
      for (int i = 0; i < clicks.size() - 1; i++) {
         long newInterval = clicks.get(i + 1).longValue() - clicks.get(i).longValue() - SELF_TIME;
         if (intervalsBetweenClicks.size() == clicks.size() - 1) {
            long sumOfIntervals = intervalsBetweenClicks.get(i).longValue();
            sumOfIntervals += newInterval;
            intervalsBetweenClicks.set(i, new Long(sumOfIntervals));
         } else {
            intervalsBetweenClicks.add(new Long(newInterval));
         }
      }
      clicks.clear();
      count++;
   }

   public void printAndResetResults() {
      if (period != null) {
         System.out.println(getClass().getSimpleName() + " " + name + " : mean period = "
               + period.format(totalNanos, count));
      }

      if (intervalsBetweenClicks.size() > 1) {
         String[][] strings = new String[intervalsBetweenClicks.size()][3];
         int maxLength0 = 0;
         int maxLength1 = 0;
         int maxLength2 = 0;
         for (int i = 0; i < intervalsBetweenClicks.size(); i++) {
            long intervalNanos = intervalsBetweenClicks.get(i).longValue();
            double intervalAsProportionOfTotal = (double) intervalNanos / totalNanos;

            String nameStr = clickNames.get(i);
            String percentStr = percent.format(intervalAsProportionOfTotal);
            String intervalStr = (interval != null ? interval.format(intervalNanos, count) : "");

            strings[i][0] = nameStr;
            strings[i][1] = percentStr;
            strings[i][2] = intervalStr;
            if (strings[i][0].length() > maxLength0) {
               maxLength0 = strings[i][0].length();
            }
            if (strings[i][1].length() > maxLength1) {
               maxLength1 = strings[i][1].length();
            }
            if (strings[i][2].length() > maxLength2) {
               maxLength2 = strings[i][2].length();
            }
         }
         int extraSpaces = 4;
         for (int i = 0; i < strings.length; i++) {
            System.out.println(stringSpaces(extraSpaces)
                  + strings[i][0]
                  + stringSpaces(maxLength0 - strings[i][0].length() + extraSpaces)
                  + strings[i][1]
                  + stringSpaces(maxLength1 - strings[i][1].length() + extraSpaces)
                  + strings[i][2]);
         }

      }

      totalNanos = 0;
      count = 0;
      lastPrintOutNanos = System.nanoTime();
      intervalsBetweenClicks.clear();
   }

   protected String stringSpaces(int numSpaces) {
      StringBuilder spaces = new StringBuilder();
      for (int i = 0; i < numSpaces; i++) {
         spaces.append(" ");
      }
      return spaces.toString();
   }

   public static void recalibrate(int numTests) {
      boolean print = false;
      CodeTimer codeTimer = new CodeTimer();
      // warm the JIT
     for (int i = 0; i < 1024; i++) {
         codeTimer.click("foo");
         codeTimer.lastClick();
      }


      // find how out long it takes to call click(), so that time can be accounted for
     ArrayList<Long> selfTimeObservations = new ArrayList<Long>(numTests);
      for (int i = 0; i < numTests; i++) {
         long nanoSelfTime = -(System.nanoTime() - System.nanoTime());
         long t0 = System.nanoTime();
         codeTimer.click("foo");
         long t1 = System.nanoTime();
         // lastClick is not tested since it really just calls click(),
        // but it is called here so that the CodeTimer's time and name lists do not get too big.
        codeTimer.lastClick();
         long currentSelfTime = t1 - t0 - nanoSelfTime;
         if (print) {
            System.out.println(CodeTimer.class.getSimpleName() + ": (t1 - t0) == " + (t1 - t0) + ", nanoSelfTime == " + nanoSelfTime + ", currentSelfTime == " + currentSelfTime);
         }
         selfTimeObservations.add(currentSelfTime);
      }
      // sort the times
     Collections.sort(selfTimeObservations);
      if (print) {
         for (int i = 0; i < selfTimeObservations.size(); i++) {
            System.out.println(CodeTimer.class.getSimpleName() + ": selfTimeObservations.get(i) == " + selfTimeObservations.get(i));
         }
      }
      // cut out the slowest 5% which are assumed to be outliers
     for (int i = 0; i < (int) (numTests * 0.05); i++) {
         selfTimeObservations.remove(0);
      }
      // cut out the fastest 5% which are assumed to be outliers
     for (int i = 0; i < (int) (numTests * 0.05); i++) {
         selfTimeObservations.remove(selfTimeObservations.size() - 1);
      }
      if (print) {
         System.out.println(CodeTimer.class.getSimpleName() + ": Slimmed list: selfTimeObservations.size() == " + selfTimeObservations.size());
         for (int i = 0; i < selfTimeObservations.size(); i++) {
            System.out.println(CodeTimer.class.getSimpleName() + ": selfTimeObservations.get(i) == " + selfTimeObservations.get(i));
         }
      }
      // find the average
     long sumOfSelfTimes = 0;
      for (int i = 0; i < selfTimeObservations.size(); i++) {
         sumOfSelfTimes += selfTimeObservations.get(i);
      }
      SELF_TIME = sumOfSelfTimes / selfTimeObservations.size();
      if (print) {
         System.out.println(CodeTimer.class.getSimpleName() + ": SELF_TIME == " + SELF_TIME);
      }
   }

   public boolean isEnabled() {
      return enabled;
   }

   public void setEnabled(boolean enabled) {
      this.enabled = enabled;
   }
}


Games published by our own members! Check 'em out!
Legends of Yore - The Casual Retro Roguelike
Offline ryanm

Senior Member


Projects: 1
Exp: 15 years


Used to be bleb


« Reply #10 - Posted 2010-04-04 08:27:24 »

See! Told you I'd broken it! Wink
Pages: [1]
  ignore  |  Print  
 
 
You cannot reply to this message, because it is very, very old.

 

Add your game by posting it in the WIP section,
or publish it in Showcase.

The first screenshot will be displayed as a thumbnail.

Dwinin (21 views)
2014-09-12 09:08:26

Norakomi (55 views)
2014-09-10 13:57:51

TehJavaDev (65 views)
2014-09-10 06:39:09

Tekkerue (33 views)
2014-09-09 02:24:56

mitcheeb (54 views)
2014-09-08 06:06:29

BurntPizza (38 views)
2014-09-07 01:13:42

Longarmx (24 views)
2014-09-07 01:12:14

Longarmx (30 views)
2014-09-07 01:11:22

Longarmx (28 views)
2014-09-07 01:10:19

mitcheeb (36 views)
2014-09-04 23:08:59
List of Learning Resources
by Longor1996
2014-08-16 10:40:00

List of Learning Resources
by SilverTiger
2014-08-05 19:33:27

Resources for WIP games
by CogWheelz
2014-08-01 16:20:17

Resources for WIP games
by CogWheelz
2014-08-01 16:19:50

List of Learning Resources
by SilverTiger
2014-07-31 16:29:50

List of Learning Resources
by SilverTiger
2014-07-31 16:26:06

List of Learning Resources
by SilverTiger
2014-07-31 11:54:12

HotSpot Options
by dleskov
2014-07-08 01:59:08
java-gaming.org is not responsible for the content posted by its members, including references to external websites, and other references that may or may not have a relation with our primarily gaming and game production oriented community. inquiries and complaints can be sent via email to the info‑account of the company managing the website of java‑gaming.org
Powered by MySQL Powered by PHP Powered by SMF 1.1.18 | SMF © 2013, Simple Machines | Managed by Enhanced Four Valid XHTML 1.0! Valid CSS!