Java Lambda-Enabled Concurrency - Variables may be Changed Unexpectedly

In my last post, I explained that Don't Use Mutable Variables in Java Lambda Concurrency, but sometimes, variables may be changed unexpectedly.

The Problem

When optimize performance of function that exports solr data as csv, I add the logger.debug statements, then find out the test throws ConcurrentModificationException:

Caused by: java.util.ConcurrentModificationException: null

at java.util.LinkedHashMap$LinkedHashIterator.nextNode(LinkedHashMap.java:711) ~[na:1.8.0_40]

at java.util.LinkedHashMap$LinkedEntryIterator.next(LinkedHashMap.java:744) ~[na:1.8.0_40]

at java.util.LinkedHashMap$LinkedEntryIterator.next(LinkedHashMap.java:742) ~[na:1.8.0_40]

at org.apache.solr.common.params.ModifiableSolrParams.toString(ModifiableSolrParams.java:201) ~[solr-solrj-5.2.1.jar:5.2.1

at java.text.MessageFormat.subformat(MessageFormat.java:1280) ~[na:1.8.0_40]

at java.text.MessageFormat.format(MessageFormat.java:865) ~[na:1.8.0_40]

at java.text.Format.format(Format.java:157) ~[na:1.8.0_40]

at java.text.MessageFormat.format(MessageFormat.java:841) ~[na:1.8.0_40]

at AbstractSolrRepository.findAllAsyncImpl(AbstractSolrRepository.java:236)

The code looks like below:

@Nonnull private List<Future<List<T>>> findAllAsync(final SolrParams originalParams, final int readSize,
        final long totalCount) {
    final ModifiableSolrParams query = new ModifiableSolrParams(originalParams);
    query.set(CommonParams.ROWS, readSize);
    final List<Future<List<T>>> futures = new ArrayList<>();
    int start = 0;
    while (start < totalCount) {
        final ModifiableSolrParams solrParams = new ModifiableSolrParams(query);
        solrParams.set(CommonParams.START, start);
        final Stopwatch stopWatch = Stopwatch.createStarted();

        futures.add(executor.submit(() -> querySolr(solrParams)));
        if (logger.isDebugEnabled()) {
            logger.debug(MessageFormat.format("executor.submit took {0}, params: {1}",
                    stopWatch.elapsed(TimeUnit.MILLISECONDS), solrParams));
        }
        start += readSize;
    }
    return futures;
}

-- the code is much simplified later. Check final code here.

We submit the query task into thread pool, and want to log how long the submit takes - when all threads in the thread pool are busy, and its queue is full, the submit will block. I want to figure out whether it happens, whether I need change the thread pool settings.

-- Check AsyncConfigurer configuration code here.

It feels strange, so I decide to figure out why.

The Root Cause

ModifiableSolrParams uses LinkedHashMap to store data, its toString loops the LinkedHashMap. 

From the exception, it means that the ModifiableSolrParams is changed during the for-loop in toString() method.

So I check what changed in ModifiableSolrParams, find out solrClient.query adds _stateVer_=cobradb.survey_response:2903.

Then I go to solr github repos and search _stateVer_, and find CloudSolrClient and public static final String STATE_VERSION = "_stateVer_";.

Then I add a break point to places where STATE_VERSION is used and find the following code:

org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(SolrRequest, int, String)

    if (request.getParams() instanceof ModifiableSolrParams) {

      ModifiableSolrParams params = (ModifiableSolrParams) request.getParams();

      if (stateVerParam != null) {

        params.set(STATE_VERSION, stateVerParam);

      } else {

        params.remove(STATE_VERSION);

      }

    }

The ConcurrentModificationException will happen when the code above and the for-loop in ModifiableSolrParams.toString runs at same time.

Search - Fix same problem

Next I search logger.*query and logger.*param to check whether we made same mistake.