Continuations - partially blocked pool threads

Play Framework
1

Consider a Play app consisting of a controller that makes use of continuations in order to allow simultaneous requests to be run by pool threads.

Create a test app

play new test

and change the application controller to

package controllers;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import play.Logger;
import play.mvc.Controller;

public class Application extends Controller {

    private static ExecutorService pool = Executors.newFixedThreadPool(10);

    public static void index() {
        Future future = pool.submit(() -> {
            try {
                Logger.info("before sleep");
                Thread.sleep(20000);
                Logger.info("after sleep");
            } catch (InterruptedException e) {
                Logger.error(e.getMessage());
            }
        });
        Logger.info("before await");
        await(future);
        Logger.info("after await");
        render();
    }


}

Then add conf/log4j.properties,

log4j.rootLogger=DEBUG, Console
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=%d{ABSOLUTE} %-5p ~ [%t] %m%n

start play

play run

and simultaneously open 3 browser tabs at http://localhost:9000/

The results are:

  • The first tab loads after (around) 20 seconds
  • The second and third tabs load after (around) 40 seconds

Logs show that:

  • Pool thread pool-5-thread-1 handles the first tab request
  • Only when pool-5-thread-1 completes, pool threads pool-5-thread-2 and pool-5-thread-3 start handling the second and third tab requests
  • pool-5-thread-2 and pool-5-thread-3 complete at (around) the same time

Since the 3 tabs were opened at (around) the same time, shouldn’t they all be loaded after (around) 20 seconds i.e. shouldn’t 3 pool threads start handling them at (around) the same time?

This behaviour is consistently reproducible.

Play! version: 1.5.2
Java version: 1.8.0_201

Logs:

12:36:48,544 INFO  ~ [play-thread-1] Application 'test' is now started !
12:36:48,723 INFO  ~ [play-thread-1] before await
12:36:48,726 DEBUG ~ [play-thread-1] suspend()
12:36:48,727 INFO  ~ [pool-5-thread-1] before sleep
12:36:48,731 DEBUG ~ [play-thread-1] push object java.util.concurrent.FutureTask@806931916/unknown [java.util.concurrent.FutureTask@3018cdcc] i[0],l[0],d[0],f[0],o[0],r[0]
12:36:48,731 DEBUG ~ [play-thread-1] push int 2 i[0],l[0],d[0],f[0],o[1],r[0]
12:36:48,741 WARN  ~ [play-thread-1] Start WaitForTasksCompletion
12:37:08,734 INFO  ~ [pool-5-thread-1] after sleep
12:37:08,795 DEBUG ~ [play-thread-1] pop int 2 i[0],l[0],d[0],f[0],o[1],r[0]
12:37:08,795 DEBUG ~ [play-thread-1] pop object java.util.concurrent.FutureTask@806931916/unknown [java.util.concurrent.FutureTask@3018cdcc] 
12:37:08,802 INFO  ~ [play-thread-1] after await
12:37:12,816 INFO  ~ [play-thread-1] before await
12:37:12,818 DEBUG ~ [play-thread-1] suspend()
12:37:12,818 DEBUG ~ [play-thread-1] push object java.util.concurrent.FutureTask@634795018/unknown [java.util.concurrent.FutureTask@25d6340a] i[0],l[0],d[0],f[0],o[0],r[0]
12:37:12,818 DEBUG ~ [play-thread-1] push int 2 i[0],l[0],d[0],f[0],o[1],r[0]
12:37:12,829 INFO  ~ [pool-5-thread-2] before sleep
12:37:12,875 INFO  ~ [play-thread-1] before await
12:37:12,875 INFO  ~ [pool-5-thread-3] before sleep
12:37:12,891 DEBUG ~ [play-thread-1] suspend()
12:37:12,891 DEBUG ~ [play-thread-1] push object java.util.concurrent.FutureTask@880603374/unknown [java.util.concurrent.FutureTask@347cf0ee] i[0],l[0],d[0],f[0],o[0],r[0]
12:37:12,891 DEBUG ~ [play-thread-1] push int 2 i[0],l[0],d[0],f[0],o[1],r[0]
12:37:32,829 INFO  ~ [pool-5-thread-2] after sleep
12:37:32,868 DEBUG ~ [play-thread-1] pop int 2 i[0],l[0],d[0],f[0],o[1],r[0]
12:37:32,868 DEBUG ~ [play-thread-1] pop object java.util.concurrent.FutureTask@634795018/unknown [java.util.concurrent.FutureTask@25d6340a] 
12:37:32,868 INFO  ~ [play-thread-1] after await
12:37:32,875 INFO  ~ [pool-5-thread-3] after sleep
12:37:32,939 DEBUG ~ [play-thread-1] pop int 2 i[0],l[0],d[0],f[0],o[1],r[0]
12:37:32,939 DEBUG ~ [play-thread-1] pop object java.util.concurrent.FutureTask@880603374/unknown [java.util.concurrent.FutureTask@347cf0ee] 
12:37:32,939 INFO  ~ [play-thread-1] after await
2

While the operations sent to the pool might actually be executed concurrently (in pool-5-thread-<n>), you’re still blocking the endpoint controller index method when you await for the future to be completed (on play-thread-1).

essentially you’re putting the next request on-hold until the first async computation is done, instead you should return the future itself as an async response to the controller method.

3

@Ivano Could you please elaborate on “return the future itself as an async response to the controller method”? An example would help (the documentation provides await-like examples only).

4

You’re reading documentation for version 1.5, which is years old.

Refer to current documentation

5

Thanks, but that’s for Play 2, this is a Play 1 topic. :slight_smile:

Any Play 1 users out there? :desert: