SOLR-7678: Switch RTimer to use nanoTime

git-svn-id: https://svn.apache.org/repos/asf/lucene/dev/trunk@1685485 13f79535-47bb-0310-9956-ffa450edef68

solr/CHANGES.txt

@@ -190,6 +190,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)
+
 ==================  5.2.1 ==================
 
 Consult the LUCENE_CHANGES.txt file for additional, low level, changes in this release

solr/core/src/java/org/apache/solr/util/RTimer.java

@@ -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());
-  }
 }

solr/core/src/test/org/apache/solr/util/TestRTimer.java

@@ -0,0 +1,88 @@
+package org.apache.solr.util;
+
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import org.apache.lucene.util.LuceneTestCase;
+import org.apache.solr.common.util.NamedList;
+
+public class TestRTimer extends LuceneTestCase {
+
+  private static class MockTimerImpl implements RTimer.TimerImpl {
+    static private long systemTime;
+    static public void incrementSystemTime(long ms) {
+      systemTime += ms;
+    }
+
+    private long start;
+    public void start() {
+      start = systemTime;
+    }
+    public double elapsed() {
+      return systemTime - start;
+    }
+  }
+
+  private class MockRTimer extends RTimer {
+    @Override
+    protected TimerImpl newTimerImpl() {
+      return new MockTimerImpl();
+    }
+    @Override
+    protected RTimer newTimer() {
+      return new MockRTimer();
+    }
+  }
+
+  public void test() {
+    RTimer rt = new MockRTimer(), subt, st;
+
+    MockTimerImpl.incrementSystemTime(100);
+    assertEquals(100, (int) rt.getTime());
+
+    subt = rt.sub("sub1");
+    MockTimerImpl.incrementSystemTime(50);
+    assertEquals(150, (int) rt.getTime());
+    assertEquals(50, (int) subt.getTime());
+
+    st = subt.sub("sub1.1");
+    st.resume();
+    MockTimerImpl.incrementSystemTime(10);
+    assertEquals(10, (int) st.getTime());
+    st.pause();
+    MockTimerImpl.incrementSystemTime(50);
+    assertEquals(10, (int) st.getTime());
+    st.resume();
+    MockTimerImpl.incrementSystemTime(10);
+    st.pause();
+    subt.stop();
+    rt.stop();
+
+    assertEquals(20, (int) st.getTime());
+    assertEquals(120, (int) subt.getTime());
+    assertEquals(220, (int) rt.getTime());
+
+    NamedList nl = rt.asNamedList();
+    assertEquals(220, ((Double) nl.get("time")).intValue());
+    NamedList sub1nl = (NamedList) nl.get("sub1");
+    assertNotNull(sub1nl);
+    assertEquals(120, ((Double) sub1nl.get("time")).intValue());
+    NamedList sub11nl = (NamedList) sub1nl.get("sub1.1");
+    assertNotNull(sub11nl);
+    assertEquals(20, ((Double) sub11nl.get("time")).intValue());
+  }
+}