Java - ExecutorService with apparently idle thread

Question

I am observing a behaviour I cannot explain with the ExecutorService. I have an application loading around 800 people profile in memory. Consider the below

ExecutorService es = Executors.newFixedThreadPool(8); // 8 cores machine
Runnable enricherService = new Runnable() {

    @Override
    public void run() {
            doEnrichment(conn, tmpCachePerson);
    }
};

// tmpCachePerson is a ConcurrentLinkedQueue<Person>
while (tmpCachePerson.isEmpty() == false) {
    es.execute(enricherService);
}

es.shutdown();

try {
    while (!es.awaitTermination(24L, TimeUnit.HOURS)) {
        System.out.println("Waiting for termination");
    }
} catch (InterruptedException e) {
    // TODO Auto-generated catch block
    e.printStackTrace();
}

This piece is very slow, compared to a pool of 1 thread. I placed some println in the code, and I can see that every so often ( ~ 4s), all the threads stop, sitting there for up to 16s, then start again, almost like a batch, but with a sleep between iterations. It takes 50s to complete. I then tried the implementation below:

Runnable enricher2Thread = new Runnable() {

            @Override
            public void run() {
                while (tmpCachePerson.isEmpty() == false) {
                    doEnrichment(conn, tmpCachePerson);
                }
            }
        };

        Thread t = new Thread(enricher2Thread);
        t.start();
        try {
            t.join();
        } catch (InterruptedException e) {
            // TODO Auto-generated catch block
            e.printStackTrace();
        }

This piece on the other hand, is very fast, uses only one thread, never stops printing in the console, and completes in 3s.

If I replace the the fixed pool in the first piece with a cached pool, the task completes in 3s, after spawning 800 threads. Same speed if I place 800 threads in the fixed pool. Anyone understand why the fixed pool pauses every so often, and therefore why it is not faster than 1 thread. Below is an extract of what I see with 8 threads. If you look at thread-1, it pauses on a simple getter for 5s . In other parts of the log, the entire task taks ~250ms.

2016-11-15 15:54:04.212 - pool-1-thread-1 - Starting
2016-11-15 15:54:04.212 - pool-1-thread-1 - Starting executing SQL
2016-11-15 15:54:04.212 - pool-1-thread-1 - Done executing SQL in 0 ms
2016-11-15 15:54:04.212 - pool-1-thread-1 - Starting adding
2016-11-15 15:54:04.212 - pool-1-thread-1 - Starting Getting Val
2016-11-15 15:54:04.212 - pool-1-thread-1 - Done Getting Val in 0 ms
2016-11-15 15:54:04.212 - pool-1-thread-1 - Starting Getting Root
2016-11-15 15:54:04.212 - pool-1-thread-1 - Done Getting Root in 0 ms
2016-11-15 15:54:04.212 - pool-1-thread-1 - Starting Getting Path
2016-11-15 15:54:04.212 - pool-1-thread-1 - Done Getting Path in 0 ms
2016-11-15 15:54:04.212 - pool-1-thread-6 - Starting
2016-11-15 15:54:04.212 - pool-1-thread-8 - Starting  <-------------- All threads stop
2016-11-15 15:54:09.533 - pool-1-thread-8 - Starting executing SQL
2016-11-15 15:54:09.533 - pool-1-thread-6 - Starting executing SQL
2016-11-15 15:54:09.533 - pool-1-thread-8 - Done executing SQL in 0 ms
2016-11-15 15:54:09.533 - pool-1-thread-1 - Starting Getting Full Path
2016-11-15 15:54:09.533 - pool-1-thread-6 - Done executing SQL in 5320 ms
2016-11-15 15:54:09.533 - pool-1-thread-8 - Starting adding
2016-11-15 15:54:09.533 - pool-1-thread-6 - Starting adding
2016-11-15 15:54:09.533 - pool-1-thread-8 - Starting Getting Val
2016-11-15 15:54:09.533 - pool-1-thread-6 - Starting Getting Val
2016-11-15 15:54:09.533 - pool-1-thread-8 - Done Getting Val in 0 ms
2016-11-15 15:54:09.533 - pool-1-thread-8 - Starting Getting Root
2016-11-15 15:54:09.533 - pool-1-thread-1 - Done Getting Full Path in 5320 ms
2016-11-15 15:54:09.533 - pool-1-thread-1 - Starting Adding Image
2016-11-15 15:54:09.533 - pool-1-thread-8 - Done Getting Root in 0 ms
2016-11-15 15:54:09.533 - pool-1-thread-1 - Done Adding Image in 0 ms
2016-11-15 15:54:09.533 - pool-1-thread-8 - Starting Getting Path
2016-11-15 15:54:09.533 - pool-1-thread-1 - Done adding in 5321 ms
2016-11-15 15:54:09.533 - pool-1-thread-1 - Starting setting
2016-11-15 15:54:09.533 - pool-1-thread-1 - Done setting in 0 ms
2016-11-15 15:54:09.533 - pool-1-thread-1 - Done in 5321 ms

Any idea how I can improve this code and why it pauses ? I can post the code of doEnrichment() if it helps

Edit: Here it is:

private void doEnrichment(Connection conn, ConcurrentLinkedQueue<Person> tmpCachePerson) {
        Person person = tmpCachePerson.poll();

        if (person != null) {
            ImageCollection personImageCollection;
            String query = "SELECT epi.value, i.path FROM Image i "
                    + "INNER JOIN EntityImageRelationship eir ON eir.id_image = i.id "
                    + "INNER JOIN EntityType et ON eir.id_entity_type = et.id "
                    + "INNER JOIN EntityPrimaryImage epi ON epi.type_to_entity_uid = eir.type_to_entity_uid "
                    + "WHERE et.id = ? AND eir.id_entity_id = ? ORDER BY i.id ASC";

            String tagQuery = "SELECT id, value FROM Tag t INNER JOIN EntityTagRelationship etr ON etr.id_tag = t.id WHERE etr.id_entity = ? AND etr.id_entity_type = ?";

            try (PreparedStatement stmnt = conn.prepareStatement(query);
                    PreparedStatement tagStmnt = conn.prepareStatement(tagQuery)) {
                personImageCollection = getEntityImages(conn, stmnt, person.getId(), person.getMovieEntityType());
                person.setImageCollection(personImageCollection);
                person.getImageCollection().setPrimaryImageIcon();

                Set<String> tags = getEntityTags(conn, tagStmnt, person.getId(), person.getMovieEntityType()).keySet();
                person.setTags(tags);

                personCache.add(person);
            } catch (Exception e) {
                // TODO Auto-generated catch block
                e.printStackTrace();
            }
        }
    }

Answer 1

This might not be the cause, but you have a race condition here:

while (tmpCachePerson.isEmpty() == false) {
    es.execute(enricherService);
}

The is absolutely no guarantee that context switching happens; even if it does, it's probably slower than you expect; that loop might run a million times before a worker starts up. Don't look any further until you fix this issue; that's a lot of spinning and memory overhead.

A better pattern is to put the polling in the worker:

Runnable enricherService = new Runnable() {
    @Override
    public void run() {
        while (!tmpCachePerson.isEmpty()) {
            doEnrichment(conn, tmpCachePerson);
            // TODO: error handling? Should a failure in doEnrichment kill the worker?
        }
    }
};

And then start the workers with

for (int i = 0; i < 8; ++i) {
    es.execute(enricherService);
}