From f12d19d0a1a93703d21889be68b606660811d9dd Mon Sep 17 00:00:00 2001
From: Liangliang Gu <marsishandsome@gmail.com>
Date: Mon, 6 Dec 2021 15:38:25 +0800
Subject: [PATCH] log SlowLog if error occures (#361)

---
 src/main/java/org/tikv/common/log/SlowLog.java        |  2 ++
 .../java/org/tikv/common/log/SlowLogEmptyImpl.java    |  3 +++
 src/main/java/org/tikv/common/log/SlowLogImpl.java    | 11 ++++++++++-
 src/main/java/org/tikv/raw/RawKVClient.java           | 10 ++++++++++
 4 files changed, 25 insertions(+), 1 deletion(-)

diff --git a/src/main/java/org/tikv/common/log/SlowLog.java b/src/main/java/org/tikv/common/log/SlowLog.java
index e172a00346..007f3f1d73 100644
--- a/src/main/java/org/tikv/common/log/SlowLog.java
+++ b/src/main/java/org/tikv/common/log/SlowLog.java
@@ -22,5 +22,7 @@ public interface SlowLog {
 
   SlowLogSpan start(String name);
 
+  void setError(Throwable err);
+
   void log();
 }
diff --git a/src/main/java/org/tikv/common/log/SlowLogEmptyImpl.java b/src/main/java/org/tikv/common/log/SlowLogEmptyImpl.java
index 37e68237db..5e76031f7c 100644
--- a/src/main/java/org/tikv/common/log/SlowLogEmptyImpl.java
+++ b/src/main/java/org/tikv/common/log/SlowLogEmptyImpl.java
@@ -30,6 +30,9 @@ public class SlowLogEmptyImpl implements SlowLog {
     return SlowLogSpanEmptyImpl.INSTANCE;
   }
 
+  @Override
+  public void setError(Throwable err) {}
+
   @Override
   public void log() {}
 }
diff --git a/src/main/java/org/tikv/common/log/SlowLogImpl.java b/src/main/java/org/tikv/common/log/SlowLogImpl.java
index 76ed4c922b..3a722b9047 100644
--- a/src/main/java/org/tikv/common/log/SlowLogImpl.java
+++ b/src/main/java/org/tikv/common/log/SlowLogImpl.java
@@ -35,6 +35,7 @@ public class SlowLogImpl implements SlowLog {
   public static final SimpleDateFormat DATE_FORMAT = new SimpleDateFormat("HH:mm:ss.SSS");
 
   private final List<SlowLogSpan> slowLogSpans = new ArrayList<>();
+  private Throwable error = null;
 
   private final long startMS;
   private final long slowThresholdMS;
@@ -63,10 +64,15 @@ public class SlowLogImpl implements SlowLog {
     return slowLogSpan;
   }
 
+  @Override
+  public void setError(Throwable err) {
+    this.error = err;
+  }
+
   @Override
   public void log() {
     long currentMS = System.currentTimeMillis();
-    if (slowThresholdMS >= 0 && currentMS - startMS > slowThresholdMS) {
+    if (error != null || (slowThresholdMS >= 0 && currentMS - startMS > slowThresholdMS)) {
       logger.warn("SlowLog:" + getSlowLogString(currentMS));
     }
   }
@@ -77,6 +83,9 @@ public class SlowLogImpl implements SlowLog {
     jsonObject.addProperty("start", DATE_FORMAT.format(startMS));
     jsonObject.addProperty("end", DATE_FORMAT.format(currentMS));
     jsonObject.addProperty("duration", (currentMS - startMS) + "ms");
+    if (error != null) {
+      jsonObject.addProperty("error", error.getMessage());
+    }
 
     for (Map.Entry<String, String> entry : properties.entrySet()) {
       jsonObject.addProperty(entry.getKey(), entry.getValue());
diff --git a/src/main/java/org/tikv/raw/RawKVClient.java b/src/main/java/org/tikv/raw/RawKVClient.java
index a5f3dd6f3b..7ffd1ed051 100644
--- a/src/main/java/org/tikv/raw/RawKVClient.java
+++ b/src/main/java/org/tikv/raw/RawKVClient.java
@@ -151,6 +151,7 @@ public class RawKVClient implements AutoCloseable {
       }
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -249,6 +250,7 @@ public class RawKVClient implements AutoCloseable {
       }
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -291,6 +293,7 @@ public class RawKVClient implements AutoCloseable {
       RAW_REQUEST_SUCCESS.labels(label).inc();
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -333,6 +336,7 @@ public class RawKVClient implements AutoCloseable {
       }
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -367,6 +371,7 @@ public class RawKVClient implements AutoCloseable {
       return result;
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -400,6 +405,7 @@ public class RawKVClient implements AutoCloseable {
       return;
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -442,6 +448,7 @@ public class RawKVClient implements AutoCloseable {
       }
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -589,6 +596,7 @@ public class RawKVClient implements AutoCloseable {
       return result;
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -677,6 +685,7 @@ public class RawKVClient implements AutoCloseable {
       return result;
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();
@@ -745,6 +754,7 @@ public class RawKVClient implements AutoCloseable {
       }
     } catch (Exception e) {
       RAW_REQUEST_FAILURE.labels(label).inc();
+      slowLog.setError(e);
       throw e;
     } finally {
       requestTimer.observeDuration();