Continuations - partially blocked pool threads

References

Discuss Play Forum: https://discuss.lightbend.com/t/continuations-partially-blocked-pool-threads/3752
Lighthouse (copy of this ticket): https://play.lighthouseapp.com/projects/57987/tickets/2390-continuations-partially-blocked-pool-threads

Description

Play! version: 1.5.2
Java version: 1.8.0_201
Ubuntu 18.04.2 LTS

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
• play-thread-1 blocks

Expected Behavior

Since the 3 tabs were opened at (around) the same time, they should all be loaded after (around) 20 seconds i.e. the 3 pool threads should start/complete handling them at (around) the same time. Furthermore, play-thread-1 should not be blocked.

Actual Behavior

All pool threads should start/complete handling simultaneous requests at (around) the same time and play-thread-1 should not block i.e. it should handle other requests while waiting for pool threads to complete.

Reproducible Test Case

The actual behaviour is consistently reproducible by following the above-mentioned steps.

Start with the Application.index example, especially await(future), and reproduce the behavior with play new test, play run, and three simultaneous requests. Trace the continuation and pool-thread handling shown in the logs; done means the requests complete together after about 20 seconds and play-thread-1 remains available for other requests.