diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt index 46af6c1c08d..9407223f331 100644 --- a/solr/CHANGES.txt +++ b/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 diff --git a/solr/core/src/java/org/apache/solr/util/RTimer.java b/solr/core/src/java/org/apache/solr/util/RTimer.java index 9c29ac02614..22ef133d2c4 100644 --- a/solr/core/src/java/org/apache/solr/util/RTimer.java +++ b/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 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 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()); - } } diff --git a/solr/core/src/test/org/apache/solr/util/TestRTimer.java b/solr/core/src/test/org/apache/solr/util/TestRTimer.java new file mode 100644 index 00000000000..26d6356f4a3 --- /dev/null +++ b/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()); + } +}