KISS

Keep It Simple Stupid

Threads synchronization by logging

| comments

Hi! Today I’d like to write a small note/reminder about a subtle and unintended threads synchronization “feature” by using a shared object, for instance logger. The example will be in Java, and you can check it out with your favorite language (not to say that Java is mine).

To get started, you can git clone https://github.com/pluton8/java_concurrency_examples.git to get the described classes. We’re interested in the e201_sequence_notsynchronizedlist and e202_sequence_notsynchronizedlist_logging classes. As the doc states, it is

A very contrived yet simple example of a Sequence class producing increasing natural numbers with each nextNumber() call. Two Worker threads get the numbers, sharing the same instance, and add them to a shared List. After they’ve added a certain number of numbers, the main object checks if all the numbers in the list are increasing uniformly.

When you run the first version you can get such an output:

1
2
Result: [0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 45, 44, 46, null, null, 48, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97]
First incorrect number @index 46: 45

or even more interesting one:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Exception in thread "Worker0" java.lang.ArrayIndexOutOfBoundsException: 10
Result: [null, null, null, 0, 4, 5, 6, 6, 7, 8, null, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50]
    at java.util.ArrayList.add(ArrayList.java:441)
    at e201_sequence_notsynchronizedlist.addNumber(e201_sequence_notsynchronizedlist.java:47)
    at e201_sequence_notsynchronizedlist$Worker.run(e201_sequence_notsynchronizedlist.java:37)
    at java.lang.Thread.run(Thread.java:744)
Exception in thread "main" java.lang.NullPointerException
    at e201_sequence_notsynchronizedlist.firstIncorrectNumberIndex(e201_sequence_notsynchronizedlist.java:53)
    at e201_sequence_notsynchronizedlist.processResults(e201_sequence_notsynchronizedlist.java:65)
    at e201_sequence_notsynchronizedlist.main(e201_sequence_notsynchronizedlist.java:88)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120)

In any case, you can notice a number of nulls in the numbers list. Where did they come from? Our Sequence’s nextNumber() method can only produce incrementing numbers. Let’s check the return values of the method in the console by adding the simple logging line here (line 36):

1
2
3
final Long number = sequence.nextNumber();
System.out.println(number);
addNumber(number);

The result is class e202_sequence_notsynchronizedlist_logging. No way! I run this version a few dozen of times and never got a null in the list:

1
2
Result: [0, 1, 2, 4, 5, 6, 7, 8, 9, 3, 10, 11, 12, 14, 15, 16, 13, 17, 19, 20, 21, 22, 23, 18, 24, 26, 27, 28, 25, 29, 31, 32, 33, 34, 30, 35, 37, 38, 39, 40, 41, 36, 42, 44, 45, 46, 47, 48, 49, 50, 43, 51, 53, 54, 55, 56, 57, 58, 59, 52, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99]
First incorrect number @index 3: 4

What happened? It’s this phenomenon when using a shared object, the console output stream in this case, implicitly creates a lock and gets rid of the synchronization issue. However, you should never use such a technique, because it’s not obvious and logging could be on in debug (no runtime issues) and off in release (users will face issues).

Remember about it and don’t fall for it. Concurrency is not an easy topic, and the only way to master it is practice.

dev

Don't hesitate to leave a comment below. NB! If you don't see a comment form under the post, it's most likely that an extension (such as Ghostery, NoScript, or AdBlock) of your browser blocks the scripts from disqus.com, and you can unblock that.

« About partial mocking Do you know what this thing is? »

Comments