From b36692c40838d007fd49db6e29ddfe5194c75b43 Mon Sep 17 00:00:00 2001 From: marsishandsome Date: Tue, 14 Dec 2021 18:44:23 +0800 Subject: [PATCH 1/6] use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic Signed-off-by: marsishandsome --- .../java/org/tikv/common/log/SlowLogImpl.java | 16 ++++++++++++---- .../org/tikv/common/log/SlowLogSpanImpl.java | 12 +++++++++++- 2 files changed, 23 insertions(+), 5 deletions(-) diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index 3a722b90476..95e2680283b 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 startNano; + 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.startNano = System.nanoTime(); this.slowThresholdMS = slowThresholdMS; this.properties = new HashMap<>(properties); } @@ -72,17 +78,19 @@ public void setError(Throwable err) { @Override public void log() { long currentMS = System.currentTimeMillis(); - if (error != null || (slowThresholdMS >= 0 && currentMS - startMS > slowThresholdMS)) { - logger.warn("SlowLog:" + getSlowLogString(currentMS)); + long currentNano = System.nanoTime(); + if (error != null + || (slowThresholdMS >= 0 && currentNano - startNano > slowThresholdMS * 1000000)) { + logger.warn("SlowLog:" + getSlowLogString(currentMS, currentNano)); } } - private String getSlowLogString(long currentMS) { + private String getSlowLogString(long currentMS, long currentNano) { JsonObject jsonObject = new JsonObject(); jsonObject.addProperty("start", DATE_FORMAT.format(startMS)); jsonObject.addProperty("end", DATE_FORMAT.format(currentMS)); - jsonObject.addProperty("duration", (currentMS - startMS) + "ms"); + jsonObject.addProperty("duration", ((currentNano - startNano) / 1000000) + "ms"); if (error != null) { jsonObject.addProperty("error", error.getMessage()); } diff --git a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java index 960baeb41dc..7f97c871fa1 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -26,21 +26,31 @@ public class SlowLogSpanImpl implements SlowLogSpan { private final String name; private long startMS; private long endMS; + /** + * use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic + */ + private long startNano; + + private long endNano; public SlowLogSpanImpl(String name) { this.name = name; this.startMS = 0; + this.startNano = 0; this.endMS = 0; + this.endNano = 0; } @Override public void start() { this.startMS = System.currentTimeMillis(); + this.startNano = System.nanoTime(); } @Override public void end() { this.endMS = System.currentTimeMillis(); + this.endNano = System.nanoTime(); } @Override @@ -72,6 +82,6 @@ private String getDurationString() { if (startMS == 0 || endMS == 0) { return "N/A"; } - return (endMS - startMS) + "ms"; + return ((endNano - startNano) / 1000000) + "ms"; } } From d7842979f7c79bf293d1175f59dbc845366df008 Mon Sep 17 00:00:00 2001 From: marsishandsome Date: Wed, 15 Dec 2021 10:27:19 +0800 Subject: [PATCH 2/6] startNano -> startNS Signed-off-by: marsishandsome --- src/main/java/org/tikv/common/log/SlowLogImpl.java | 14 +++++++------- .../java/org/tikv/common/log/SlowLogSpanImpl.java | 14 +++++++------- 2 files changed, 14 insertions(+), 14 deletions(-) diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index 95e2680283b..c6e0a6cea47 100644 --- a/src/main/java/org/tikv/common/log/SlowLogImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java @@ -41,7 +41,7 @@ public class SlowLogImpl implements SlowLog { /** * use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic */ - private final long startNano; + private final long startNS; private final long slowThresholdMS; @@ -50,7 +50,7 @@ public class SlowLogImpl implements SlowLog { public SlowLogImpl(long slowThresholdMS, Map properties) { this.startMS = System.currentTimeMillis(); - this.startNano = System.nanoTime(); + this.startNS = System.nanoTime(); this.slowThresholdMS = slowThresholdMS; this.properties = new HashMap<>(properties); } @@ -78,19 +78,19 @@ public void setError(Throwable err) { @Override public void log() { long currentMS = System.currentTimeMillis(); - long currentNano = System.nanoTime(); + long currentNS = System.nanoTime(); if (error != null - || (slowThresholdMS >= 0 && currentNano - startNano > slowThresholdMS * 1000000)) { - logger.warn("SlowLog:" + getSlowLogString(currentMS, currentNano)); + || (slowThresholdMS >= 0 && currentNS - startNS > slowThresholdMS * 1000000)) { + logger.warn("SlowLog:" + getSlowLogString(currentMS, currentNS)); } } - private String getSlowLogString(long currentMS, long currentNano) { + private String getSlowLogString(long currentMS, long currentNS) { JsonObject jsonObject = new JsonObject(); jsonObject.addProperty("start", DATE_FORMAT.format(startMS)); jsonObject.addProperty("end", DATE_FORMAT.format(currentMS)); - jsonObject.addProperty("duration", ((currentNano - startNano) / 1000000) + "ms"); + jsonObject.addProperty("duration", ((currentNS - startNS) / 1000000) + "ms"); if (error != null) { jsonObject.addProperty("error", error.getMessage()); } diff --git a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java index 7f97c871fa1..c6bbf8b5ec5 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -29,28 +29,28 @@ public class SlowLogSpanImpl implements SlowLogSpan { /** * use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic */ - private long startNano; + private long startNS; - private long endNano; + private long endNS; public SlowLogSpanImpl(String name) { this.name = name; this.startMS = 0; - this.startNano = 0; + this.startNS = 0; this.endMS = 0; - this.endNano = 0; + this.endNS = 0; } @Override public void start() { this.startMS = System.currentTimeMillis(); - this.startNano = System.nanoTime(); + this.startNS = System.nanoTime(); } @Override public void end() { this.endMS = System.currentTimeMillis(); - this.endNano = System.nanoTime(); + this.endNS = System.nanoTime(); } @Override @@ -82,6 +82,6 @@ private String getDurationString() { if (startMS == 0 || endMS == 0) { return "N/A"; } - return ((endNano - startNano) / 1000000) + "ms"; + return ((endNS - startNS) / 1000000) + "ms"; } } From f6e7aa8593b8990c78e24aa1f4c1082701c2403d Mon Sep 17 00:00:00 2001 From: marsishandsome Date: Wed, 15 Dec 2021 11:15:44 +0800 Subject: [PATCH 3/6] remove System.currentTimeMillis() Signed-off-by: marsishandsome --- .../java/org/tikv/common/log/SlowLogImpl.java | 4 ++-- .../java/org/tikv/common/log/SlowLogSpanImpl.java | 15 ++++++++++----- 2 files changed, 12 insertions(+), 7 deletions(-) diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index c6e0a6cea47..54b3dce9fd2 100644 --- a/src/main/java/org/tikv/common/log/SlowLogImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java @@ -62,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); } @@ -77,8 +77,8 @@ public void setError(Throwable err) { @Override public void log() { - long currentMS = System.currentTimeMillis(); long currentNS = System.nanoTime(); + long currentMS = startMS + (currentNS - startNS) / 1000000; if (error != null || (slowThresholdMS >= 0 && currentNS - startNS > slowThresholdMS * 1000000)) { logger.warn("SlowLog:" + getSlowLogString(currentMS, currentNS)); diff --git a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java index c6bbf8b5ec5..1040fc41a9a 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -24,6 +24,9 @@ public class SlowLogSpanImpl implements SlowLogSpan { private final String name; + private final long requestStartNS; + private final long requestStartMS; + private long startMS; private long endMS; /** @@ -33,8 +36,10 @@ public class SlowLogSpanImpl implements SlowLogSpan { 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; @@ -43,14 +48,14 @@ public SlowLogSpanImpl(String name) { @Override public void start() { - this.startMS = System.currentTimeMillis(); - this.startNS = System.nanoTime(); + startNS = System.nanoTime(); + startMS = requestStartMS + (startNS - requestStartNS) / 1000000; } @Override public void end() { - this.endMS = System.currentTimeMillis(); - this.endNS = System.nanoTime(); + endNS = System.nanoTime(); + endMS = startMS + (endNS - startNS) / 1000000; } @Override From d04f417f66e23ea840426c10e879ee52321cc6b5 Mon Sep 17 00:00:00 2001 From: marsishandsome Date: Wed, 15 Dec 2021 11:33:18 +0800 Subject: [PATCH 4/6] address code review Signed-off-by: marsishandsome --- src/main/java/org/tikv/common/log/SlowLogImpl.java | 9 ++++----- src/main/java/org/tikv/common/log/SlowLogSpanImpl.java | 2 +- 2 files changed, 5 insertions(+), 6 deletions(-) diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index 54b3dce9fd2..bce5f06888c 100644 --- a/src/main/java/org/tikv/common/log/SlowLogImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java @@ -79,18 +79,17 @@ public void setError(Throwable err) { public void log() { long currentNS = System.nanoTime(); long currentMS = startMS + (currentNS - startNS) / 1000000; - if (error != null - || (slowThresholdMS >= 0 && currentNS - startNS > slowThresholdMS * 1000000)) { - logger.warn("SlowLog:" + getSlowLogString(currentMS, currentNS)); + if (error != null || (slowThresholdMS >= 0 && currentMS - startMS > slowThresholdMS)) { + logger.warn("SlowLog:" + getSlowLogString(currentMS)); } } - private String getSlowLogString(long currentMS, long currentNS) { + private String getSlowLogString(long currentMS) { JsonObject jsonObject = new JsonObject(); jsonObject.addProperty("start", DATE_FORMAT.format(startMS)); jsonObject.addProperty("end", DATE_FORMAT.format(currentMS)); - jsonObject.addProperty("duration", ((currentNS - startNS) / 1000000) + "ms"); + jsonObject.addProperty("duration", (currentMS - startMS) + "ms"); if (error != null) { jsonObject.addProperty("error", error.getMessage()); } diff --git a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java index 1040fc41a9a..723aad614f4 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -87,6 +87,6 @@ private String getDurationString() { if (startMS == 0 || endMS == 0) { return "N/A"; } - return ((endNS - startNS) / 1000000) + "ms"; + return (endMS - startMS) + "ms"; } } From 952975022b779f74419a28f3f15d6caea217dc40 Mon Sep 17 00:00:00 2001 From: marsishandsome Date: Wed, 15 Dec 2021 15:43:14 +0800 Subject: [PATCH 5/6] address code review Signed-off-by: marsishandsome --- src/main/java/org/tikv/common/log/SlowLogImpl.java | 2 +- src/main/java/org/tikv/common/log/SlowLogSpanImpl.java | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index bce5f06888c..5c5a34177aa 100644 --- a/src/main/java/org/tikv/common/log/SlowLogImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java @@ -78,7 +78,7 @@ public void setError(Throwable err) { @Override public void log() { long currentNS = System.nanoTime(); - long currentMS = startMS + (currentNS - startNS) / 1000000; + long currentMS = startMS + (currentNS - startNS) / 10_00_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 723aad614f4..b5fa06b1603 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -49,13 +49,13 @@ public SlowLogSpanImpl(String name, long requestStartMS, long requestStartNS) { @Override public void start() { startNS = System.nanoTime(); - startMS = requestStartMS + (startNS - requestStartNS) / 1000000; + startMS = requestStartMS + (startNS - requestStartNS) / 10_00_000; } @Override public void end() { endNS = System.nanoTime(); - endMS = startMS + (endNS - startNS) / 1000000; + endMS = startMS + (endNS - startNS) / 10_00_000; } @Override From 1edf58ba2b003376ea642947c432be0ae6b3fa10 Mon Sep 17 00:00:00 2001 From: marsishandsome Date: Wed, 15 Dec 2021 16:19:37 +0800 Subject: [PATCH 6/6] address code review Signed-off-by: marsishandsome --- src/main/java/org/tikv/common/log/SlowLogImpl.java | 2 +- src/main/java/org/tikv/common/log/SlowLogSpanImpl.java | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java index 5c5a34177aa..b49f18b8c2a 100644 --- a/src/main/java/org/tikv/common/log/SlowLogImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java @@ -78,7 +78,7 @@ public void setError(Throwable err) { @Override public void log() { long currentNS = System.nanoTime(); - long currentMS = startMS + (currentNS - startNS) / 10_00_000; + 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 b5fa06b1603..20b95d57127 100644 --- a/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java +++ b/src/main/java/org/tikv/common/log/SlowLogSpanImpl.java @@ -49,13 +49,13 @@ public SlowLogSpanImpl(String name, long requestStartMS, long requestStartNS) { @Override public void start() { startNS = System.nanoTime(); - startMS = requestStartMS + (startNS - requestStartNS) / 10_00_000; + startMS = requestStartMS + (startNS - requestStartNS) / 1_000_000; } @Override public void end() { endNS = System.nanoTime(); - endMS = startMS + (endNS - startNS) / 10_00_000; + endMS = startMS + (endNS - startNS) / 1_000_000; } @Override