INTERNAL: Add actual elapsed duration to timeout exception message.

naver · Jul 17, 2024 · 776b893 · 776b893
1 parent 7f3daab
commit 776b893
Show file tree

Hide file tree

Showing 11 changed files with 63 additions and 24 deletions.
diff --git a/src/main/java/net/spy/memcached/TimedOutMessageFactory.java b/src/main/java/net/spy/memcached/TimedOutMessageFactory.java
@@ -14,7 +14,9 @@ private TimedOutMessageFactory() {
 
   public static String createTimedOutMessage(long duration,
                                              TimeUnit unit,
+                                             long elapsed,
                                              Collection<Operation> ops) {
+
     StringBuilder rv = new StringBuilder();
     Operation firstOp = ops.iterator().next();
     if (isBulkOperation(firstOp, ops)) {
@@ -25,7 +27,9 @@ public static String createTimedOutMessage(long duration,
     }
 
     rv.append(firstOp.getAPIType());
-    rv.append(" operation timed out (>").append(duration);
+    rv.append(" operation timed out (");
+    rv.append(unit.convert(elapsed, TimeUnit.MILLISECONDS));
+    rv.append(" >= ").append(duration);
     rv.append(" ").append(unit).append(") - ");
 
     rv.append("failing node");

diff --git a/src/main/java/net/spy/memcached/internal/BroadcastFuture.java b/src/main/java/net/spy/memcached/internal/BroadcastFuture.java
@@ -54,6 +54,8 @@ public boolean isDone() {
   @Override
   public T get(long duration, TimeUnit unit)
           throws InterruptedException, TimeoutException, ExecutionException {
+
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(duration, unit)) {
       // whenever timeout occurs, continuous timeout counter will increase by 1.
       Collection<Operation> timedOutOps = new HashSet<>();
@@ -66,7 +68,8 @@ public T get(long duration, TimeUnit unit)
         }
       }
       if (!timedOutOps.isEmpty()) {
-        throw new CheckedOperationTimeoutException(duration, unit, timedOutOps);
+        long elapsed = System.currentTimeMillis() - beforeAwait;
+        throw new CheckedOperationTimeoutException(duration, unit, elapsed, timedOutOps);
       }
     } else {
       // continuous timeout counter will be reset

diff --git a/src/main/java/net/spy/memcached/internal/BulkGetFuture.java b/src/main/java/net/spy/memcached/internal/BulkGetFuture.java
@@ -134,6 +134,7 @@ public int getOpCount() {
   private Map<String, T> internalGet(long to, TimeUnit unit, boolean throwOnTimeout)
            throws InterruptedException, ExecutionException, TimeoutException {
 
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(to, unit)) {
       Collection<Operation> timedOutOps = new HashSet<>();
       for (Operation op : ops) {
@@ -147,7 +148,8 @@ private Map<String, T> internalGet(long to, TimeUnit unit, boolean throwOnTimeou
         MemcachedConnection.opsTimedOut(timedOutOps);
         isTimeout.set(true);
 
-        TimeoutException e = new CheckedOperationTimeoutException(to, unit, timedOutOps);
+        long elapsed = System.currentTimeMillis() - beforeAwait;
+        TimeoutException e = new CheckedOperationTimeoutException(to, unit, elapsed, timedOutOps);
         if (throwOnTimeout) {
           throw e;
         }

diff --git a/src/main/java/net/spy/memcached/internal/BulkOperationFuture.java b/src/main/java/net/spy/memcached/internal/BulkOperationFuture.java
@@ -69,6 +69,8 @@ public Map<String, T> get() throws InterruptedException, ExecutionException {
   public Map<String, T> get(long duration,
                             TimeUnit unit) throws InterruptedException,
           TimeoutException, ExecutionException {
+
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(duration, unit)) {
       Collection<Operation> timedOutOps = new HashSet<>();
       for (Operation op : ops) {
@@ -80,7 +82,9 @@ public Map<String, T> get(long duration,
       }
       if (!timedOutOps.isEmpty()) {
         MemcachedConnection.opsTimedOut(timedOutOps);
-        throw new CheckedOperationTimeoutException(duration, unit, timedOutOps);
+
+        long elapsed = System.currentTimeMillis() - beforeAwait;
+        throw new CheckedOperationTimeoutException(duration, unit, elapsed, timedOutOps);
       }
     } else {
       // continuous timeout counter will be reset

diff --git a/src/main/java/net/spy/memcached/internal/CheckedOperationTimeoutException.java b/src/main/java/net/spy/memcached/internal/CheckedOperationTimeoutException.java
@@ -34,14 +34,16 @@ public class CheckedOperationTimeoutException extends TimeoutException {
 
   public CheckedOperationTimeoutException(long duration,
                                           TimeUnit unit,
+                                          long elapsed,
                                           Operation op) {
-    this(duration, unit, Collections.singleton(op));
+    this(duration, unit, elapsed, Collections.singleton(op));
   }
 
   public CheckedOperationTimeoutException(long duration,
                                           TimeUnit unit,
+                                          long elapsed,
                                           Collection<Operation> ops) {
-    super(TimedOutMessageFactory.createTimedOutMessage(duration, unit, ops));
+    super(TimedOutMessageFactory.createTimedOutMessage(duration, unit, elapsed, ops));
     operations = ops;
   }
 

diff --git a/src/main/java/net/spy/memcached/internal/CollectionGetBulkFuture.java b/src/main/java/net/spy/memcached/internal/CollectionGetBulkFuture.java
@@ -60,18 +60,22 @@ public T get() throws InterruptedException, ExecutionException {
   @Override
   public T get(long duration, TimeUnit unit)
       throws InterruptedException, TimeoutException, ExecutionException {
+
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(duration, unit)) {
-      Collection<Operation> timedDutOps = new HashSet<>();
+      Collection<Operation> timedOutOps = new HashSet<>();
       for (Operation op : ops) {
         if (op.getState() != OperationState.COMPLETE) {
-          timedDutOps.add(op);
+          timedOutOps.add(op);
         } else {
           MemcachedConnection.opSucceeded(op);
         }
       }
-      if (!timedDutOps.isEmpty()) {
-        MemcachedConnection.opsTimedOut(timedDutOps);
-        throw new CheckedOperationTimeoutException(duration, unit, timedDutOps);
+      if (!timedOutOps.isEmpty()) {
+        MemcachedConnection.opsTimedOut(timedOutOps);
+
+        long elapsed = System.currentTimeMillis() - beforeAwait;
+        throw new CheckedOperationTimeoutException(duration, unit, elapsed, timedOutOps);
       }
     } else {
       // continuous timeout counter will be reset

diff --git a/src/main/java/net/spy/memcached/internal/OperationFuture.java b/src/main/java/net/spy/memcached/internal/OperationFuture.java
@@ -73,10 +73,14 @@ public T get() throws InterruptedException, ExecutionException {
 
   public T get(long duration, TimeUnit unit)
           throws InterruptedException, TimeoutException, ExecutionException {
+
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(duration, unit)) {
       // whenever timeout occurs, continuous timeout counter will increase by 1.
       MemcachedConnection.opTimedOut(op);
-      throw new CheckedOperationTimeoutException(duration, unit, op);
+
+      long elapsed = System.currentTimeMillis() - beforeAwait;
+      throw new CheckedOperationTimeoutException(duration, unit, elapsed, op);
     } else {
       // continuous timeout counter will be reset
       MemcachedConnection.opSucceeded(op);

diff --git a/src/main/java/net/spy/memcached/internal/PipedCollectionFuture.java b/src/main/java/net/spy/memcached/internal/PipedCollectionFuture.java
@@ -62,6 +62,7 @@ public boolean isDone() {
   public Map<K, V> get(long duration, TimeUnit unit)
           throws InterruptedException, TimeoutException, ExecutionException {
 
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(duration, unit)) {
       Collection<Operation> timedOutOps = new HashSet<>();
       for (Operation op : ops) {
@@ -74,7 +75,9 @@ public Map<K, V> get(long duration, TimeUnit unit)
       if (!timedOutOps.isEmpty()) {
         // set timeout only once for piped ops requested to single node.
         MemcachedConnection.opTimedOut(timedOutOps.iterator().next());
-        throw new CheckedOperationTimeoutException(duration, unit, timedOutOps);
+
+        long elapsed = System.currentTimeMillis() - beforeAwait;
+        throw new CheckedOperationTimeoutException(duration, unit, elapsed, timedOutOps);
       }
     } else {
       // continuous timeout counter will be reset only once in pipe

diff --git a/src/main/java/net/spy/memcached/internal/SMGetFuture.java b/src/main/java/net/spy/memcached/internal/SMGetFuture.java
@@ -57,6 +57,7 @@ public SMGetFuture(Collection<Operation> ops,
   public T get(long duration, TimeUnit unit)
           throws InterruptedException, TimeoutException, ExecutionException {
 
+    long beforeAwait = System.currentTimeMillis();
     if (!latch.await(duration, unit)) {
       Collection<Operation> timedOutOps = new HashSet<>();
       for (Operation op : ops) {
@@ -68,7 +69,9 @@ public T get(long duration, TimeUnit unit)
       }
       if (!timedOutOps.isEmpty()) {
         MemcachedConnection.opsTimedOut(timedOutOps);
-        throw new CheckedOperationTimeoutException(duration, unit, timedOutOps);
+
+        long elapsed = System.currentTimeMillis() - beforeAwait;
+        throw new CheckedOperationTimeoutException(duration, unit, elapsed, timedOutOps);
       }
     } else {
       // continuous timeout counter will be reset

diff --git a/src/test/java/net/spy/memcached/ArcusTimeoutMessageTest.java b/src/test/java/net/spy/memcached/ArcusTimeoutMessageTest.java
@@ -20,6 +20,7 @@
 import java.net.InetSocketAddress;
 import java.util.ArrayList;
 import java.util.Arrays;
+import java.util.Collection;
 import java.util.Collections;
 import java.util.HashMap;
 import java.util.List;
@@ -29,6 +30,7 @@
 import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.TimeoutException;
+import java.util.regex.Pattern;
 
 import junit.framework.TestCase;
 
@@ -726,11 +728,18 @@ public void complete() {
   }
 
   private String createTimedOutMessage(Operation op) {
-    return TimedOutMessageFactory
-            .createTimedOutMessage(1, TimeUnit.MILLISECONDS, Collections.singletonList(op));
+    Collection<Operation> ops = Collections.singleton(op);
+    return TimedOutMessageFactory.createTimedOutMessage(1, TimeUnit.MILLISECONDS, 0, ops);
   }
 
   private String getTimedOutHeadMessage(String message) {
-    return message.split("-")[0];
+    String[] tokens = message.split("-")[0].split(" >= ");
+    String token = tokens[0];
+
+    token = token.substring(0, token.lastIndexOf('('));
+    String result = (token + "(>= " + tokens[1]).trim();
+
+    assertTrue(Pattern.matches("[A-Z]+ operation timed out \\(>= [0-9]+ [A-Z]+\\)", result));
+    return result;
   }
 }
diff --git a/src/test/java/net/spy/memcached/internal/CheckedOperationTimeoutExceptionTest.java b/src/test/java/net/spy/memcached/internal/CheckedOperationTimeoutExceptionTest.java
@@ -34,30 +34,31 @@ public class CheckedOperationTimeoutExceptionTest extends TestCase {
 
   private final long duration = 1;
   private final TimeUnit unit = TimeUnit.MILLISECONDS;
+  private final long elapsed = 5;
 
   public void testSingleOperation() {
     Operation op = buildOp(11211);
-    Exception e = new CheckedOperationTimeoutException(duration, unit, op);
+    Exception e = new CheckedOperationTimeoutException(duration, unit, elapsed, op);
 
     String expected = CheckedOperationTimeoutException.class.getName() +
-            ": UNDEFINED operation timed out (>1 MILLISECONDS)" +
+            ": UNDEFINED operation timed out (5 >= 1 MILLISECONDS)" +
             " - failing node: localhost:11211 [WRITE_QUEUED] [MOCK_STATE]";
     assertEquals(expected, e.toString());
   }
 
   public void testNullNode() {
     Operation op = new TestOperation();
-    Exception e = new CheckedOperationTimeoutException(duration, unit, op);
+    Exception e = new CheckedOperationTimeoutException(duration, unit, elapsed, op);
 
     String expected = CheckedOperationTimeoutException.class.getName() +
-            ": UNDEFINED operation timed out (>1 MILLISECONDS)" +
+            ": UNDEFINED operation timed out (5 >= 1 MILLISECONDS)" +
             " - failing node: <unknown> [WRITE_QUEUED]";
     assertEquals(expected, e.toString());
   }
 
   public void testNullOperation() {
     try {
-      Exception e = new CheckedOperationTimeoutException(duration, unit, (Operation) null);
+      Exception e = new CheckedOperationTimeoutException(duration, unit, elapsed, (Operation) null);
       fail("NullPointerException is NOT thrown... " + e.getMessage());
     } catch (Exception e) {
       e.printStackTrace();
@@ -69,10 +70,10 @@ public void testMultipleOperation() {
     Collection<Operation> ops = new ArrayList<>();
     ops.add(buildOp(11211));
     ops.add(buildOp(64212));
-    Exception e = new CheckedOperationTimeoutException(duration, unit, ops);
+    Exception e = new CheckedOperationTimeoutException(duration, unit, elapsed, ops);
 
     String expected = CheckedOperationTimeoutException.class.getName() +
-            ": UNDEFINED operation timed out (>1 MILLISECONDS)" +
+            ": UNDEFINED operation timed out (5 >= 1 MILLISECONDS)" +
             " - failing nodes: localhost:11211 [WRITE_QUEUED] [MOCK_STATE]," +
             " localhost:64212 [WRITE_QUEUED] [MOCK_STATE]";
     assertEquals(expected, e.toString());