4

Ok. I wrote the code and get unexpected result of it and I don't know how to explain this result. Can someone help me with this?

public class JMM {
static volatile Boolean ready = false;
static volatile int data = 0;

public static void main() {
    Log.d("JMM", "start");
    new Thread(new Runnable() {
        @Override
        public void run() {
            try {
                Thread.sleep(2000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            data = 1;
            ready = true;
        }
    }).start();

    for(int i = 0; i < 100; i++) {
        new Thread(new Runnable() {
            @Override
            public void run() {
                while (!ready)
                    Log.d("JMM", "second thread data " + data);
            }
        }).start();
    }
}
}

I executed it on Nexus 5 (it has 4 cores):

@Override
protected void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);
    MM.main();
}

result:

D/JMM: second thread data 0

...

D/JMM: second thread data 0

D/JMM: second thread data 0

D/JMM: second thread data 0

D/JMM: second thread data 0

D/JMM: second thread data 0

D/JMM: second thread data 1

D/JMM: second thread data 1

D/JMM: second thread data 1

D/JMM: second thread data 0

D/JMM: second thread data 0

D/JMM: second thread data 1

D/JMM: second thread data 1

D/JMM: second thread data 1

D/JMM: second thread data 1

What I expect? That int is atomic type by default (however I wrote volatile before) and it doesn't cached it's value. But I see that different threads read different values from one field in same moment. Who can explain this to me?

Community
  • 1
  • 1
  • Could you please replace Log.d("JMM", "second thread data " + data) with Log.d("JMM", String.format("%s: %s at %s ",Thread.currentThread(), data, System.currentTimeMillis())) and give us the new output – Nicolas Filotto Apr 16 '16 at 11:58
  • seems like in your case "volatile" do not provide "happens before" ordering. What environment are you using, jre vendor version, compiler? – hahn Apr 16 '16 at 12:01
  • @NicolasFilotto here is link, there some logs with data = 1 https://drive.google.com/file/d/0BysQNNAg-a38ZnhLdk9SUW11Nnc/view?usp=sharing – Alexander Pereverzev Apr 16 '16 at 13:19

1 Answers1

2

Consider what happens at this line:

Log.d("JMM", "second thread data " + data);
  1. Read data
  2. Convert it to a String and concatenate at with "second thread data "
  3. Pass the two args to Log.d
  4. It eventually prints out the message

There is a lot of stuff that happens after the first step, and it's very possible that one thread will start step 1 after another, but get to step 4 before it. For instance:

Thread 1               | Thread 2
-----------------------+-----------------------
1. read "data"         |
2. concat string:      |
  "...data 0"          |
     <<< third thread updates data = 1 >>>
                       | 1. read "data"
                       | 2. concat string:
                       |   "... data 1"
                       | 3. invoke Log.d(...)
                       | 4. print message
                       |   with "... data 1"
3. invoke Log.d(...)   | 
4. print message       |
  with "data 0"        |
yshavit
  • 42,327
  • 7
  • 87
  • 124
  • could you please clarify what do you mean by "another thread will start 1 later, but get to step 4 before"? In this case, writing happens first into "data" and then to "ready" (reordering must not be applied because of volatile). According to JMM, the memory-effect in this case should impose happens-before relationship and thus when "ready" becomes "true", data must be "1". That's why when "Log.d" is called, value of "data" must be "1" and it do not have any relation to the steps that you've showed. – hahn Apr 17 '16 at 09:59
  • @hahn I updated my answer. Note that the happens-before relationship only applies when the variable is read (e.g. into a local register, so that it can be passed to the string concatenation method). It does _not_ mean that any values derived from that read are automatically updated if the volatile variable subsequently changes. – yshavit Apr 17 '16 at 15:36
  • I should have read the code more accurately. instead of "while (!ready)" I read "while (ready)". Thanks anyway.. – hahn Apr 17 '16 at 19:07