Reduce profiling overhead. (#25772)

Calling `System.nanoTime()` for each method call may have a significant
performance impact.

Closes #24799

core/src/main/java/org/elasticsearch/search/profile/AbstractProfileBreakdown.java

@@ -53,7 +53,7 @@ public abstract class AbstractProfileBreakdown<T extends Enum<T>> {
     public Map<String, Long> toTimingMap() {
         Map<String, Long> map = new HashMap<>();
         for (T timingType : timingTypes) {
-            map.put(timingType.toString(), timings[timingType.ordinal()].getTiming());
+            map.put(timingType.toString(), timings[timingType.ordinal()].getApproximateTiming());
             map.put(timingType.toString() + "_count", timings[timingType.ordinal()].getCount());
         }
         return Collections.unmodifiableMap(map);

core/src/main/java/org/elasticsearch/search/profile/Timer.java

@@ -33,38 +33,64 @@ package org.elasticsearch.search.profile;
  *  }
  *  </pre>
  */
-// TODO: do not time every single call as discussed in https://github.com/elastic/elasticsearch/issues/24799
+public class Timer {
-public final class Timer {
 
-    private long timing, count, start;
+    private boolean doTiming;
+    private long timing, count, lastCount, start;
+
+    /** pkg-private for testing */
+    long nanoTime() {
+        return System.nanoTime();
+    }
 
     /** Start the timer. */
-    public void start() {
+    public final void start() {
         assert start == 0 : "#start call misses a matching #stop call";
+        // We measure the timing of each method call for the first 256
+        // calls, then 1/2 call up to 512 then 1/3 up to 768, etc. with
+        // a maximum interval of 1024, which is reached for 1024*2^8 ~= 262000
+        // This allows to not slow down things too much because of calls
+        // to System.nanoTime() when methods are called millions of time
+        // in tight loops, while still providing useful timings for methods
+        // that are only called a couple times per search execution.
+        doTiming = (count - lastCount) >= Math.min(lastCount >>> 8, 1024);
+        if (doTiming) {
+            start = nanoTime();
+        }
         count++;
-        start = System.nanoTime();
     }
 
     /** Stop the timer. */
-    public void stop() {
+    public final void stop() {
-        timing += Math.max(System.nanoTime() - start, 1L);
+        if (doTiming) {
-        start = 0;
+            timing += (count - lastCount) * Math.max(nanoTime() - start, 1L);
+            lastCount = count;
+            start = 0;
+        }
     }
 
     /** Return the number of times that {@link #start()} has been called. */
-    public long getCount() {
+    public final long getCount() {
         if (start != 0) {
             throw new IllegalStateException("#start call misses a matching #stop call");
         }
         return count;
     }
 
-    /** Return an approximation of the total time spend between consecutive calls of #start and #stop. */
+    /** Return an approximation of the total time spent between consecutive calls of #start and #stop. */
-    public long getTiming() {
+    public final long getApproximateTiming() {
         if (start != 0) {
             throw new IllegalStateException("#start call misses a matching #stop call");
         }
+        // We don't have timings for the last `count-lastCount` method calls
+        // so we assume that they had the same timing as the lastCount first
+        // calls. This approximation is ok since at most 1/256th of method
+        // calls have not been timed.
+        long timing = this.timing;
+        if (count > lastCount) {
+            assert lastCount > 0;
+            timing += (count - lastCount) * timing / lastCount;
+        }
         return timing;
     }
-
 }

core/src/test/java/org/elasticsearch/search/profile/TimerTests.java

@@ -0,0 +1,68 @@
+/*
+ * Licensed to Elasticsearch under one or more contributor
+ * license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright
+ * ownership. Elasticsearch 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.
+ */
+
+package org.elasticsearch.search.profile;
+
+import org.elasticsearch.test.ESTestCase;
+
+import java.util.concurrent.atomic.AtomicLong;
+
+public class TimerTests extends ESTestCase {
+
+    public void testTimingInterval() {
+        final AtomicLong nanoTimeCallCounter = new AtomicLong();
+        Timer t = new Timer() {
+            long time = 50;
+            @Override
+            long nanoTime() {
+                nanoTimeCallCounter.incrementAndGet();
+                return time += 1;
+            }
+        };
+        for (int i = 0; i < 100000; ++i) {
+            t.start();
+            t.stop();
+            if (i < 256) {
+                // for the first 256 calls, nanoTime() is called
+                // once for `start` and once for `stop`
+                assertEquals((i + 1) * 2, nanoTimeCallCounter.get());
+            }
+        }
+        // only called nanoTime() 3356 times, which is significantly less than 100000
+        assertEquals(3356L, nanoTimeCallCounter.get());
+    }
+
+    public void testExtrapolate() {
+        Timer t = new Timer() {
+            long time = 50;
+            @Override
+            long nanoTime() {
+                return time += 42;
+            }
+        };
+        for (int i = 1; i < 100000; ++i) {
+            t.start();
+            t.stop();
+            assertEquals(i, t.getCount());
+            // Make sure the cumulated timing is 42 times the number of calls as expected
+            assertEquals(i * 42L, t.getApproximateTiming());
+        }
+    }
+
+}