This week's book giveaway is in the Mac OS forum.
We're giving away four copies of a choice of "Take Control of Upgrading to Yosemite" or "Take Control of Automating Your Mac" and have Joe Kissell on-line!
See this thread for details.
The moose likes Threads and Synchronization and the fly likes Need help understanding results from running 2 threads Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login


JavaRanch » Java Forums » Java » Threads and Synchronization
Bookmark "Need help understanding results from running 2 threads" Watch "Need help understanding results from running 2 threads" New topic
Author

Need help understanding results from running 2 threads

Faz Ali
Greenhorn

Joined: Dec 02, 2010
Posts: 21
Hi All,

I've heard nothing but good things about JavaRanch so have decided to join to get some grade A Java knowledge. Please bear with me as I am a relative Java newbie and I apologise in advance if my questions are extremely stupid...
I have just dived into the world of threads and am having a little play. I'm written the following code but the results are not as I expect them to be, I hope someone can enlighten me on what is happening?!?:




Now, during a certain run of the above code, I received the following results:

Runnable1 is reading
Runnable2 is reading
Runnable1 is about to update the counter
Runnable2 is about to update the counter
Runnable1 has written 2
Runnable1 is reading
Runnable1 is about to update the counter
Runnable1 has written 3
Runnable1 is reading
Runnable1 is about to update the counter
Runnable1 has written 4
Runnable1 is reading
Runnable1 is about to update the counter
Runnable1 has written 5
Runnable1 is reading
Runnable1 is about to update the counter
Runnable1 has written 6
Runnable1 is reading
Runnable1 is about to update the counter
Runnable1 has written 7
Runnable1 is reading
Runnable1 is about to update the counter
Runnable2 has written 2
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 9
Runnable2 is reading

My question is, why does Runnable2 change the counter value to '2' when it calls the updateCounter() method since Runnable1 has been running and has already changed the counter value to '7' or higher. I mean, the method updateCounter() is just doing counter++. I.e. counter = counter + 1. Therefore a new read of counter is carried out and at this stage, counter should be identified as '7' or higher. The changes made should have been tracked theoretically unless I'm missing something obvious?

Any explanation would be appreciated. Feel free to run the code and see similar results firsthand.
Thanks
Steve Luke
Bartender

Joined: Jan 28, 2003
Posts: 4181
    
  21

Hi Faz,

Welcome to JavaRanch!

The problem here is in the reporting. You are synchronizing the counter++ part, but are not synchronizing anything else. This means that the reporting may be out of synch.

The key to remember here is that this line of code is actually multiple steps:


It can turn in to code that reads like this (not actual byte code - just an example):


The instruction can be interrupted at any point in there to allow a different thread to run. What looks like it may be happening is that Runnable2 gets through the 'get counter' part (and maybe anywhere before the flush command) first, but the context gets switched to Runnable1 before the flush occurs. So you see Runnable1's output first. Runnable1 makes several changes then the thread context switches back toe Runnable2, which already has a value for counter which is stale, it flushes the output and you get what looks like an out of sequence value, but which is probably just a stale report.

If you need to make sure the report is up to date with the counter (and prevent this sort of stale data from leaking out) then you need to put the report (the System.out.println) in the same synchronized block as the code which does the data update.


Steve
Faz Ali
Greenhorn

Joined: Dec 02, 2010
Posts: 21
Steve Luke wrote:Hi Faz,

Welcome to JavaRanch!

The problem here is in the reporting. You are synchronizing the counter++ part, but are not synchronizing anything else. This means that the reporting may be out of synch.

The key to remember here is that this line of code is actually multiple steps:


It can turn in to code that reads like this (not actual byte code - just an example):


The instruction can be interrupted at any point in there to allow a different thread to run. What looks like it may be happening is that Runnable2 gets through the 'get counter' part (and maybe anywhere before the flush command) first, but the context gets switched to Runnable1 before the flush occurs. So you see Runnable1's output first. Runnable1 makes several changes then the thread context switches back toe Runnable2, which already has a value for counter which is stale, it flushes the output and you get what looks like an out of sequence value, but which is probably just a stale report.

If you need to make sure the report is up to date with the counter (and prevent this sort of stale data from leaking out) then you need to put the report (the System.out.println) in the same synchronized block as the code which does the data update.


Hi Steve,

I was ripping my hair out trying to figure this out what you've written makes perfect sense and explains it in the best possible way.
Thanks a bunch.
Pawan Kr Gupta
Greenhorn

Joined: Nov 21, 2010
Posts: 26
Dear Faz,It is working fine.Please see the output.

Runnable1 is reading
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 1
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 2
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 3
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 4
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 5
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 6
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 7
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 8
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 9
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 10
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 11
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 12
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 13
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 14
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 15
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 16
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 17
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 18
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 19
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 20
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 21
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 22
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 23
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 24
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 25
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 26
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 27
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 28
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 29
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 30
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 31
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 32
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 33
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 34
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 35
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 36
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 37
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 38
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 39
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 40
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 41
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 42
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 43
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 44
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 45
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 46
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 47
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 48
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 49
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 50
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 51
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 52
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 53
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 54
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 55
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 56
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 57
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 58
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 59
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 60
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 61
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 62
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 63
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 64
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 65
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 66
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 67
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 68
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 69
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 70
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 71
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 72
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 73
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 74
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 75
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 76
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 77
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 78
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 79
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 80
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 81
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 82
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 83
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 84
Runnable2 is reading
Runnable2 is about to update the counter
Runnable1 is about to update the counter
Runnable2 has written 85
Runnable2 is reading
Runnable1 has written 86
Runnable1 is reading
Runnable2 is about to update the counter
Runnable1 is about to update the counter
Runnable2 has written 87
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 89
Runnable2 is reading
Runnable2 is about to update the counter
Runnable1 has written 88
Runnable1 is reading
Runnable1 is about to update the counter
Runnable1 has written 91
Runnable1 is reading
Runnable1 is about to update the counter
Runnable2 has written 90
Runnable2 is reading
Runnable2 is about to update the counter
Runnable1 has written 92
Runnable1 is reading
Runnable1 is about to update the counter
Runnable2 has written 93
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 95
Runnable1 has written 94
Runnable2 is reading
Runnable2 is about to update the counter
Runnable1 is reading
Runnable2 has written 96
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 97
Runnable2 is reading
Runnable2 is about to update the counter
Runnable2 has written 98
Runnable2 is reading
Runnable2 is about to update the counter
Runnable1 is about to update the counter
Runnable2 has written 99
Runnable2 is reading
Runnable1 has written 100
Steve Luke
Bartender

Joined: Jan 28, 2003
Posts: 4181
    
  21

I am glad I could help. I wanted to make sure you realized that I simplified things a bit to make them more understandable in the given context. Things can get a bit more complicated than that. For example - the synchronization between the 'thread store' and the 'global store' is only guaranteed to occur around a synchronized boundary - which means the 'get counter' step could actually occur prior to the counter++ step, and then from that point on the value could be maintained locally. The effect is that the context switch between Runnable1 and Runnable2 could occur much sooner than the example I gave above and still have the same results. The solution is the same, however, which is why I described it as above.

This gets into the details of the 'Java Memory Model' which can be read in detail here: The Java Memory Model (Chap. 17 in the JLS)
Alex Hurtt
Ranch Hand

Joined: Oct 26, 2010
Posts: 98
In reading this discussion I was wondering about 2 things...

1) was it really necessary to define 2 Runnables with identical function (except for the hard coded text they print out) or could one Runnable have been defined and given to two different Threads?

2) Should the counter variable be volatile? Is there a risk that synchronization alone is not enough were these two Threads to be scheduled on different CPU cores and run truly concurrently, not just time sliced/interleaved on a single processor? Multiple core CPU's are the norm more than the exception these days and I'm in the process of learning about how this development impacts the way we think about traditional Threading issues and what we must consider going forward. My understanding is that most multi-core CPU's these days all have their own local registers (L1/L2 cache) but typically share a single L3 cache pool. Will the proper use of synchronized ensure that even if the 2 Threads are scheduled by the OS on completely separate cores, they will always read and update the value of counter from either the shared L3 cache or the system RAM pool? Or is there still a risk each thread will keep its own local copy of the counter variable in the local cache of the core on which it is running? Or do I have it completely wrong?

Sorry, not trying to hijack the Thread (pun intended) but it got me thinking about these things.
Steve Luke
Bartender

Joined: Jan 28, 2003
Posts: 4181
    
  21

Alex Hurtt wrote:In reading this discussion I was wondering about 2 things...

1) was it really necessary to define 2 Runnables with identical function (except for the hard coded text they print out) or could one Runnable have been defined and given to two different Threads?


Yeah, that would be a good thing to do. But it wouldn't affect the outcome of the program.

2) Should the counter variable be volatile? Is there a risk that synchronization alone is not enough were these two Threads to be scheduled on different CPU cores and run truly concurrently, not just time sliced/interleaved on a single processor?


That depends on what you need. The volatile keyword could be used and would make sure that the values being reported would be currently up to date. The updateCounter() method would still need to be synchronized because volatile only ensures current correctness, it does not ensure sequential integrity. So since the counter++ is actually a multi-step process, it would need to be protected with a synchronized block. Similarly, the volatile key word would not ensure the reported value was the value actually set by the increment. To do that the report would have to occur in the same synchronized block as the increment.

Multiple core CPU's are the norm more than the exception these days and I'm in the process of learning about how this development impacts the way we think about traditional Threading issues and what we must consider going forward. My understanding is that most multi-core CPU's these days all have their own local registers (L1/L2 cache) but typically share a single L3 cache pool. Will the proper use of synchronized ensure that even if the 2 Threads are scheduled by the OS on completely separate cores, they will always read and update the value of counter from either the shared L3 cache or the system RAM pool? Or is there still a risk each thread will keep its own local copy of the counter variable in the local cache of the core on which it is running? Or do I have it completely wrong?


The Java Memory Model guarantees the value gets read from or written to the shared memory pool along synchronization boarders. This is true for multi core processors as well as single core systems. The JRE you are running on may influence where that memory lives and whether threads can actually be run on different cores. But those that allow multi core execution must implement it such that it behaves according to the Java Memory Model rules.

It may also be that the JRE doesn't have to worry about such things - perhaps that level of management (what cache the data belongs in, etc...) is controlled at the CPU or OS level and as such would be invisible to Java. I don't know, it never really concerned me because the JMM tells me the behavior to expect and anything lower level than that doesn't matter to me (not to say it isn't important, just to say I am content with being told what to expect).
 
I agree. Here's the link: http://aspose.com/file-tools
 
subject: Need help understanding results from running 2 threads