title: How to find stack of 'blocking' CompletableFuture
body: <p><strong>UPDATE 15.10.2020:</strong> I have at least found one thread leak, which i documented here: <a href="https://github.com/graphql-java/graphql-java/issues/2068" rel="nofollow noreferrer">https://github.com/graphql-java/graphql-java/issues/2068</a>. I cannot confirm if this was/is actually the case for the issue below tho.</p>
  <p>We have a Java 8 Server which uses Spring Boot and GraphQL. For GraphQL we use <a href="https://github.com/graphql-java-kickstart/graphql-spring-boot" rel="nofollow noreferrer">graphql-spring-boot-starter</a>, which includes <a href="https://github.com/graphql-java/java-dataloader" rel="nofollow noreferrer">java-dataloader</a>.</p>
  <p>This weekend we had a very strange bug with <code>CompletableFutures</code>, which are used by java-dataloaders to resolve the different fields of a GraphQL request in an async manner. Somehow one (or multiple) <code>CompletableFuture(s)</code> never completed and thus the Thread waiting to join all those, never finished either and leaked.</p>
  <p>Furthermore, dataloaders also optionally can put every return value (<code>CompletableFuture</code>) into a cache so that every request asking for the same resource can use the cached result. Our cache is configured to hold this value for 10 minutes. Every following GraphQL request in the next 10 minutes requesting the same, already cached, value would never complete either (since the <code>CompletableFuture</code> in the cache never completed) and leak a thread. Luckily in the end we only had 47 leaked threads (from 47 different requests using the same resource).</p>
  <p>We have never seen this issue before and were also unable to reproduce it yet. We were able to produce a thread- and heap-dump and now i would like to identifiy exactly what went wrong. For that i tried to use VisualVM, but sadly i was not able to identify the blocking <code>CompletableFuture</code>. Has anyone any expierence in tracking down this kind of bugs?
  Here is an excerpt from a stack from one of the leaked threads:</p>
  <pre><code>&quot;https-jsse-nio-8041-exec-1&quot; #99 daemon prio=5 os_prio=0 cpu=76290.00 [reset 76290.00] ms elapsed=77044.87 [reset 77044.87] s allocated=9766202448 B (9.10 GB) [reset 9766202448 B (9.10 GB)] defined_classes=647
  io= file i/o: 7077964/13591454 B, net i/o: 38446078/25897999 B, files opened:4850, socks opened:-72  [reset file i/o: 7077964/13591454 B, net i/o: 38446078/25897999 B, files opened:4850, socks opened:-72 ] 
  tid=0x00007f5248771000 nid=0x2c16 / 11286  pthread-id=139987580286720 waiting on condition   [_thread_blocked (_at_safepoint), stack(0x00007f5165eef000,0x00007f5165ff0000)] [0x00007f5165feb000]
     java.lang.Thread.State: WAITING (parking)
      at jdk.internal.misc.Unsafe.park(ZJ)V(Native Method)
      - parking to wait for  &lt;0x0000000558be0128&gt; (a java.util.concurrent.CompletableFuture$Signaller)
      at sun.misc.Unsafe.park(ZJ)V(Unsafe.java:1079)
      at java.util.concurrent.locks.LockSupport.park(Ljava/lang/Object;)V(LockSupport.java:175)
      at java.util.concurrent.CompletableFuture$Signaller.block()Z(CompletableFuture.java:1707)
      at java.util.concurrent.ForkJoinPool.managedBlock(Ljava/util/concurrent/ForkJoinPool$ManagedBlocker;)V(ForkJoinPool.java:3323)
      at java.util.concurrent.CompletableFuture.waitingGet(Z)Ljava/lang/Object;(CompletableFuture.java:1742)
      at java.util.concurrent.CompletableFuture.join()Ljava/lang/Object;(CompletableFuture.java:1947)
      at graphql.kickstart.execution.GraphQLInvoker.query(Lgraphql/kickstart/execution/input/GraphQLSingleInvocationInput;)Lgraphql/ExecutionResult;(GraphQLInvoker.java:38)
      at graphql.kickstart.execution.GraphQLInvoker.query(Lgraphql/kickstart/execution/input/GraphQLInvocationInput;)Lgraphql/kickstart/execution/GraphQLQueryResult;(GraphQLInvoker.java:31)
      at graphql.kickstart.servlet.HttpRequestHandlerImpl.invoke(Lgraphql/kickstart/execution/input/GraphQLInvocationInput;Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)Lgraphql/kickstart/execution/GraphQLQueryResult;(HttpRequestHandlerImpl.java:67)
      at graphql.kickstart.servlet.HttpRequestHandlerImpl.execute(Lgraphql/kickstart/execution/input/GraphQLInvocationInput;Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V(HttpRequestHandlerImpl.java:52)
      at graphql.kickstart.servlet.HttpRequestHandlerImpl.handle(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V(HttpRequestHandlerImpl.java:37)
      at graphql.kickstart.servlet.AbstractGraphQLHttpServlet.doRequest(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Lgraphql/kickstart/servlet/HttpRequestHandler;Ljavax/servlet/AsyncContext;)V(AbstractGraphQLHttpServlet.java:147)
      at graphql.kickstart.servlet.AbstractGraphQLHttpServlet.doRequestAsync(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;Lgraphql/kickstart/servlet/HttpRequestHandler;)V(AbstractGraphQLHttpServlet.java:137)
      at graphql.kickstart.servlet.AbstractGraphQLHttpServlet.doPost(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V(AbstractGraphQLHttpServlet.java:169)
      at javax.servlet.http.HttpServlet.service(Ljavax/servlet/http/HttpServletRequest;Ljavax/servlet/http/HttpServletResponse;)V(HttpServlet
  </code></pre>
  <p>Here is also an image of a specific <code>ThreadPoolExecutor</code>, which i found digging through the heap dump with VisualVM:
  <a href="https://i.stack.imgur.com/bDJTs.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/bDJTs.png" alt="enter image description here" /></a></p>
  <p>As you can see this specific executor has a <code>submittedCount</code> of 47, but a count of completed tasks of 0. Sadly i am not sure where to go from there.</p>
  <p>In my research i also came across this <a href="https://bugs.openjdk.java.net/browse/JDK-8201576" rel="nofollow noreferrer">bug</a> in the Open JDK tracker and was able to reproduce it on my local machine (using JDK 8) with the provided reproduction. But i am not sure if our bug can be caused by this.</p>
  <p>Although i don't believe that our implementation has any issues here is the code for our implementation of a BatchLoader:</p>
  <pre><code>public abstract class ContextAwareBatchLoader&lt;K, V&gt; implements BatchLoader&lt;K, V&gt; {
      protected final JPAQueryFactory queryFactory;
      private final CrossRequestCacheMap&lt;K, V&gt; cacheMap;
  
      public ContextAwareBatchLoader(JPAQueryFactory queryFactory, Cache cache) {
          this.queryFactory = queryFactory;
          this.cacheMap = new CrossRequestCacheMap&lt;&gt;(cache, getCachePrefix());
      }
  
      protected abstract List&lt;V&gt; loaderFunction(List&lt;K&gt; list);
  
      protected abstract String getCachePrefix();
  
      public DataLoaderOptions getOptions() {
          return DataLoaderOptions.newOptions().setCacheMap(this.cacheMap);
      }
  
      @Override
      public CompletionStage&lt;List&lt;V&gt;&gt; load(List&lt;K&gt; list) {
          SecurityContext context = SecurityContextHolder.getContext();
          Locale locale = LocaleContextHolder.getLocale();
          return CompletableFuture.supplyAsync(() -&gt; {
              LocaleContextHolder.setLocale(locale);
              if (context != null) SecurityContextHolder.setContext(context);
              return this.loaderFunction(list);
          });
      }
  }
  </code></pre>
  <p>Which can be extended to build a dataloader like this:</p>
  <pre><code>@Component
  public class DressageExerciseLinesBatchLoader extends ContextAwareBatchLoader&lt;Long, List&lt;DressageExerciseLine&gt;&gt; {
      @Autowired
      public DressageExerciseLinesBatchLoader(JPAQueryFactory queryFactory, CacheManager cacheManager) {
          super(queryFactory, cacheManager.getCache(&quot;graphqlCache&quot;));
      }
  
      @Override
      protected List&lt;List&lt;DressageExerciseLine&gt;&gt; loaderFunction(List&lt;Long&gt; list) {
          List&lt;List&lt;DressageExerciseLine&gt;&gt; returnList = new ArrayList&lt;&gt;();
          List&lt;DressageExerciseLine&gt; exerciseLines = queryFactory.selectFrom(QDressageExerciseLine.dressageExerciseLine)
                  .where(QDressageExerciseLine.dressageExerciseLine.exercise.id.in(list)).fetch();
          list.forEach(exerciseId -&gt;
                  returnList.add(exerciseLines.stream().filter(exerciseLine -&gt;
                          exerciseLine.getExercise().getId().equals(exerciseId)).collect(Collectors.toList()))
          );
          return returnList;
      }
  
      @Override
      protected String getCachePrefix() {
          return &quot;dressageExerciseLines&quot;;
      }
  }
  </code></pre>