Search code examples
javasynchronizationatomicinteger

Incorect value of incremented value inside lambda and new Thread

I create 10 parallel network requests. And I need to understand when all of them was finished.

I try to do this via AtomicInteger and synchronized block. But it not help.

Size of hostInfoList = 10.

Here snippet:

    AtomicInteger countOfResponse = new AtomicInteger(0);
    LOGGER.info("myMethod: hostInfoList_size  = {}", hostInfoList.size());
    for (HostInfo hostInfo : hostInfoList) {
        new Thread(() -> {
            ErrorDetails errorDetails = new ErrorDetails();
            XML response = null;
            try {
                LOGGER.info("");
                response = execute_network_request(); // run network request
                LOGGER.info("myMethod: before_inc_count = {}", countOfResponse.get());
                synchronized (this) {
                    countOfResponse.incrementAndGet();
                }
                LOGGER.info("myMethod:after_inc_count = {}", countOfResponse.get());
            } catch (Exception e) {
                errorDetails.setDetails(e.getMessage());
            } finally {
                LOGGER.info("myMethod: finally")
                if (countOfResponse.get() ==  hostInfoList.size()) {
                   LOGGER.info("myMethod: finished all requests");
                 } 
            }
        }).start();
    }

And here log:

2024-02-15 13:28:08.558 INFO  [MyClass:Thread-275] myMethod: before_inc_count = 0
2024-02-15 13:28:08.558 INFO  [MyClass:Thread-272] myMethod: before_inc_count = 0
2024-02-15 13:28:08.558 INFO  [MyClass:Thread-275] myMethod: after_inc_count = 2
2024-02-15 13:28:08.558 INFO  [MyClass:Thread-272] myMethod: after_inc_count = 2
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-275] myMethod: finally
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-272] myMethod: finally
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-274] myMethod: before_inc_count = 2
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-274] myMethod:after_inc_count = 3
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-271] myMethod: before_inc_count = 3
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-274] myMethod: finally
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-273] myMethod: before_inc_count = 3
2024-02-15 13:28:08.559 INFO  [MyClass:Thread-271] myMethod:after_inc_count = 4
2024-02-15 13:28:08.560 INFO  [MyClass:Thread-273] myMethod:after_inc_count = 5
2024-02-15 13:28:08.560 INFO  [MyClass:Thread-271] myMethod: finally
2024-02-15 13:28:08.560 INFO  [MyClass:Thread-273] myMethod: finally
2024-02-15 13:28:08.560 INFO  [MyClass:Thread-276] myMethod: before_inc_count = 5
2024-02-15 13:28:08.560 INFO  [MyClass:Thread-276] myMethod:after_inc_count = 6
2024-02-15 13:28:08.560 INFO  [MyClass:Thread-276] myMethod: finally
2024-02-15 13:28:08.562 INFO  [MyClass:Thread-277] myMethod: before_inc_count = 6
2024-02-15 13:28:08.562 INFO  [MyClass:Thread-277] myMethod:after_inc_count = 7
2024-02-15 13:28:08.562 INFO  [MyClass:Thread-277] myMethod: finally
2024-02-15 13:28:08.562 INFO  [MyClass:Thread-278] myMethod: before_inc_count = 7
2024-02-15 13:28:08.562 INFO  [MyClass:Thread-278] myMethod:after_inc_count = 8
2024-02-15 13:28:08.562 INFO  [MyClass:Thread-278] myMethod: finally
2024-02-15 13:28:08.563 INFO  [MyClass:Thread-279] myMethod: before_inc_count = 8
2024-02-15 13:28:08.563 INFO  [MyClass:Thread-279] myMethod:after_inc_count = 9
2024-02-15 13:28:08.563 INFO  [MyClass:Thread-279] myMethod: finally
2024-02-15 13:28:08.564 INFO  [MyClass:Thread-280] myMethod: before_inc_count = 9
2024-02-15 13:28:08.564 INFO  [MyClass:Thread-280] myMethod:after_inc_count = 10
2024-02-15 13:28:08.564 INFO  [MyClass:Thread-280] myMethod: finally

As you can see before_inc_count = 0 and then after_inc_count = 2.

But where is the after_inc_count = 1 ?

Solution

  • AtomicInteger is only atomic per method call. If you make multiple method calls to it, each of those is atomic (and guarantees visibility), but there is no guarantee that the calls to the methods aren't interleaved between threads.

    LOGGER.info("myMethod: before_inc_count = {}", countOfResponse.get());
synchronized (this) {
  countOfResponse.incrementAndGet();
}
LOGGER.info("myMethod:after_inc_count = {}", countOfResponse.get());

    You've got 3 method calls here. They will execute in program order in a single thread, but there is no guaranteed order between threads.

    This means that you could get execution like this:

    Thread 1          Thread 2

get()                                   -> value is 0
                  get()                 -> value is 0
incrementAndGet()                       -> value is 1, but you don't print it
                  incrementAndGet()     -> value is 2, but you don't print it
get()                                   -> value is 2
                  get()                 -> value is 2

    To do this "atomically", you don't need the synchronized block at all:

    int valueBefore;
LOGGER.info("myMethod: before_inc_count = {}", valueBefore = countOfResponse.getAndIncrement());
LOGGER.info("myMethod:after_inc_count = {}", valueBefore + 1);

    (There isn't really any point in logging the after value, because you now know it's one more than what it was before)

    Note, however, that the calls to LOGGER.info are not atomic, so might still interleave between threads, so the messages may not display in ascending order.

    Moreover, even a single invocation of LOGGER.info involves invoking the getAndIncrement method, so you might get interleaving between threads even with just the first log message.

    You could avoid that by wrapping the log lines in a synchronized block; but honestly, accessing an AtomicInteger within a synchronized block is a bit of an indicator of a deeper issue.