diff --git a/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java b/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java index 11b8506c5227d..0894943c814b5 100644 --- a/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java +++ b/src/main/java/org/apache/lucene/index/TrackingConcurrentMergeScheduler.java @@ -91,7 +91,7 @@ public Set onGoingMerges() { protected void doMerge(MergePolicy.OneMerge merge) throws IOException { int totalNumDocs = merge.totalNumDocs(); long totalSizeInBytes = merge.totalBytesSize(); - long time = System.currentTimeMillis(); + long timeNS = System.nanoTime(); currentMerges.inc(); currentMergesNumDocs.inc(totalNumDocs); currentMergesSizeInBytes.inc(totalSizeInBytes); @@ -106,7 +106,7 @@ protected void doMerge(MergePolicy.OneMerge merge) throws IOException { beforeMerge(onGoingMerge); super.doMerge(merge); } finally { - long took = System.currentTimeMillis() - time; + long tookMS = TimeValue.nsecToMSec(System.nanoTime() - timeNS); onGoingMerges.remove(onGoingMerge); afterMerge(onGoingMerge); @@ -117,15 +117,16 @@ protected void doMerge(MergePolicy.OneMerge merge) throws IOException { totalMergesNumDocs.inc(totalNumDocs); totalMergesSizeInBytes.inc(totalSizeInBytes); - totalMerges.inc(took); + totalMerges.inc(tookMS); + String message = String.format(Locale.ROOT, "merge segment [%s] done: took [%s], [%,.1f MB], [%,d docs]", merge.info == null ? "_na_" : merge.info.info.name, - TimeValue.timeValueMillis(took), + TimeValue.timeValueMillis(tookMS), totalSizeInBytes/1024f/1024f, totalNumDocs); - if (took > 20000) { // if more than 20 seconds, DEBUG log it + if (tookMS > 20000) { // if more than 20 seconds, DEBUG log it logger.debug(message); } else if (logger.isTraceEnabled()) { logger.trace(message); diff --git a/src/main/java/org/elasticsearch/action/admin/cluster/health/TransportClusterHealthAction.java b/src/main/java/org/elasticsearch/action/admin/cluster/health/TransportClusterHealthAction.java index 04bb0afae06ea..e14e91efd8563 100644 --- a/src/main/java/org/elasticsearch/action/admin/cluster/health/TransportClusterHealthAction.java +++ b/src/main/java/org/elasticsearch/action/admin/cluster/health/TransportClusterHealthAction.java @@ -73,7 +73,7 @@ protected ClusterHealthResponse newResponse() { @Override protected void masterOperation(final ClusterHealthRequest request, final ClusterState unusedState, final ActionListener listener) throws ElasticsearchException { if (request.waitForEvents() != null) { - final long endTime = System.currentTimeMillis() + request.timeout().millis(); + final long endTimeMS = TimeValue.nsecToMSec(System.nanoTime()) + request.timeout().millis(); clusterService.submitStateUpdateTask("cluster_health (wait_for_events [" + request.waitForEvents() + "])", request.waitForEvents(), new ProcessedClusterStateUpdateTask() { @Override public ClusterState execute(ClusterState currentState) { @@ -82,7 +82,7 @@ public ClusterState execute(ClusterState currentState) { @Override public void clusterStateProcessed(String source, ClusterState oldState, ClusterState newState) { - final long timeoutInMillis = Math.max(0, endTime - System.currentTimeMillis()); + final long timeoutInMillis = Math.max(0, endTimeMS - TimeValue.nsecToMSec(System.nanoTime())); final TimeValue newTimeout = TimeValue.timeValueMillis(timeoutInMillis); request.timeout(newTimeout); executeHealth(request, listener); diff --git a/src/main/java/org/elasticsearch/action/update/UpdateHelper.java b/src/main/java/org/elasticsearch/action/update/UpdateHelper.java index dec00d9403cbf..978bb95bf3011 100644 --- a/src/main/java/org/elasticsearch/action/update/UpdateHelper.java +++ b/src/main/java/org/elasticsearch/action/update/UpdateHelper.java @@ -74,7 +74,7 @@ public UpdateHelper(Settings settings, ScriptService scriptService) { */ @SuppressWarnings("unchecked") public Result prepare(UpdateRequest request, IndexShard indexShard) { - long getDate = System.currentTimeMillis(); + long getDateNS = System.nanoTime(); final GetResult getResult = indexShard.getService().get(request.type(), request.id(), new String[]{RoutingFieldMapper.NAME, ParentFieldMapper.NAME, TTLFieldMapper.NAME, TimestampFieldMapper.NAME}, true, request.version(), request.versionType(), FetchSourceContext.FETCH_SOURCE, false); @@ -222,7 +222,7 @@ public Result prepare(UpdateRequest request, IndexShard indexShard) { if (ttl == null) { ttl = getResult.getFields().containsKey(TTLFieldMapper.NAME) ? (Long) getResult.field(TTLFieldMapper.NAME).getValue() : null; if (ttl != null) { - ttl = ttl - (System.currentTimeMillis() - getDate); // It is an approximation of exact TTL value, could be improved + ttl = ttl - TimeValue.nsecToMSec(System.nanoTime() - getDateNS); // It is an approximation of exact TTL value, could be improved } } diff --git a/src/main/java/org/elasticsearch/cluster/ClusterStateObserver.java b/src/main/java/org/elasticsearch/cluster/ClusterStateObserver.java index a890963693212..0df21452f5598 100644 --- a/src/main/java/org/elasticsearch/cluster/ClusterStateObserver.java +++ b/src/main/java/org/elasticsearch/cluster/ClusterStateObserver.java @@ -49,7 +49,7 @@ public boolean apply(ClusterChangedEvent changedEvent) { final AtomicReference lastObservedState; // observingContext is not null when waiting on cluster state changes final AtomicReference observingContext = new AtomicReference(null); - volatile long startTime; + volatile long startTimeNS; volatile boolean timedOut; volatile TimeoutClusterStateListener clusterStateListener = new ObserverClusterStateListener(); @@ -68,7 +68,7 @@ public ClusterStateObserver(ClusterService clusterService, TimeValue timeout, ES this.timeOutValue = timeout; this.clusterService = clusterService; this.lastObservedState = new AtomicReference<>(new ObservedState(clusterService.state())); - this.startTime = System.currentTimeMillis(); + this.startTimeNS = System.nanoTime(); this.logger = logger; } @@ -108,14 +108,14 @@ public void waitForNextChange(Listener listener, ChangePredicate changePredicate if (observingContext.get() != null) { throw new ElasticsearchException("already waiting for a cluster state change"); } - long timeoutTimeLeft; + long timeoutTimeLeftMS; if (timeOutValue == null) { timeOutValue = this.timeOutValue; - long timeSinceStart = System.currentTimeMillis() - startTime; - timeoutTimeLeft = timeOutValue.millis() - timeSinceStart; - if (timeoutTimeLeft <= 0l) { + long timeSinceStartMS = TimeValue.nsecToMSec(System.nanoTime() - startTimeNS); + timeoutTimeLeftMS = timeOutValue.millis() - timeSinceStartMS; + if (timeoutTimeLeftMS <= 0l) { // things have timeout while we were busy -> notify - logger.debug("observer timed out. notifying listener. timeout setting [{}], time since start [{}]", timeOutValue, new TimeValue(timeSinceStart)); + logger.debug("observer timed out. notifying listener. timeout setting [{}], time since start [{}]", timeOutValue, new TimeValue(timeSinceStartMS)); // update to latest, in case people want to retry timedOut = true; lastObservedState.set(new ObservedState(clusterService.state())); @@ -123,9 +123,9 @@ public void waitForNextChange(Listener listener, ChangePredicate changePredicate return; } } else { - this.startTime = System.currentTimeMillis(); + this.startTimeNS = System.nanoTime(); this.timeOutValue = timeOutValue; - timeoutTimeLeft = timeOutValue.millis(); + timeoutTimeLeftMS = timeOutValue.millis(); timedOut = false; } @@ -143,7 +143,7 @@ public void waitForNextChange(Listener listener, ChangePredicate changePredicate if (!observingContext.compareAndSet(null, context)) { throw new ElasticsearchException("already waiting for a cluster state change"); } - clusterService.add(new TimeValue(timeoutTimeLeft), clusterStateListener); + clusterService.add(new TimeValue(timeoutTimeLeftMS), clusterStateListener); } } @@ -223,8 +223,8 @@ public void onTimeout(TimeValue timeout) { ObservingContext context = observingContext.getAndSet(null); if (context != null) { clusterService.remove(this); - long timeSinceStart = System.currentTimeMillis() - startTime; - logger.debug("observer: timeout notification from cluster service. timeout setting [{}], time since start [{}]", timeOutValue, new TimeValue(timeSinceStart)); + long timeSinceStartMS = TimeValue.nsecToMSec(System.nanoTime() - startTimeNS); + logger.debug("observer: timeout notification from cluster service. timeout setting [{}], time since start [{}]", timeOutValue, new TimeValue(timeSinceStartMS)); // update to latest, in case people want to retry lastObservedState.set(new ObservedState(clusterService.state())); timedOut = true; diff --git a/src/main/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDecider.java b/src/main/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDecider.java index 7b0ef78ad1b07..24653fb1bc613 100644 --- a/src/main/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDecider.java +++ b/src/main/java/org/elasticsearch/cluster/routing/allocation/decider/DiskThresholdDecider.java @@ -130,7 +130,7 @@ public void onRefreshSettings(Settings settings) { */ class DiskListener implements ClusterInfoService.Listener { private final Client client; - private long lastRun; + private long lastRunNS; DiskListener(Client client) { this.client = client; @@ -168,8 +168,8 @@ public void onNewInfo(ClusterInfo info) { warnAboutDiskIfNeeded(entry); if (entry.getFreeBytes() < DiskThresholdDecider.this.freeBytesThresholdHigh.bytes() || entry.getFreeDiskAsPercentage() < DiskThresholdDecider.this.freeDiskThresholdHigh) { - if ((System.currentTimeMillis() - lastRun) > DiskThresholdDecider.this.rerouteInterval.millis()) { - lastRun = System.currentTimeMillis(); + if ((System.nanoTime() - lastRunNS) > DiskThresholdDecider.this.rerouteInterval.nanos()) { + lastRunNS = System.nanoTime(); reroute = true; } else { logger.debug("high disk watermark exceeded on {} but an automatic reroute has occurred in the last [{}], skipping reroute", diff --git a/src/main/java/org/elasticsearch/cluster/service/InternalClusterService.java b/src/main/java/org/elasticsearch/cluster/service/InternalClusterService.java index 8faf7dc1e739b..ec6ef390aa343 100644 --- a/src/main/java/org/elasticsearch/cluster/service/InternalClusterService.java +++ b/src/main/java/org/elasticsearch/cluster/service/InternalClusterService.java @@ -325,19 +325,19 @@ public int numberOfPendingTasks() { static abstract class TimedPrioritizedRunnable extends PrioritizedRunnable { - private final long creationTime; + private final long creationTimeNS; protected final String source; protected TimedPrioritizedRunnable(Priority priority, String source) { super(priority); this.source = source; - this.creationTime = System.currentTimeMillis(); + this.creationTimeNS = System.nanoTime(); } public long timeSinceCreatedInMillis() { // max with 0 to make sure we always return a non negative number // even if time shifts. - return Math.max(0, System.currentTimeMillis() - creationTime); + return Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - creationTimeNS)); } public String source() { @@ -369,11 +369,11 @@ public void run() { return; } ClusterState newClusterState; - long startTime = System.currentTimeMillis(); + long startTimeNS = System.nanoTime(); try { newClusterState = updateTask.execute(previousClusterState); } catch (Throwable e) { - TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, System.currentTimeMillis() - startTime)); + TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - startTimeNS))); if (logger.isTraceEnabled()) { StringBuilder sb = new StringBuilder("failed to execute cluster state update in ").append(executionTime).append(", state:\nversion [").append(previousClusterState.version()).append("], source [").append(source).append("]\n"); sb.append(previousClusterState.nodes().prettyPrint()); @@ -394,7 +394,7 @@ public void run() { if (updateTask instanceof ProcessedClusterStateUpdateTask) { ((ProcessedClusterStateUpdateTask) updateTask).clusterStateProcessed(source, previousClusterState, newClusterState); } - TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, System.currentTimeMillis() - startTime)); + TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - startTimeNS))); logger.debug("processing [{}]: took {} no change in cluster_state", source, executionTime); warnAboutSlowTaskIfNeeded(executionTime, source); return; @@ -514,11 +514,11 @@ public void run() { ((ProcessedClusterStateUpdateTask) updateTask).clusterStateProcessed(source, previousClusterState, newClusterState); } - TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, System.currentTimeMillis() - startTime)); + TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - startTimeNS))); logger.debug("processing [{}]: took {} done applying updated cluster_state (version: {})", source, executionTime, newClusterState.version()); warnAboutSlowTaskIfNeeded(executionTime, source); } catch (Throwable t) { - TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, System.currentTimeMillis() - startTime)); + TimeValue executionTime = TimeValue.timeValueMillis(Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - startTimeNS))); StringBuilder sb = new StringBuilder("failed to apply updated cluster state in ").append(executionTime).append(":\nversion [").append("], source [").append(source).append("]\n"); sb.append(newClusterState.nodes().prettyPrint()); sb.append(newClusterState.routingTable().prettyPrint()); diff --git a/src/main/java/org/elasticsearch/common/StopWatch.java b/src/main/java/org/elasticsearch/common/StopWatch.java index 14f898ba2bde8..cc18e9332b55b 100644 --- a/src/main/java/org/elasticsearch/common/StopWatch.java +++ b/src/main/java/org/elasticsearch/common/StopWatch.java @@ -31,7 +31,7 @@ * Simple stop watch, allowing for timing of a number of tasks, * exposing total running time and running time for each named task. *

- *

Conceals use of System.currentTimeMillis(), improving the + *

Conceals use of System.nanoTime(), improving the * readability of application code and reducing the likelihood of calculation errors. *

*

Note that this object is not designed to be thread-safe and does not @@ -58,7 +58,7 @@ public class StopWatch { /** * Start time of the current task */ - private long startTimeMillis; + private long startTimeNS; /** * Is the stop watch currently running? @@ -77,7 +77,7 @@ public class StopWatch { /** * Total running time */ - private long totalTimeMillis; + private long totalTimeNS; /** * Construct a new stop watch. Does not start any task. @@ -129,7 +129,7 @@ public StopWatch start(String taskName) throws IllegalStateException { if (this.running) { throw new IllegalStateException("Can't start StopWatch: it's already running"); } - this.startTimeMillis = System.currentTimeMillis(); + this.startTimeNS = System.nanoTime(); this.running = true; this.currentTaskName = taskName; return this; @@ -146,9 +146,9 @@ public StopWatch stop() throws IllegalStateException { if (!this.running) { throw new IllegalStateException("Can't stop StopWatch: it's not running"); } - long lastTime = System.currentTimeMillis() - this.startTimeMillis; - this.totalTimeMillis += lastTime; - this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime); + long lastTimeNS = System.nanoTime() - this.startTimeNS; + this.totalTimeNS += lastTimeNS; + this.lastTaskInfo = new TaskInfo(this.currentTaskName, TimeValue.nsecToMSec(lastTimeNS)); if (this.keepTaskList) { this.taskList.add(lastTaskInfo); } @@ -189,7 +189,7 @@ public String lastTaskName() throws IllegalStateException { * Return the total time for all tasks. */ public TimeValue totalTime() { - return new TimeValue(totalTimeMillis, TimeUnit.MILLISECONDS); + return new TimeValue(totalTimeNS, TimeUnit.NANOSECONDS); } /** diff --git a/src/main/java/org/elasticsearch/common/inject/internal/Stopwatch.java b/src/main/java/org/elasticsearch/common/inject/internal/Stopwatch.java index eab5f2250b655..849e869353745 100644 --- a/src/main/java/org/elasticsearch/common/inject/internal/Stopwatch.java +++ b/src/main/java/org/elasticsearch/common/inject/internal/Stopwatch.java @@ -16,6 +16,8 @@ package org.elasticsearch.common.inject.internal; +import org.elasticsearch.common.unit.TimeValue; + import java.util.logging.Logger; /** @@ -26,17 +28,17 @@ public class Stopwatch { private static final Logger logger = Logger.getLogger(Stopwatch.class.getName()); - private long start = System.currentTimeMillis(); + private long startNS = System.nanoTime(); /** * Resets and returns elapsed time in milliseconds. */ public long reset() { - long now = System.currentTimeMillis(); + long nowNS = System.nanoTime(); try { - return now - start; + return TimeValue.nsecToMSec(nowNS - startNS); } finally { - start = now; + startNS = nowNS; } } diff --git a/src/main/java/org/elasticsearch/common/unit/TimeValue.java b/src/main/java/org/elasticsearch/common/unit/TimeValue.java index 6ad1bbc0d2e63..a7037b4e90c25 100644 --- a/src/main/java/org/elasticsearch/common/unit/TimeValue.java +++ b/src/main/java/org/elasticsearch/common/unit/TimeValue.java @@ -38,6 +38,9 @@ */ public class TimeValue implements Serializable, Streamable { + /** How many nano-seconds in one milli-second */ + public static final long NSEC_PER_MSEC = 1000000; + public static TimeValue timeValueNanos(long nanos) { return new TimeValue(nanos, TimeUnit.NANOSECONDS); } @@ -296,4 +299,8 @@ public int hashCode() { long normalized = timeUnit.toNanos(duration); return (int) (normalized ^ (normalized >>> 32)); } + + public static long nsecToMSec(long ns) { + return ns / NSEC_PER_MSEC; + } } diff --git a/src/main/java/org/elasticsearch/env/NodeEnvironment.java b/src/main/java/org/elasticsearch/env/NodeEnvironment.java index f195f6d5b19d1..0d8754056b428 100644 --- a/src/main/java/org/elasticsearch/env/NodeEnvironment.java +++ b/src/main/java/org/elasticsearch/env/NodeEnvironment.java @@ -38,6 +38,7 @@ import org.elasticsearch.common.settings.ImmutableSettings; import org.elasticsearch.common.settings.Settings; import org.elasticsearch.common.unit.ByteSizeValue; +import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.index.Index; import org.elasticsearch.index.settings.IndexSettings; import org.elasticsearch.index.shard.ShardId; @@ -393,11 +394,11 @@ public List lockAllForIndex(Index index, @IndexSettings Settings sett logger.trace("locking all shards for index {} - [{}]", index, numShards); List allLocks = new ArrayList<>(numShards); boolean success = false; - long startTime = System.currentTimeMillis(); + long startTimeNS = System.nanoTime(); try { for (int i = 0; i < numShards; i++) { - long timeoutLeft = Math.max(0, lockTimeoutMS - (System.currentTimeMillis() - startTime)); - allLocks.add(shardLock(new ShardId(index, i), timeoutLeft)); + long timeoutLeftMS = Math.max(0, lockTimeoutMS - TimeValue.nsecToMSec((System.nanoTime() - startTimeNS))); + allLocks.add(shardLock(new ShardId(index, i), timeoutLeftMS)); } success = true; } finally { diff --git a/src/main/java/org/elasticsearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java b/src/main/java/org/elasticsearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java index ad1402503576f..a06f00c87430c 100644 --- a/src/main/java/org/elasticsearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java +++ b/src/main/java/org/elasticsearch/index/fielddata/ordinals/GlobalOrdinalsBuilder.java @@ -26,6 +26,7 @@ import org.elasticsearch.common.breaker.CircuitBreaker; import org.elasticsearch.common.logging.ESLogger; import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.index.fielddata.AtomicOrdinalsFieldData; import org.elasticsearch.index.fielddata.IndexOrdinalsFieldData; import org.elasticsearch.indices.breaker.CircuitBreakerService; @@ -43,7 +44,7 @@ public enum GlobalOrdinalsBuilder { */ public static IndexOrdinalsFieldData build(final IndexReader indexReader, IndexOrdinalsFieldData indexFieldData, Settings settings, CircuitBreakerService breakerService, ESLogger logger) throws IOException { assert indexReader.leaves().size() > 1; - long startTime = System.currentTimeMillis(); + long startTimeNS = System.nanoTime(); final AtomicOrdinalsFieldData[] atomicFD = new AtomicOrdinalsFieldData[indexReader.leaves().size()]; final RandomAccessOrds[] subs = new RandomAccessOrds[indexReader.leaves().size()]; @@ -60,7 +61,7 @@ public static IndexOrdinalsFieldData build(final IndexReader indexReader, IndexO "Global-ordinals[{}][{}] took {} ms", indexFieldData.getFieldNames().fullName(), ordinalMap.getValueCount(), - (System.currentTimeMillis() - startTime) + TimeValue.nsecToMSec(System.nanoTime() - startTimeNS) ); } return new InternalGlobalOrdinalsIndexFieldData(indexFieldData.index(), settings, indexFieldData.getFieldNames(), diff --git a/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java b/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java index 3f6c85dcd2b23..806036e755e01 100644 --- a/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java +++ b/src/main/java/org/elasticsearch/index/indexing/ShardIndexingService.java @@ -26,6 +26,7 @@ import org.elasticsearch.common.metrics.MeanMetric; import org.elasticsearch.common.regex.Regex; import org.elasticsearch.common.settings.Settings; +import org.elasticsearch.common.unit.TimeValue; import org.elasticsearch.index.engine.Engine; import org.elasticsearch.index.indexing.slowlog.ShardSlowLogIndexingService; import org.elasticsearch.index.settings.IndexSettings; @@ -269,33 +270,33 @@ static class StatsHolder { public final CounterMetric noopUpdates = new CounterMetric(); public final CounterMetric throttleTimeMillisMetric = new CounterMetric(); volatile boolean isThrottled = false; - volatile long startOfThrottleMillis; + volatile long startOfThrottleNS; public IndexingStats.Stats stats() { - long currentThrottleMillis = 0; - if (isThrottled && startOfThrottleMillis != 0) { - currentThrottleMillis += System.currentTimeMillis() - startOfThrottleMillis; - if (currentThrottleMillis < 0) { - //Timeslip must have happened, have to ignore this value - currentThrottleMillis = 0; + long currentThrottleNS = 0; + if (isThrottled && startOfThrottleNS != 0) { + currentThrottleNS += System.nanoTime() - startOfThrottleNS; + if (currentThrottleNS < 0) { + // Paranoia (System.nanoTime() is supposed to be monotonic): time slip must have happened, have to ignore this value + currentThrottleNS = 0; } } return new IndexingStats.Stats( indexMetric.count(), TimeUnit.NANOSECONDS.toMillis(indexMetric.sum()), indexCurrent.count(), deleteMetric.count(), TimeUnit.NANOSECONDS.toMillis(deleteMetric.sum()), deleteCurrent.count(), - noopUpdates.count(), isThrottled, TimeUnit.MILLISECONDS.toMillis(throttleTimeMillisMetric.count() + currentThrottleMillis)); + noopUpdates.count(), isThrottled, TimeUnit.MILLISECONDS.toMillis(throttleTimeMillisMetric.count() + TimeValue.nsecToMSec(currentThrottleNS))); } void setThrottled(boolean isThrottled) { if (!this.isThrottled && isThrottled) { - startOfThrottleMillis = System.currentTimeMillis(); + startOfThrottleNS = System.nanoTime(); } else if (this.isThrottled && !isThrottled) { - assert startOfThrottleMillis > 0 : "Bad state of startOfThrottleMillis"; - long throttleTimeMillis = System.currentTimeMillis() - startOfThrottleMillis; - if (throttleTimeMillis >= 0) { - //A timeslip may have occured but never want to add a negative number - throttleTimeMillisMetric.inc(throttleTimeMillis); + assert startOfThrottleNS > 0 : "Bad state of startOfThrottleNS"; + long throttleTimeNS = System.nanoTime() - startOfThrottleNS; + if (throttleTimeNS >= 0) { + // Paranoia (System.nanoTime() is supposed to be monotonic): time slip may have occurred but never want to add a negative number + throttleTimeMillisMetric.inc(TimeValue.nsecToMSec(throttleTimeNS)); } } this.isThrottled = isThrottled; diff --git a/src/main/java/org/elasticsearch/index/shard/IndexShard.java b/src/main/java/org/elasticsearch/index/shard/IndexShard.java index 96b95d818653c..41eb03c71b657 100644 --- a/src/main/java/org/elasticsearch/index/shard/IndexShard.java +++ b/src/main/java/org/elasticsearch/index/shard/IndexShard.java @@ -1203,7 +1203,7 @@ public void run() { private void checkIndex(boolean throwException) throws IndexShardException { try { - long time = System.currentTimeMillis(); + long timeNS = System.nanoTime(); if (!Lucene.indexExists(store.directory())) { return; } @@ -1238,7 +1238,7 @@ private void checkIndex(boolean throwException) throws IndexShardException { logger.debug("check index [success]\n{}", new String(os.bytes().toBytes(), Charsets.UTF_8)); } } - recoveryState.getStart().checkIndexTime(Math.max(0, System.currentTimeMillis() - time)); + recoveryState.getStart().checkIndexTime(Math.max(0, TimeValue.nsecToMSec(System.nanoTime() - timeNS))); } catch (Exception e) { logger.warn("failed to check index", e); } diff --git a/src/main/java/org/elasticsearch/index/store/Store.java b/src/main/java/org/elasticsearch/index/store/Store.java index b20eb531f1123..d0534b4a9dc2e 100644 --- a/src/main/java/org/elasticsearch/index/store/Store.java +++ b/src/main/java/org/elasticsearch/index/store/Store.java @@ -1167,10 +1167,8 @@ public synchronized void write(Store store) throws IOException { } synchronized void writeChecksums(Directory directory, Map checksums, long lastVersion) throws IOException { - long nextVersion = System.currentTimeMillis(); - while (nextVersion <= lastVersion) { - nextVersion = System.currentTimeMillis(); - } + // Make sure if clock goes backwards we still move version forwards: + long nextVersion = Math.max(lastVersion+1, System.currentTimeMillis()); final String checksumName = CHECKSUMS_PREFIX + nextVersion; try (IndexOutput output = directory.createOutput(checksumName, IOContext.DEFAULT)) { output.writeInt(0); // version diff --git a/src/main/java/org/elasticsearch/indices/IndicesService.java b/src/main/java/org/elasticsearch/indices/IndicesService.java index 60da6020d4b06..fb16a44ec022a 100644 --- a/src/main/java/org/elasticsearch/indices/IndicesService.java +++ b/src/main/java/org/elasticsearch/indices/IndicesService.java @@ -709,7 +709,7 @@ public int compareTo(PendingDelete o) { */ public void processPendingDeletes(Index index, @IndexSettings Settings indexSettings, TimeValue timeout) throws IOException { logger.debug("{} processing pending deletes", index); - final long startTime = System.currentTimeMillis(); + final long startTimeNS = System.nanoTime(); final List shardLocks = nodeEnv.lockAllForIndex(index, indexSettings, timeout.millis()); try { Map locks = new HashMap<>(); @@ -768,7 +768,7 @@ public void processPendingDeletes(Index index, @IndexSettings Settings indexSett return; } } - } while ((System.currentTimeMillis() - startTime) < timeout.millis()); + } while ((System.nanoTime() - startTimeNS) < timeout.nanos()); } } finally { IOUtils.close(shardLocks); diff --git a/src/main/java/org/elasticsearch/indices/fielddata/cache/IndicesFieldDataCache.java b/src/main/java/org/elasticsearch/indices/fielddata/cache/IndicesFieldDataCache.java index 3ff75591aa3f4..a1d358bda12a8 100644 --- a/src/main/java/org/elasticsearch/indices/fielddata/cache/IndicesFieldDataCache.java +++ b/src/main/java/org/elasticsearch/indices/fielddata/cache/IndicesFieldDataCache.java @@ -318,7 +318,7 @@ public FieldDataCacheCleaner(Cache cache, ESLogger logger, ThreadPool threadPool @Override public void run() { - long startTime = System.currentTimeMillis(); + long startTimeNS = System.nanoTime(); if (logger.isTraceEnabled()) { logger.trace("running periodic field data cache cleanup"); } @@ -328,7 +328,7 @@ public void run() { logger.warn("Exception during periodic field data cache cleanup:", e); } if (logger.isTraceEnabled()) { - logger.trace("periodic field data cache cleanup finished in {} milliseconds", System.currentTimeMillis() - startTime); + logger.trace("periodic field data cache cleanup finished in {} milliseconds", TimeValue.nsecToMSec(System.nanoTime() - startTimeNS)); } // Reschedule itself to run again if not closed if (closed == false) { diff --git a/src/main/java/org/elasticsearch/indices/recovery/RecoveryState.java b/src/main/java/org/elasticsearch/indices/recovery/RecoveryState.java index fb855a376c8e0..dea74815e622f 100644 --- a/src/main/java/org/elasticsearch/indices/recovery/RecoveryState.java +++ b/src/main/java/org/elasticsearch/indices/recovery/RecoveryState.java @@ -397,13 +397,15 @@ public static class Timer implements Streamable { public synchronized void start() { assert startTime == 0 : "already started"; - startTime = System.currentTimeMillis(); + startTime = TimeValue.nsecToMSec(System.nanoTime()); } + /** Returns start time in millis */ public synchronized long startTime() { return startTime; } + /** Returns elapsed time in millis, or 0 if timer was not started */ public synchronized long time() { if (startTime == 0) { return 0; @@ -411,16 +413,17 @@ public synchronized long time() { if (time >= 0) { return time; } - return Math.max(0, System.currentTimeMillis() - startTime); + return Math.max(0, TimeValue.nsecToMSec(System.nanoTime()) - startTime); } + /** Returns stop time in millis */ public synchronized long stopTime() { return stopTime; } public synchronized void stop() { assert stopTime == 0 : "already stopped"; - stopTime = Math.max(System.currentTimeMillis(), startTime); + stopTime = Math.max(TimeValue.nsecToMSec(System.nanoTime()), startTime); time = stopTime - startTime; assert time >= 0; } diff --git a/src/main/java/org/elasticsearch/indices/store/TransportNodesListShardStoreMetaData.java b/src/main/java/org/elasticsearch/indices/store/TransportNodesListShardStoreMetaData.java index 6db1f201110eb..dff4cc27f5727 100644 --- a/src/main/java/org/elasticsearch/indices/store/TransportNodesListShardStoreMetaData.java +++ b/src/main/java/org/elasticsearch/indices/store/TransportNodesListShardStoreMetaData.java @@ -54,6 +54,7 @@ import java.util.List; import java.util.Map; import java.util.Set; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicReferenceArray; /** @@ -146,7 +147,7 @@ protected NodeStoreFilesMetaData nodeOperation(NodeRequest request) throws Elast private StoreFilesMetaData listStoreMetaData(ShardId shardId) throws IOException { logger.trace("listing store meta data for {}", shardId); - long startTime = System.currentTimeMillis(); + long startTimeNS = System.nanoTime(); boolean exists = false; try { IndexService indexService = indicesService.indexService(shardId.index().name()); @@ -188,7 +189,7 @@ private StoreFilesMetaData listStoreMetaData(ShardId shardId) throws IOException } return new StoreFilesMetaData(false, shardId, Store.readMetadataSnapshot(shardIndexLocations, logger).asMap()); } finally { - TimeValue took = new TimeValue(System.currentTimeMillis() - startTime); + TimeValue took = new TimeValue(System.nanoTime() - startTimeNS, TimeUnit.NANOSECONDS); if (exists) { logger.debug("{} loaded store meta data (took [{}])", shardId, took); } else { diff --git a/src/main/java/org/elasticsearch/plugins/PluginsService.java b/src/main/java/org/elasticsearch/plugins/PluginsService.java index da0b5a7b7267a..5a88f0b95b9da 100644 --- a/src/main/java/org/elasticsearch/plugins/PluginsService.java +++ b/src/main/java/org/elasticsearch/plugins/PluginsService.java @@ -73,7 +73,7 @@ public class PluginsService extends AbstractComponent { private PluginsInfo cachedPluginsInfo; private final TimeValue refreshInterval; private final boolean checkLucene; - private long lastRefresh; + private long lastRefreshNS; static class OnModuleReference { public final Class moduleClass; @@ -298,13 +298,13 @@ public Collection> shardServices() { synchronized public PluginsInfo info() { if (refreshInterval.millis() != 0) { if (cachedPluginsInfo != null && - (refreshInterval.millis() < 0 || (System.currentTimeMillis() - lastRefresh) < refreshInterval.millis())) { + (refreshInterval.millis() < 0 || (System.nanoTime() - lastRefreshNS) < refreshInterval.nanos())) { if (logger.isTraceEnabled()) { logger.trace("using cache to retrieve plugins info"); } return cachedPluginsInfo; } - lastRefresh = System.currentTimeMillis(); + lastRefreshNS = System.nanoTime(); } if (logger.isTraceEnabled()) {