svn commit: r1686080 - in /lucene/dev/branches/branch_5x: ./ solr/ solr/CHANGES.txt solr/core/ solr/core/src/java/org/apache/solr/util/RTimer.java solr/core/src/test/org/apache/solr/util/TestRTimer.java

[an...@apache.org]

Author: andyetitmoves
Date: Wed Jun 17 17:18:57 2015
New Revision: 1686080

URL: http://svn.apache.org/r1686080
Log:
SOLR-7678: Switch RTimer to use nanoTime

Added:
    lucene/dev/branches/branch_5x/solr/core/src/test/org/apache/solr/util/TestRTimer.java
      - copied unchanged from r1685485, lucene/dev/trunk/solr/core/src/test/org/apache/solr/util/TestRTimer.java
Modified:
    lucene/dev/branches/branch_5x/   (props changed)
    lucene/dev/branches/branch_5x/solr/   (props changed)
    lucene/dev/branches/branch_5x/solr/CHANGES.txt   (contents, props changed)
    lucene/dev/branches/branch_5x/solr/core/   (props changed)
    lucene/dev/branches/branch_5x/solr/core/src/java/org/apache/solr/util/RTimer.java

Modified: lucene/dev/branches/branch_5x/solr/CHANGES.txt
URL: http://svn.apache.org/viewvc/lucene/dev/branches/branch_5x/solr/CHANGES.txt?rev=1686080&r1=1686079&r2=1686080&view=diff
==============================================================================
--- lucene/dev/branches/branch_5x/solr/CHANGES.txt (original)
+++ lucene/dev/branches/branch_5x/solr/CHANGES.txt Wed Jun 17 17:18:57 2015
@@ -139,6 +139,9 @@ Other Changes
 * SOLR-7619: Fix SegmentsInfoRequestHandlerTest when more than one segment is created.
   (Ramkumar Aiyengar, Steve Rowe)
 
+* SOLR-7678: Switch RTimer to use nanoTime (improves accuracy of QTime, and other times
+  returned by Solr handlers) (Ramkumar Aiyengar)
+
 * SOLR-7680: Use POST instead of GET when finding versions for mismatches with
   CloudInspectUtil for tests (Ramkumar Aiyengar)
 

Modified: lucene/dev/branches/branch_5x/solr/core/src/java/org/apache/solr/util/RTimer.java
URL: http://svn.apache.org/viewvc/lucene/dev/branches/branch_5x/solr/core/src/java/org/apache/solr/util/RTimer.java?rev=1686080&r1=1686079&r2=1686080&view=diff
==============================================================================
--- lucene/dev/branches/branch_5x/solr/core/src/java/org/apache/solr/util/RTimer.java (original)
+++ lucene/dev/branches/branch_5x/solr/core/src/java/org/apache/solr/util/RTimer.java Wed Jun 17 17:18:57 2015
@@ -17,13 +17,12 @@ package org.apache.solr.util;
  * limitations under the License.
  */
 
+import java.util.Map;
+import java.util.concurrent.TimeUnit;
+
 import org.apache.solr.common.util.NamedList;
 import org.apache.solr.common.util.SimpleOrderedMap;
 
-import java.lang.System;
-import java.lang.Thread;
-import java.util.*;
-
 /** A recursive timer.
  * 
  * RTimers are started automatically when instantiated; subtimers are also
@@ -39,31 +38,49 @@ public class RTimer {
   public static final int PAUSED = 2;
 
   protected int state;
-  protected double startTime;
+  protected TimerImpl timerImpl;
   protected double time;
   protected double culmTime;
   protected SimpleOrderedMap<RTimer> children;
 
+  protected interface TimerImpl {
+    void start();
+    double elapsed();
+  }
+
+  private class NanoTimeTimerImpl implements TimerImpl {
+    private long start;
+    public void start() {
+      start = System.nanoTime();
+    }
+    public double elapsed() {
+      return TimeUnit.MILLISECONDS.convert(System.nanoTime() - start, TimeUnit.NANOSECONDS);
+    }
+  }
+
+  protected TimerImpl newTimerImpl() {
+    return new NanoTimeTimerImpl();
+  }
+
+  protected RTimer newTimer() {
+    return new RTimer();
+  }
+
   public RTimer() {
     time = 0;
     culmTime = 0;
     children = new SimpleOrderedMap<>();
-    startTime = now();
+    timerImpl = newTimerImpl();
+    timerImpl.start();
     state = STARTED;
   }
 
-  /** Get current time
-   *
-   * May override to implement a different timer (CPU time, etc).
-   */
-  protected double now() { return System.currentTimeMillis(); }
-
   /** Recursively stop timer and sub timers */
   public double stop() {
     assert state == STARTED || state == PAUSED;
     time = culmTime;
     if(state == STARTED) 
-      time += now() - startTime;
+      time += timerImpl.elapsed();
     state = STOPPED;
     
     for( Map.Entry<String,RTimer> entry : children ) {
@@ -76,7 +93,7 @@ public class RTimer {
 
   public void pause() {
     assert state == STARTED;
-    culmTime += now() - startTime;
+    culmTime += timerImpl.elapsed();
     state = PAUSED;
   }
   
@@ -85,7 +102,7 @@ public class RTimer {
       return;
     assert state == PAUSED;
     state = STARTED;
-    startTime = now();
+    timerImpl.start();
   }
 
   /** Get total elapsed time for this timer. */
@@ -94,7 +111,7 @@ public class RTimer {
     else if (state == PAUSED) return culmTime;
     else {
       assert state == STARTED;
-      return culmTime + (now() - startTime);
+      return culmTime + timerImpl.elapsed();
     }
  }
 
@@ -105,7 +122,7 @@ public class RTimer {
   public RTimer sub(String desc) {
     RTimer child = children.get( desc );
     if( child == null ) {
-      child = new RTimer();
+      child = newTimer();
       children.add(desc, child);
     }
     return child;
@@ -134,25 +151,4 @@ public class RTimer {
   {
     return children;
   }
-
-  /*************** Testing *******/
-  public static void main(String []argv) throws InterruptedException {
-    RTimer rt = new RTimer(), subt, st;
-    Thread.sleep(100);
-
-    subt = rt.sub("sub1");
-    Thread.sleep(50);
-    st = subt.sub("sub1.1");
-    st.resume();
-    Thread.sleep(10);
-    st.pause();
-    Thread.sleep(50);
-    st.resume();
-    Thread.sleep(10);
-    st.pause();
-    subt.stop();
-    rt.stop();
-
-    System.out.println( rt.toString());
-  }
 }