tracing for Future.get

Change-Id: I5c0bf627c86eef180889fa769e7952de2a27afdd

java/com.sap.sse/src/com/sap/sse/util/SmartFutureCache.java

@@ -13,6 +13,7 @@ import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Executor;
 import java.util.concurrent.Future;
 import java.util.concurrent.FutureTask;
+import java.util.concurrent.ThreadPoolExecutor;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.TimeoutException;
 import java.util.concurrent.locks.ReentrantReadWriteLock;
@@ -23,6 +24,9 @@ import com.sap.sse.common.Util.Pair;
 import com.sap.sse.concurrent.LockUtil;
 import com.sap.sse.concurrent.NamedReentrantReadWriteLock;
 import com.sap.sse.util.SmartFutureCache.UpdateInterval;
+import com.sap.sse.util.impl.KnowsExecutor;
+import com.sap.sse.util.impl.KnowsExecutorAndTracingGet;
+import com.sap.sse.util.impl.KnowsExecutorAndTracingGetImpl;
 
 /**
  * A cache for which a background update can be triggered. Readers can decide whether they want to wait for any ongoing
@@ -201,7 +205,9 @@ public class SmartFutureCache<K, V, U extends UpdateInterval<U>> {
      * @author Axel Uhl (D043530)
      * 
      */
-    private class FutureTaskWithCancelBlocking extends FutureTask<V> implements Callable<V> {
+    private class FutureTaskWithCancelBlocking extends FutureTask<V> implements KnowsExecutor, Callable<V> {
+        private final KnowsExecutorAndTracingGet<V> tracingGetHelper;
+        
         private boolean runningAndReadUpdateInterval;
         
         private final K key;
@@ -228,6 +234,7 @@ public class SmartFutureCache<K, V, U extends UpdateInterval<U>> {
         public FutureTaskWithCancelBlocking(SettableCallable<V> callable, final K key, final U updateInterval,
                 final boolean callerWaitsSynchronouslyForResult, final Thread callerThread) {
             super(callable);
+            tracingGetHelper = new KnowsExecutorAndTracingGetImpl<>();
             callable.setCallable(this);
             this.gettingThreads = new HashSet<>();
             this.key = key;
@@ -274,7 +281,7 @@ public class SmartFutureCache<K, V, U extends UpdateInterval<U>> {
                     }
                 }
             }
-            return super.get();
+            return tracingGetHelper.callGetAndTraceAfterEachTimeout(this);
         }
 
         @Override
@@ -363,6 +370,11 @@ public class SmartFutureCache<K, V, U extends UpdateInterval<U>> {
         public U getUpdateInterval() {
             return updateInterval;
         }
+
+        @Override
+        public void setExecutorThisTaskIsScheduledFor(ThreadPoolExecutor executorThisTaskIsScheduledFor) {
+            tracingGetHelper.setExecutorThisTaskIsScheduledFor(executorThisTaskIsScheduledFor);
+        }
     }
     
     public SmartFutureCache(CacheUpdater<K, V, U> cacheUpdateComputer, String nameForLocks) {

java/com.sap.sse/src/com/sap/sse/util/ThreadPoolUtil.java

@@ -51,8 +51,9 @@ public interface ThreadPoolUtil {
      * <p>
      * 
      * The same configuration as for {@link #getDefaultBackgroundTaskThreadPoolExecutor()} is used.
+     * @param name TODO
      */
-    ScheduledExecutorService createBackgroundTaskThreadPoolExecutor();
+    ScheduledExecutorService createBackgroundTaskThreadPoolExecutor(String name);
     
     /**
      * In case an application module really requires its own thread pool instead of
@@ -73,6 +74,7 @@ public interface ThreadPoolUtil {
      * <p>
      * 
      * The same configuration as for {@link #getDefaultForegroundTaskThreadPoolExecutor()} is used.
+     * @param name TODO
      */
-    ScheduledExecutorService createForegroundTaskThreadPoolExecutor();
+    ScheduledExecutorService createForegroundTaskThreadPoolExecutor(String name);
 }

java/com.sap.sse/src/com/sap/sse/util/impl/FutureTaskWithTracingGet.java

@@ -0,0 +1,37 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.Callable;
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.FutureTask;
+
+public class FutureTaskWithTracingGet<V> extends FutureTask<V> {
+    private final HasTracingGet<V> hasTracingGet;
+    private final String traceInfo;
+    
+    public FutureTaskWithTracingGet(String traceInfo, Callable<V> callable) {
+        super(callable);
+        this.traceInfo = traceInfo;
+        hasTracingGet = createHasTracingGet();
+    }
+
+    public FutureTaskWithTracingGet(String traceInfo, Runnable runnable, V result) {
+        super(runnable, result);
+        this.traceInfo = traceInfo;
+        hasTracingGet = createHasTracingGet();
+    }
+
+    @Override
+    public V get() throws InterruptedException, ExecutionException {
+        return hasTracingGet.callGetAndTraceAfterEachTimeout(this);
+    }
+
+    private HasTracingGet<V> createHasTracingGet() {
+        return new HasTracingGetImpl<V>() {
+            @Override
+            protected String getAdditionalTraceInfo() {
+                return traceInfo;
+            }
+        };
+    }
+
+}

java/com.sap.sse/src/com/sap/sse/util/impl/HasTracingGet.java

@@ -0,0 +1,16 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.Future;
+import java.util.concurrent.TimeoutException;
+
+public interface HasTracingGet<V> {
+    /**
+     * Keeps calling {@link Future#get(long, java.util.concurrent.TimeUnit)} with a timeout until a result is available
+     * or an exception other than a {@link TimeoutException} is thrown. When a timeout occurs, some trace output is
+     * written to the log. The method is guaranteed not to call {@link Future#get()} and therefore can be used in an
+     * implementation of a {@link Future#get()} method without causing an endless recursion as long as
+     * {@link Future#get(long, java.util.concurrent.TimeUnit)} is not calling this method.
+     */
+    V callGetAndTraceAfterEachTimeout(Future<V> future) throws InterruptedException, ExecutionException;
+}

java/com.sap.sse/src/com/sap/sse/util/impl/HasTracingGetImpl.java

@@ -0,0 +1,37 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+import com.sap.sse.common.Duration;
+
+/**
+ * Can be used with a {@link Future} task and outputs trace messages to the log after {@link #MILLIS_AFTER_WHICH_TO_TRACE_NON_RETURNING_GET} milliseconds
+ * of a {@link #get()} call not returning. The {@link #getAdditionalTraceInfo()} method must be implemented by subclasses to provide some meaningful
+ * hint as to which object is currently timing out.
+ * 
+ * @author Axel Uhl (d043530)
+ *
+ * @param <V>
+ */
+public abstract class HasTracingGetImpl<V> implements HasTracingGet<V> {
+    private static final Logger logger = Logger.getLogger(HasTracingGetImpl.class.getName());
+    private final long MILLIS_AFTER_WHICH_TO_TRACE_NON_RETURNING_GET = Duration.ONE_SECOND.times(5).asMillis();
+    
+    public V callGetAndTraceAfterEachTimeout(Future<V> future) throws InterruptedException, ExecutionException {
+        while (true) {
+            try {
+                return future.get(MILLIS_AFTER_WHICH_TO_TRACE_NON_RETURNING_GET, TimeUnit.MILLISECONDS);
+            } catch (TimeoutException e) {
+                logger.log(Level.INFO, "Timeout waiting for future task "+this+
+                        "; "+ getAdditionalTraceInfo(), e);
+            }
+        }
+    }
+
+    protected abstract String getAdditionalTraceInfo();
+}

java/com.sap.sse/src/com/sap/sse/util/impl/KnowsExecutor.java

@@ -0,0 +1,14 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.ThreadPoolExecutor;
+
+/**
+ * A {@link ThreadPoolExecutor} can be set on this object. This is used, in particular, by the
+ * {@link NamedTracingScheduledThreadPoolExecutor} whenever a task of this type is enqueued.
+ * 
+ * @author Axel Uhl (d043530)
+ *
+ */
+public interface KnowsExecutor {
+    void setExecutorThisTaskIsScheduledFor(ThreadPoolExecutor executorThisTaskIsScheduledFor);
+}

java/com.sap.sse/src/com/sap/sse/util/impl/KnowsExecutorAndTracingGet.java

@@ -0,0 +1,17 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.Future;
+
+import com.sap.sse.util.ThreadPoolUtil;
+
+/**
+ * Can be used with a {@link Future} task and outputs trace messages to the log after {@link #MILLIS_AFTER_WHICH_TO_TRACE_NON_RETURNING_GET} milliseconds
+ * of a {@link #get()} call not returning. When used in conjunction with a {@link NamedTracingScheduledThreadPoolExecutor} such as
+ * the ones returned by {@link ThreadPoolUtil}, the task will be 
+ * 
+ * @author Axel Uhl (d043530)
+ *
+ * @param <V>
+ */
+public interface KnowsExecutorAndTracingGet<V> extends KnowsExecutor, HasTracingGet<V> {
+}

java/com.sap.sse/src/com/sap/sse/util/impl/KnowsExecutorAndTracingGetImpl.java

@@ -0,0 +1,32 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.Future;
+import java.util.concurrent.ThreadPoolExecutor;
+
+import com.sap.sse.util.ThreadPoolUtil;
+
+/**
+ * Can be used with a {@link Future} task and outputs trace messages to the log after
+ * {@link #MILLIS_AFTER_WHICH_TO_TRACE_NON_RETURNING_GET} milliseconds of a {@link #get()} call not returning. When used
+ * in conjunction with a {@link NamedTracingScheduledThreadPoolExecutor} such as the ones returned by
+ * {@link ThreadPoolUtil}, the task will be
+ * 
+ * @author Axel Uhl (d043530)
+ *
+ * @param <V>
+ */
+public class KnowsExecutorAndTracingGetImpl<V> extends HasTracingGetImpl<V> implements KnowsExecutorAndTracingGet<V> {
+    private ThreadPoolExecutor executorThisTaskIsScheduledFor;
+
+    @Override
+    public void setExecutorThisTaskIsScheduledFor(ThreadPoolExecutor executorThisTaskIsScheduledFor) {
+        this.executorThisTaskIsScheduledFor = executorThisTaskIsScheduledFor;
+    }
+
+    @Override
+    protected String getAdditionalTraceInfo() {
+        return (executorThisTaskIsScheduledFor == null ? "not scheduled"
+                : ("scheduled with executor " + executorThisTaskIsScheduledFor + " with queue size "
+                        + executorThisTaskIsScheduledFor.getQueue().size()));
+    }
+}

java/com.sap.sse/src/com/sap/sse/util/impl/NamedTracingScheduledThreadPoolExecutor.java

@@ -0,0 +1,75 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.Callable;
+import java.util.concurrent.RejectedExecutionHandler;
+import java.util.concurrent.RunnableFuture;
+import java.util.concurrent.RunnableScheduledFuture;
+import java.util.concurrent.ScheduledThreadPoolExecutor;
+import java.util.concurrent.ThreadFactory;
+
+/**
+ * A scheduled thread pool executor with a name that produces {@link Future} tasks that write a trace message
+ * to the log after their {@link Future#get()} method hasn't produced a result for some time, then keep trying.
+ * The tasks are linked to this executor, also when a {@link KnowsExecutor} task is submitted to the {@link #execute(Runnable)}
+ * method, so that when they need to trace they
+ * 
+ * @author Axel Uhl (d043530)
+ *
+ */
+public class NamedTracingScheduledThreadPoolExecutor extends ScheduledThreadPoolExecutor {
+    private final String name;
+    
+    public NamedTracingScheduledThreadPoolExecutor(String name, int corePoolSize, RejectedExecutionHandler handler) {
+        super(corePoolSize, handler);
+        this.name = name;
+    }
+
+    public NamedTracingScheduledThreadPoolExecutor(String name, int corePoolSize, ThreadFactory threadFactory,
+            RejectedExecutionHandler handler) {
+        super(corePoolSize, threadFactory, handler);
+        this.name = name;
+    }
+
+    public NamedTracingScheduledThreadPoolExecutor(String name, int corePoolSize, ThreadFactory threadFactory) {
+        super(corePoolSize, threadFactory);
+        this.name = name;
+    }
+
+    public NamedTracingScheduledThreadPoolExecutor(String name, int corePoolSize) {
+        super(corePoolSize);
+        this.name = name;
+    }
+    
+    @Override
+    protected <V> RunnableScheduledFuture<V> decorateTask(Runnable runnable, RunnableScheduledFuture<V> task) {
+        return new ThreadPoolAwareRunnableScheduledFutureDelegate<>(this, task);
+    }
+
+    @Override
+    protected <V> RunnableScheduledFuture<V> decorateTask(Callable<V> callable, RunnableScheduledFuture<V> task) {
+        return new ThreadPoolAwareRunnableScheduledFutureDelegate<>(this, task);
+    }
+
+    @Override
+    protected <T> RunnableFuture<T> newTaskFor(Runnable runnable, T value) {
+        return new ThreadPoolAwareFutureTask<T>(this, runnable, value);
+    }
+
+    @Override
+    protected <T> RunnableFuture<T> newTaskFor(Callable<T> callable) {
+        return new ThreadPoolAwareFutureTask<T>(this, callable);
+    }
+
+    @Override
+    public void execute(Runnable command) {
+        if (command instanceof KnowsExecutor) {
+            ((KnowsExecutor) command).setExecutorThisTaskIsScheduledFor(this);
+        }
+        super.execute(command);
+    }
+
+    @Override
+    public String toString() {
+        return "NamedTracingScheduledThreadPoolExecutor [name=" + name + "]";
+    }
+}

java/com.sap.sse/src/com/sap/sse/util/impl/ThreadPoolAwareFutureTask.java

@@ -0,0 +1,43 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.Callable;
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.FutureTask;
+import java.util.concurrent.ThreadPoolExecutor;
+
+import com.sap.sse.util.ThreadPoolUtil;
+
+/**
+ * A future task that outputs trace messages to the log after {@link #MILLIS_AFTER_WHICH_TO_TRACE_NON_RETURNING_GET} milliseconds
+ * of a {@link #get()} call not returning. When used in conjunction with a {@link NamedTracingScheduledThreadPoolExecutor} such as
+ * the ones returned by {@link ThreadPoolUtil}, the task will be updated by the executor when added to the queue. When the {@link #get()}
+ * method doesn't respond after the timeout period, the executor that scheduled this tasks, its name as well as its queue size
+ * are traced into the log.
+ * 
+ * @author Axel Uhl (d043530)
+ *
+ * @param <V>
+ */
+public class ThreadPoolAwareFutureTask<V> extends FutureTask<V> implements KnowsExecutor {
+    private final KnowsExecutorAndTracingGet<V> getHelper = new KnowsExecutorAndTracingGetImpl<V>();
+    
+    public ThreadPoolAwareFutureTask(ThreadPoolExecutor executor, Callable<V> callable) {
+        super(callable);
+        getHelper.setExecutorThisTaskIsScheduledFor(executor);
+    }
+
+    public ThreadPoolAwareFutureTask(ThreadPoolExecutor executor, Runnable runnable, V result) {
+        super(runnable, result);
+        getHelper.setExecutorThisTaskIsScheduledFor(executor);
+    }
+    
+    @Override
+    public void setExecutorThisTaskIsScheduledFor(ThreadPoolExecutor executorThisTaskIsScheduledFor) {
+        this.getHelper.setExecutorThisTaskIsScheduledFor(executorThisTaskIsScheduledFor);
+    }
+
+    @Override
+    public V get() throws InterruptedException, ExecutionException {
+        return getHelper.callGetAndTraceAfterEachTimeout(this);
+    }
+}

java/com.sap.sse/src/com/sap/sse/util/impl/ThreadPoolAwareRunnableScheduledFutureDelegate.java

@@ -0,0 +1,53 @@
+package com.sap.sse.util.impl;
+
+import java.util.concurrent.Delayed;
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.RunnableScheduledFuture;
+import java.util.concurrent.ThreadPoolExecutor;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
+
+public class ThreadPoolAwareRunnableScheduledFutureDelegate<V> extends KnowsExecutorAndTracingGetImpl<V> implements KnowsExecutorAndTracingGet<V>, RunnableScheduledFuture<V> {
+    private final RunnableScheduledFuture<V> future;
+
+    public ThreadPoolAwareRunnableScheduledFutureDelegate(ThreadPoolExecutor executor, RunnableScheduledFuture<V> future) {
+        this.future = future;
+        setExecutorThisTaskIsScheduledFor(executor);
+    }
+
+    public long getDelay(TimeUnit unit) {
+        return future.getDelay(unit);
+    }
+
+    public void run() {
+        future.run();
+    }
+
+    public boolean isPeriodic() {
+        return future.isPeriodic();
+    }
+
+    public boolean cancel(boolean mayInterruptIfRunning) {
+        return future.cancel(mayInterruptIfRunning);
+    }
+
+    public int compareTo(Delayed o) {
+        return future.compareTo(o);
+    }
+
+    public boolean isCancelled() {
+        return future.isCancelled();
+    }
+
+    public boolean isDone() {
+        return future.isDone();
+    }
+
+    public V get() throws InterruptedException, ExecutionException {
+        return callGetAndTraceAfterEachTimeout(future);
+    }
+
+    public V get(long timeout, TimeUnit unit) throws InterruptedException, ExecutionException, TimeoutException {
+        return future.get(timeout, unit);
+    }
+}

java/com.sap.sse/src/com/sap/sse/util/impl/ThreadPoolUtilImpl.java

@@ -1,21 +1,18 @@
 package com.sap.sse.util.impl;
 
-import java.util.concurrent.Executors;
 import java.util.concurrent.ScheduledExecutorService;
 
 import com.sap.sse.util.ThreadPoolUtil;
 
 public class ThreadPoolUtilImpl implements ThreadPoolUtil {
-    private static final int REASONABLE_THREAD_POOL_SIZE = Math.max(Runtime.getRuntime().availableProcessors()/2, 3);
+    private static final int REASONABLE_THREAD_POOL_SIZE = Math.max(Runtime.getRuntime().availableProcessors()-1, 3);
 
     private final ScheduledExecutorService defaultBackgroundTaskThreadPoolExecutor;
     private final ScheduledExecutorService defaultForegroundTaskThreadPoolExecutor;
     
     public ThreadPoolUtilImpl() {
-        defaultBackgroundTaskThreadPoolExecutor = Executors.newScheduledThreadPool(/* corePoolSize */ REASONABLE_THREAD_POOL_SIZE,
-                new ThreadFactoryWithPriority(Thread.NORM_PRIORITY-1, /* daemon */ true));
-        defaultForegroundTaskThreadPoolExecutor = Executors.newScheduledThreadPool(/* corePoolSize */ Math.max(Runtime.getRuntime().availableProcessors()-1, 6),
-                new ThreadFactoryWithPriority(Thread.NORM_PRIORITY, /* daemon */ true));
+        defaultBackgroundTaskThreadPoolExecutor = createBackgroundTaskThreadPoolExecutor("Default background executor");
+        defaultForegroundTaskThreadPoolExecutor = createForegroundTaskThreadPoolExecutor("Default foreground executor");
     }
     
     @Override
@@ -29,18 +26,21 @@ public class ThreadPoolUtilImpl implements ThreadPoolUtil {
     }
 
     @Override
-    public ScheduledExecutorService createBackgroundTaskThreadPoolExecutor() {
-        return createThreadPoolExecutor(Thread.NORM_PRIORITY-1);
+    public ScheduledExecutorService createBackgroundTaskThreadPoolExecutor(String name) {
+        return createThreadPoolExecutor(name, Thread.NORM_PRIORITY-1);
     }
 
     @Override
-    public ScheduledExecutorService createForegroundTaskThreadPoolExecutor() {
-        return createThreadPoolExecutor(Thread.NORM_PRIORITY);
+    public ScheduledExecutorService createForegroundTaskThreadPoolExecutor(String name) {
+        return createThreadPoolExecutor(name, Thread.NORM_PRIORITY);
     }
 
-    private ScheduledExecutorService createThreadPoolExecutor(final int priority) {
-        return Executors.newScheduledThreadPool(/* corePoolSize */ REASONABLE_THREAD_POOL_SIZE,
-                new ThreadFactoryWithPriority(priority, /* daemon */ true));
+    private ScheduledExecutorService createThreadPoolExecutor(String name, final int priority) {
+        return createThreadPoolExecutor(name, priority, /* corePoolSize */ REASONABLE_THREAD_POOL_SIZE);
+    }
+
+    private ScheduledExecutorService createThreadPoolExecutor(String name, final int priority, final int size) {
+        return new NamedTracingScheduledThreadPoolExecutor(name, /* corePoolSize */ size, new ThreadFactoryWithPriority(priority, /* daemon */ true));
     }
 
     @Override