diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index 3a722b90476..b49f18b8c2a 100644 --- a/src/main/java/org/tikv/common/log/SlowLogImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java @@ -38,6 +38,11 @@ public class SlowLogImpl implements SlowLog { private Throwable error = null; private final long startMS; + /** + * use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic + */ + private final long startNS; + private final long slowThresholdMS; /** Key-Value pairs which will be logged, e.g. function name, key, region, etc. */ @@ -45,6 +50,7 @@ public class SlowLogImpl implements SlowLog { public SlowLogImpl(long slowThresholdMS, Map properties) { this.startMS = System.currentTimeMillis(); + this.startNS = System.nanoTime(); this.slowThresholdMS = slowThresholdMS; this.properties = new HashMap<>(properties); } @@ -56,7 +62,7 @@ public void addProperty(String key, String value) { @Override public synchronized SlowLogSpan start(String name) { - SlowLogSpan slowLogSpan = new SlowLogSpanImpl(name); + SlowLogSpan slowLogSpan = new SlowLogSpanImpl(name, startMS, startNS); if (slowLogSpans.size() < MAX_SPAN_SIZE) { slowLogSpans.add(slowLogSpan); } @@ -71,7 +77,8 @@ public void setError(Throwable err) { @Override public void log() { - long currentMS = System.currentTimeMillis(); + long currentNS = System.nanoTime(); + long currentMS = startMS + (currentNS - startNS) / 1_000_000; if (error != null || (slowThresholdMS >= 0 && currentMS - startMS > slowThresholdMS)) { logger.warn("SlowLog:" + getSlowLogString(currentMS)); } diff --git a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java index 960baeb41dc..20b95d57127 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -24,23 +24,38 @@ public class SlowLogSpanImpl implements SlowLogSpan { private final String name; + private final long requestStartNS; + private final long requestStartMS; + private long startMS; private long endMS; + /** + * use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic + */ + private long startNS; + + private long endNS; - public SlowLogSpanImpl(String name) { + public SlowLogSpanImpl(String name, long requestStartMS, long requestStartNS) { this.name = name; + this.requestStartMS = requestStartMS; + this.requestStartNS = requestStartNS; this.startMS = 0; + this.startNS = 0; this.endMS = 0; + this.endNS = 0; } @Override public void start() { - this.startMS = System.currentTimeMillis(); + startNS = System.nanoTime(); + startMS = requestStartMS + (startNS - requestStartNS) / 1_000_000; } @Override public void end() { - this.endMS = System.currentTimeMillis(); + endNS = System.nanoTime(); + endMS = startMS + (endNS - startNS) / 1_000_000; } @Override