CODEWITHSUNDEEP
javamultithreadingconcurrencyjava.util.concurrent
MangKyu
MangKyu

Reputation: 51

Java concurrency problem by multi-thread not occured and automatically synchronized

I’m trying to test a multi-threaded concurrency problem.

What I expected is that the result should be less than 0 (not always but sometimes), because it is not synchronized.

Notice the pair of println calls enabled/disabled by an if ( doPrintln ) test. Enabling/disabling changes the outcome of the test.

class OptionTest
{
    static class Option
    {
        private int quantity;

        public Option ( int aQuantity ) { this.quantity = aQuantity; }

        public int getQuantity ( ) { return quantity; }

        public boolean subtract ( final int aQuantity )
        {
            final boolean doPrintln = false;
            if ( aQuantity >= this.quantity )
            {
                if ( doPrintln ) System.out.println( "Returning FALSE. this.quantity = " + this.quantity + " at " + Instant.now( ) );
                return false;
            }

            if ( doPrintln ) System.out.println( "Returning TRUE. this.quantity = " + this.quantity + " at " + Instant.now( ) );
            this.quantity -= aQuantity;
            return true;
        }
    }

    @Test
    void asyncSubtract ( ) throws InterruptedException
    {
        int numberOfThreads = 100; // Increased number of threads
        ExecutorService executorService = Executors.newFixedThreadPool( numberOfThreads );
        List < Callable < Boolean > > tasks = new ArrayList <>( );

        Option option = new Option( 201 );
        for ( int i = 0 ; i < numberOfThreads ; i++ )
        {
            tasks.add( ( ) -> option.subtract( 50 ) );
        }

        executorService.invokeAll( tasks );
        executorService.shutdown( );

        assertThat( option.getQuantity( ) ).isLessThan( 1 ); // org.assertj.core.api.Assertions.assertThat
        System.out.println( "INFO - Test end.  option.getQuantity( ) = " + option.getQuantity( ) + ". Now: " + Instant.now( ) );
    }
}

Without println

When I run while suppressing the println calls (doPrintln = false), I get this result:

java.lang.AssertionError: 
Expecting actual:
  1
to be less than:
  1 

    at work.basil.example.testing.OptionTest.asyncSubtract(OriginalOptionTest.java:55)
    at java.base/java.lang.reflect.Method.invoke(Method.java:580)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1597)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1597)

With println

When I run the test with doPrintln = true, I get the following result, a hundred lines of Returning … output.

Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.537881Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528665Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528054Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531742Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531094Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.537219Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532059Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528697Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531952Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.527946Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532171Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532220Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.537462Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528005Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.538305Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.536697Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.530989Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.535044Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.538518Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528587Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528202Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528469Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.534627Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528248Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532282Z
Returning FALSE. this.quantity = -999 at 2024-07-24T19:04:06.539461Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528481Z
Returning FALSE. this.quantity = -1049 at 2024-07-24T19:04:06.539559Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532323Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.530792Z
Returning FALSE. this.quantity = -349 at 2024-07-24T19:04:06.538886Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531271Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.527857Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528781Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531565Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532480Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528736Z
Returning FALSE. this.quantity = -1399 at 2024-07-24T19:04:06.540039Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532122Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531314Z
Returning FALSE. this.quantity = -1599 at 2024-07-24T19:04:06.540262Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531166Z
Returning FALSE. this.quantity = -499 at 2024-07-24T19:04:06.539014Z
Returning FALSE. this.quantity = -1649 at 2024-07-24T19:04:06.540332Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532820Z
Returning FALSE. this.quantity = -1649 at 2024-07-24T19:04:06.540406Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.530923Z
Returning FALSE. this.quantity = -1699 at 2024-07-24T19:04:06.540453Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.527858Z
Returning FALSE. this.quantity = -599 at 2024-07-24T19:04:06.539171Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528355Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.533105Z
Returning FALSE. this.quantity = -1849 at 2024-07-24T19:04:06.540620Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.533050Z
Returning FALSE. this.quantity = -899 at 2024-07-24T19:04:06.539382Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528146Z
Returning FALSE. this.quantity = -1949 at 2024-07-24T19:04:06.540756Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.527857Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528517Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.527868Z
Returning FALSE. this.quantity = -2099 at 2024-07-24T19:04:06.540873Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528291Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528636Z
Returning FALSE. this.quantity = -2199 at 2024-07-24T19:04:06.540951Z
Returning FALSE. this.quantity = -1199 at 2024-07-24T19:04:06.539664Z
Returning FALSE. this.quantity = -2249 at 2024-07-24T19:04:06.540996Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.532579Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.531213Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528807Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.528098Z
Returning FALSE. this.quantity = -1199 at 2024-07-24T19:04:06.539833Z
Returning FALSE. this.quantity = -2449 at 2024-07-24T19:04:06.541133Z
Returning TRUE. this.quantity = 201 at 2024-07-24T19:04:06.533149Z
Returning FALSE. this.quantity = -1549 at 2024-07-24T19:04:06.540224Z
Returning FALSE. this.quantity = -1749 at 2024-07-24T19:04:06.540496Z
Returning FALSE. this.quantity = -1799 at 2024-07-24T19:04:06.540566Z
Returning FALSE. this.quantity = -1949 at 2024-07-24T19:04:06.540704Z
Returning FALSE. this.quantity = -1999 at 2024-07-24T19:04:06.540813Z
Returning FALSE. this.quantity = -2149 at 2024-07-24T19:04:06.540909Z
Returning FALSE. this.quantity = -2299 at 2024-07-24T19:04:06.541048Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541178Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541357Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541231Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541415Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541268Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541463Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541311Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541514Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541588Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541618Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541674Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541711Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541767Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541823Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541853Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541895Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541940Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.541988Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.542028Z
Returning FALSE. this.quantity = -2499 at 2024-07-24T19:04:06.542081Z
INFO - Test end.  option.getQuantity( ) = -2499. Now: 2024-07-24T19:04:06.568632Z

Why does invoking System.out.println consistently alter the results?

=================================================== Answer my self. This is indeed an issue caused by memory visibility, and it stems from the cached data in the CPU cores. Context switching ouccured by I/O tasks and it makes data updated on cache of CPU cores. If you want to fix this issue, use keyword volatile.

Upvotes: 1

Views: 119

Answers (1)

Stephen C
Stephen C

Reputation: 719376

If you are asking why adding the print statement causes the program to succeed1, that is (probably) because the print is doing some under the hood synchronization on the shared output stream data structures. That will change the behavior of the code you are testing, and it may be enough to "cure" the memory visibility anomaly you are trying to test for.

While the synchronization behavior of writing to a shared output stream is not specified (e.g. by the javadocs), you would kind of expect it to occur in a typical Java class library. (Output stream classes that could randomly break if used without technically correct synchronization would not be regarded as "fit for purpose".)

1 - Succeed in the sense that it computes the correct results. I understand that you are actually trying to demonstrate that incorrect results can be produced. From that perspective, this is a failure!

Upvotes: 2

Related Questions