diff --git a/core/src/main/java/org/elasticsearch/search/profile/AbstractProfileBreakdown.java b/core/src/main/java/org/elasticsearch/search/profile/AbstractProfileBreakdown.java index 1ca23b44734bf..f49ad4a8718a0 100644 --- a/core/src/main/java/org/elasticsearch/search/profile/AbstractProfileBreakdown.java +++ b/core/src/main/java/org/elasticsearch/search/profile/AbstractProfileBreakdown.java @@ -53,7 +53,7 @@ public Timer getTimer(T timing) { public Map toTimingMap() { Map 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); diff --git a/core/src/main/java/org/elasticsearch/search/profile/Timer.java b/core/src/main/java/org/elasticsearch/search/profile/Timer.java index 41763552a6df0..72b62ec562244 100644 --- a/core/src/main/java/org/elasticsearch/search/profile/Timer.java +++ b/core/src/main/java/org/elasticsearch/search/profile/Timer.java @@ -33,38 +33,64 @@ * } * */ -// TODO: do not time every single call as discussed in https://github.com/elastic/elasticsearch/issues/24799 -public final class Timer { +public 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() { - timing += Math.max(System.nanoTime() - start, 1L); - start = 0; + public final void stop() { + if (doTiming) { + 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. */ - public long getTiming() { + /** Return an approximation of the total time spent between consecutive calls of #start and #stop. */ + 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; } - } diff --git a/core/src/test/java/org/elasticsearch/search/profile/TimerTests.java b/core/src/test/java/org/elasticsearch/search/profile/TimerTests.java new file mode 100644 index 0000000000000..fc1bd76f39ecd --- /dev/null +++ b/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()); + } + } + +}