Friday, October 23, 2009

Thread Contention introduced with multiple synchronization blocks on the same object, in the same method...

I am currently working on a legacy project and wanted to communicate some of the findings/enhancements as I go along.

I came across a method that incremented static fields to kept track of the number of requests and the thresholds used to send alerts about server utilization. This method had a number of synchronization blocks that used the static lock to manage access to the static variables. The method was basically in the following form:

public void method() {
DO_SOME_WORK THAT DOESN'T NEED TO BE SYNC'ED....
synchronized (this.getClass()) {
DO_SOME_CRITICAL_WORK....
}
DO_SOME_WORK THAT DOESN'T NEED TO BE SYNC'ED....
synchronized (this.getClass()) {
DO_SOME_OTHER_CRITICAL_WORK....
}
}

Looking at the code, a lock (monitor) is attained twice on the same object, which will cause contention as more threads stack up in the queue.

I believe the implementation took to heart, keep the sync blocks as small as possible, but since the same monitor (lock) is being used in the same method, a large amount of contention was introduced.

In a JVM, how threads handle wait/notifications is not mandated in the Java specification, so it is implementation specific and results may vary depending on the JVM you use.

Through inspection, the Sun JVM seems to use a queuing metaphor to handle requests for monitor control.

So basically, the flow with 3 thread could be as follows (again, the exact order can vary, but in general):
- Thread 1,2 & 3 request monitor control, respectively.
- Thread 1 gets the monitor while Thread 2 & 3 are queued.
- Thread 1 exists sync block 1 and releases control of the monitor.
- Thread 2 gets the monitor.
- Thread 1 hits sync block 2 , can't get control of the monitor and is queued.
- Thread 2 exists sync block 1 and releases control of the monitor.
- Thread 3 gets the monitor.
- Thread 2 hits sync block 2, can't get control of the monitor and is queued.
- Thread 3 exists sync block 1 and releases control of the monitor.
- Thread 1 gets the monitor.
- Thread 3 hits sync block 2, can't get control of the monitor and is queued.
- Thread 1 exists sync block 2 and releases control of the monitor.
- Thread 2 gets the monitor.
- Thread 2 exists sync block 2 and releases control of the monitor.
- Thread 3 gets the monitor.
- Thread 3 exists sync block 2 and releases control of the monitor.

Below you will find, the actual load-tested output that depicts the choreography between the sync blocks with 20 concurrent requests and 50 concurrent requests

Some of the requests finished faster than others, but as you can see some took quite a bit longer. I highlighted and labeled some of the threads that took a longer time for maximum affect.

A better implementation would have you a single synchronized block to handle the critical areas of the methods or use an efficient monitoring tool to get the same statistics...

DISCLAIMER: Yes, I know that adding the print statements exacerbated the time spent inside the sync block therefore making the times longer, but I am trying to convey what is going on inside the JVM, not the exact duration times inside the method. All instrumentation affects performance :-)

Hope this helps - Thanks - Mark :-)

_________________________________________________________________________________
This is what happens when I sent 20 concurrent requests in...
Sync 1 out - TP-Processor8 - Outside of Sync block 1 waiting to get the monitor
Sync 1 out - TP-Processor5
Sync 1 out - TP-Processor1
Sync 1 out - TP-Processor13
Sync 1 out - TP-Processor11
Sync 1 out - TP-Processor15
Sync 1 out - TP-Processor9
Sync 1 out - TP-Processor7
Sync 1 out - TP-Processor12
Sync 1 out - TP-Processor19
Sync 1 out - TP-Processor3
Sync 1 out - TP-Processor18
Sync 1 in - TP-Processor24
Sync 1 out - TP-Processor14
Sync 1 in - TP-Processor17
Sync 2 out - TP-Processor24
Sync 2 out - TP-Processor17
Sync 1 in - TP-Processor6
Sync 2 out - TP-Processor6
Sync 1 in - TP-Processor20
Sync 2 out - TP-Processor20
Sync 1 in - TP-Processor2
Sync 2 out - TP-Processor2
Sync 1 in - TP-Processor16
Sync 2 out - TP-Processor16
Sync 1 in - TP-Processor10
Sync 2 out - TP-Processor10
Sync 1 in - TP-Processor8 - Inside Sync block 1 (has monitor)
Sync 2 out - TP-Processor8 - Outside Sync block 2 waiting to get the monitor
Sync 1 in - TP-Processor5
Sync 2 out - TP-Processor5
Sync 1 in - TP-Processor1
Sync 2 out - TP-Processor1
Sync 1 in - TP-Processor13
Sync 2 out - TP-Processor13
Sync 1 in - TP-Processor11
Sync 2 out - TP-Processor11
Sync 1 in - TP-Processor15
Sync 2 out - TP-Processor15
Sync 1 in - TP-Processor9
Sync 2 out - TP-Processor9
Sync 1 in - TP-Processor7
Sync 2 out - TP-Processor7
Sync 1 in - TP-Processor12
Sync 2 out - TP-Processor12
Sync 1 in - TP-Processor19
Sync 2 out - TP-Processor19
Sync 1 in - TP-Processor3
Sync 2 out - TP-Processor3
Sync 1 in - TP-Processor18
Sync 2 out - TP-Processor18
Sync 1 in - TP-Processor14
Sync 2 out - TP-Processor14
Sync 2 in - TP-Processor24
Sync Complete - 389 - TP-Processor24
Sync 2 in - TP-Processor17
Sync Complete - 389 - TP-Processor17
Sync 2 in - TP-Processor6
Sync Complete - 405 - TP-Processor6
Sync 2 in - TP-Processor20
Sync Complete - 390 - TP-Processor20
Sync 2 in - TP-Processor2
Sync Complete - 390 - TP-Processor2
Sync 2 in - TP-Processor16
Sync 2 in - TP-Processor10
Sync Complete - 406 - TP-Processor10
Sync 2 in - TP-Processor8 - Inside Sync block 2 (has monitor)
Sync Complete - 406 - TP-Processor16
Sync Complete - 405 - TP-Processor8 - Finished method in 405 ms

_________________________________________________________________________________
This is what happens when I sent 50 concurrent requests in...
Sync 1 out - TP-Processor5- Outside Sync block 1 waiting to get the monitor
Sync 2 out - TP-Processor38
Sync 1 in - TP-Processor28
Sync 1 out - TP-Processor46
Sync 2 out - TP-Processor28
Sync 1 in - TP-Processor44
Sync 2 out - TP-Processor44
Sync 1 in - TP-Processor34
Sync 2 out - TP-Processor34
Sync 1 in - TP-Processor20
Sync 2 out - TP-Processor20
Sync 1 in - TP-Processor10
Sync 2 out - TP-Processor10
Sync 1 in - TP-Processor2
Sync 2 out - TP-Processor2
Sync 1 in - TP-Processor35
Sync 2 out - TP-Processor35
Sync 1 in - TP-Processor42
Sync 2 out - TP-Processor42
Sync 1 in - TP-Processor1
Sync 2 out - TP-Processor1
Sync 1 in - TP-Processor40
Sync 2 out - TP-Processor40
Sync 1 in - TP-Processor36
Sync 2 out - TP-Processor36
Sync 1 in - TP-Processor16
Sync 2 out - TP-Processor16
Sync 1 in - TP-Processor14
Sync 2 out - TP-Processor14
Sync 1 in - TP-Processor26
Sync 2 out - TP-Processor26
Sync 2 in - TP-Processor31
Sync Complete - 726 - TP-Processor31
Sync 1 in - TP-Processor25
Sync 2 out - TP-Processor25
Sync 1 in - TP-Processor37
Sync 1 in - TP-Processor18
Sync 2 out - TP-Processor37
Sync 2 out - TP-Processor18
Sync 1 in - TP-Processor9
Sync 2 out - TP-Processor9
Sync 1 in - TP-Processor45
Sync 2 out - TP-Processor45
Sync 1 in - TP-Processor29
Sync 2 out - TP-Processor29
Sync 1 in - TP-Processor52
Sync 2 out - TP-Processor52
Sync 1 in - TP-Processor30
Sync 2 out - TP-Processor30
Sync 1 in - TP-Processor50
Sync 1 in - TP-Processor11
Sync 2 out - TP-Processor50
Sync 2 out - TP-Processor11
Sync 1 in - TP-Processor48
Sync 2 out - TP-Processor48
Sync 1 in - TP-Processor6
Sync 2 out - TP-Processor6
Sync 1 in - TP-Processor41
Sync 2 out - TP-Processor41
Sync 1 in - TP-Processor8
Sync 2 out - TP-Processor8
Sync 1 in - TP-Processor13
Sync 2 out - TP-Processor13
Sync 1 in - TP-Processor3
Sync 2 out - TP-Processor3
Sync 1 in - TP-Processor7
Sync 2 out - TP-Processor7
Sync 1 in - TP-Processor24
Sync 2 out - TP-Processor24
Sync 1 in - TP-Processor19
Sync 1 in - TP-Processor21
Sync 2 out - TP-Processor19
Sync 2 out - TP-Processor21
Sync 1 in - TP-Processor12
Sync 2 out - TP-Processor12
Sync 1 in - TP-Processor51
Sync 2 out - TP-Processor51
Sync 1 in - TP-Processor47
Sync 2 out - TP-Processor47
Sync 1 in - TP-Processor22
Sync 2 out - TP-Processor22
Sync 1 in - TP-Processor17
Sync 2 out - TP-Processor17
Sync 1 in - TP-Processor27
Sync 2 out - TP-Processor27
Sync 1 in - TP-Processor43
Sync 2 out - TP-Processor43
Sync 1 in - TP-Processor15
Sync 2 out - TP-Processor15
Sync 1 in - TP-Processor32
Sync 2 out - TP-Processor32
Sync 1 in - TP-Processor33
Sync 2 out - TP-Processor33
Sync 1 in - TP-Processor23
Sync 2 out - TP-Processor23
Sync 1 in - TP-Processor39
Sync 2 out - TP-Processor39
Sync 1 in - TP-Processor5 - Inside Sync block 1 (has monitor)
Sync 2 out - TP-Processor5 - Outside Sync block 2 waiting to get the monitor
Sync 2 in - TP-Processor38
Sync Complete - 947 - TP-Processor38
Sync 1 in - TP-Processor46
Sync 2 out - TP-Processor46
Sync 2 in - TP-Processor28
Sync Complete - 931 - TP-Processor28
Sync 2 in - TP-Processor44
Sync Complete - 916 - TP-Processor44
Sync 2 in - TP-Processor34
Sync Complete - 916 - TP-Processor34
Sync 2 in - TP-Processor20
Sync 2 in - TP-Processor10
Sync Complete - 900 - TP-Processor20
Sync Complete - 900 - TP-Processor10
Sync 2 in - TP-Processor2
Sync Complete - 899 - TP-Processor2
Sync 2 in - TP-Processor35
Sync Complete - 899 - TP-Processor35
Sync 2 in - TP-Processor42
Sync Complete - 899 - TP-Processor42
Sync 2 in - TP-Processor1
Sync 2 in - TP-Processor40
Sync Complete - 915 - TP-Processor1
Sync Complete - 915 - TP-Processor40
Sync 2 in - TP-Processor36
Sync Complete - 915 - TP-Processor36
Sync 2 in - TP-Processor16
Sync Complete - 915 - TP-Processor16
Sync 2 in - TP-Processor14
Sync Complete - 915 - TP-Processor14
Sync 2 in - TP-Processor26
Sync Complete - 931 - TP-Processor26
Sync 2 in - TP-Processor25
Sync Complete - 773 - TP-Processor25
Sync 2 in - TP-Processor37
Sync Complete - 758 - TP-Processor37
Sync 2 in - TP-Processor18
Sync Complete - 758 - TP-Processor18
Sync 2 in - TP-Processor9
Sync Complete - 774 - TP-Processor9
Sync 2 in - TP-Processor45
Sync 2 in - TP-Processor29
Sync Complete - 773 - TP-Processor45
Sync Complete - 773 - TP-Processor29
Sync 2 in - TP-Processor52
Sync Complete - 773 - TP-Processor52
Sync 2 in - TP-Processor30
Sync Complete - 789 - TP-Processor30
Sync 2 in - TP-Processor50
Sync Complete - 773 - TP-Processor50
Sync 2 in - TP-Processor11
Sync Complete - 773 - TP-Processor11
Sync 2 in - TP-Processor48
Sync Complete - 773 - TP-Processor48
Sync 2 in - TP-Processor6
Sync 2 in - TP-Processor41
Sync Complete - 789 - TP-Processor6
Sync Complete - 805 - TP-Processor41
Sync 2 in - TP-Processor8
Sync Complete - 789 - TP-Processor8
Sync 2 in - TP-Processor13
Sync Complete - 805 - TP-Processor13
Sync 2 in - TP-Processor3
Sync Complete - 805 - TP-Processor3
Sync 2 in - TP-Processor7
Sync Complete - 805 - TP-Processor7
Sync 2 in - TP-Processor24
Sync Complete - 805 - TP-Processor24
Sync 2 in - TP-Processor19
Sync Complete - 805 - TP-Processor19
Sync 2 in - TP-Processor21
Sync Complete - 805 - TP-Processor21
Sync 2 in - TP-Processor12
Sync Complete - 805 - TP-Processor12
Sync 2 in - TP-Processor51
Sync Complete - 821 - TP-Processor51
Sync 2 in - TP-Processor47
Sync Complete - 821 - TP-Processor47
Sync 2 in - TP-Processor22
Sync 2 in - TP-Processor17
Sync Complete - 805 - TP-Processor22
Sync Complete - 805 - TP-Processor17
Sync 2 in - TP-Processor27
Sync Complete - 821 - TP-Processor27
Sync 2 in - TP-Processor43
Sync Complete - 821 - TP-Processor43
Sync 2 in - TP-Processor15
Sync Complete - 821 - TP-Processor15
Sync 2 in - TP-Processor32
Sync 2 in - TP-Processor33
Sync Complete - 821 - TP-Processor32
Sync Complete - 2036 - TP-Processor33
Sync 2 in - TP-Processor23
Sync Complete - 2052 - TP-Processor23
Sync 2 in - TP-Processor39
Sync Complete - 2052 - TP-Processor39
Sync 2 in - TP-Processor5 - Inside Sync block 2 (has monitor)
Sync Complete - 2067 - TP-Processor5 - Finished method in 2067 ms