Tuesday, December 18, 2012

Java Collections - Synchronization Myth

Introduction:

Java community tried to reduce developers pain by adding synchronization mechanism for various java collections. There are 6 flavors of API available which could help developers to synchronize different java collections. Here is the list of API:
  • Collections.synchronizedList()
  • Collections.synchronizedCollection()
  • Collections.synchronizedMap()
  • Collections.synchronizedSet()
  • Collections.synchronizedSortedMap()
  • Collections.synchronizedSortedSet()
The collections returned by these methods are capable to handle synchronization for basic operations on collections e.g. get(), set(), add(), remove() etc.

The Myth:

As soon as  developers synchronize their objects using synchronization APIs, they start to believe that they need to put more code to deal with synchronization for these objects, which is not true for all cases. Let me demonstrate this with simple example.

"An ArrayList Need to be accessed by two different threads, One thread need to iterate over list and other will try to add few new entries"

Here is threads detail:
  • t1 : This thread uses Iterator to traverse through the list
  • t2 : This thread uses for loop with index based approach
  • t3 : This thread uses Iterator with sync block to traverse through the list
  • t4 : This thread will try to add new entries in the list.
Source Code:
import java.util.ArrayList;
import java.util.Collections;
import java.util.Iterator;
import java.util.List;
public class Sample2 {
public static void main(String[] args) {
new Sample2().doMain();
}
private void doMain(){
final List<String> list = Collections.synchronizedList(new ArrayList<String>());
for (int i = 0; i < 10; i++) {
list.add("value "+ i);
}
Thread t1 = new Thread(new Runnable(){
@Override
public void run() {
for (Iterator<String> iterator = list.iterator(); iterator.hasNext();) {
System.out.println(iterator.next());
try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
});
Thread t2 =new Thread(new Runnable(){
@Override
public void run() {
for (int i = 0; i < list.size(); i++) {
System.out.println(list.get(i));
try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
});
Thread t3 = new Thread(new Runnable(){
@Override
public void run() {
synchronized (list) {
for (Iterator<String> iterator = list.iterator(); iterator.hasNext();) {
System.out.println(iterator.next());
try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}
});
Thread t4 = new Thread(new Runnable(){
@Override
public void run() {
for (int i=0; i <5; i++) {
list.add("New Value "+i);
System.out.println("Valued Added");
try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
});
t1.start();
t4.start();
}
}
view raw Sample2.java hosted with ❤ by GitHub
I tried to execute code in different combinations:

case1:

Use t1 and t4. Start both threads. 
"ConcurrentModificationException" will be thrown.

 

case2:

Use t2 and t4. Start both threads. 
Successful execution with concurrently updating the list.

 

case3:

User t3 and t4. Start both threads. 
Successful execution with no concurrent update.

Conclusion:  

Developers need to be careful about synchronization even if collections has been synchronized using Collections API.

Tuesday, December 11, 2012

Efficient Logging in Java

Logging is very important part of any programming language. It gives important information to developers to understand the program behavior. Its almost next to impossible to debug issues without logs. So logs are very important but logging itself is overhead for any program. It shares valuable CPU time, consume program memory, perform I/O operations. So Logs are necessary evils. 

Various logging framework provide various techniques to reduce these overhead. Common techniques to improve performance

  • Configuration Techniques
    • Set default logging level to Severe
    • On demand enable Logging for specific module
  • Programming Techniques
    • Use discretion while putting log level for evey log
    • Check log level before processing logging command
Recently I come across some other ways to improve logging efficiency. I tried to run few tests around them. Here is test case result:

Test Code using "java.util.logging.Logger"
package learn.java.logger;
import java.util.logging.Level;
import java.util.logging.Logger;
public class LearnJavaLogging {
private static final Logger logger = Logger.getLogger(LearnJavaLogging.class.getName());
public static void main(String[] args){
logger.log(Level.SEVERE, "Case 1: Start time : {0}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
logger.log(Level.FINE, "Entry number: {0} is ", i);
}
logger.log(Level.SEVERE, "Case 1: End time : {0}", System.currentTimeMillis());
logger.log(Level.SEVERE, "Case 2: Start time : {0}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
if(logger.isLoggable(Level.FINE)){
logger.log(Level.FINE, "Entry number: {0} is ", i);
}
}
logger.log(Level.SEVERE, "Case 2: End time : {0}", System.currentTimeMillis());
logger.log(Level.SEVERE, "Case 3: Start time : {0}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
logger.log(Level.FINE, "Entry number: " + i + " is ");
}
logger.log(Level.SEVERE, "Case 3: End time : {0}", System.currentTimeMillis());
logger.log(Level.SEVERE, "Case 4: Start time : {0}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
logger.log(Level.FINE, "Static Log");
}
logger.log(Level.SEVERE, "Case 4: End time : {0}", System.currentTimeMillis());
logger.log(Level.SEVERE, "Case 5: Start time : {0}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
if(logger.isLoggable(Level.FINE)){
logger.log(Level.FINE, "Static Log");
}
}
logger.log(Level.SEVERE, "Case 5: End time : {0}", System.currentTimeMillis());
}
}

Test Results "java.util.logging.Logger"
23:36:44.427 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: Start time : 1355249204421
23:36:44.449 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: End time : 1355249204449
23:36:44.450 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: Start time : 1355249204450
23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: End time : 1355249204455
23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: Start time : 1355249204455
23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: End time : 1355249204505
23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: Start time : 1355249204505
23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: End time : 1355249204506
23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: Start time : 1355249204506
23:36:44.507 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: End time : 1355249204507

Test Results "java.util.logging.Logger"
SEVERE: Case 1: Start time : 1,355,176,462,009
SEVERE: Case 1: End time : 1,355,176,462,101
SEVERE: Case 2: Start time : 1,355,176,462,102
SEVERE: Case 2: End time : 1,355,176,462,105
SEVERE: Case 3: Start time : 1,355,176,462,106
SEVERE: Case 3: End time : 1,355,176,462,160
SEVERE: Case 4: Start time : 1,355,176,462,160
SEVERE: Case 4: End time : 1,355,176,462,162
SEVERE: Case 5: Start time : 1,355,176,462,163
SEVERE: Case 5: End time : 1,355,176,462,164

Test Code using "org.apache.logging.log4j.Logger"
package learn.java.logger;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class LearnApacheLogging {
private static final Logger logger = LogManager.getLogger(LearnApacheLogging.class.getName());
public static void main(String[] args){
logger.fatal("Case 1: Start time : {}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
logger.debug("Entry number: {} is ", i);
}
logger.fatal("Case 1: End time : {}", System.currentTimeMillis());
logger.fatal("Case 2: Start time : {}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
if(logger.isDebugEnabled()){
logger.debug("Entry number: {} is ", i);
}
}
logger.fatal("Case 2: End time : {}", System.currentTimeMillis());
logger.fatal("Case 3: Start time : {}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
logger.debug("Entry number: " + i + " is ");
}
logger.fatal("Case 3: End time : {}", System.currentTimeMillis());
logger.fatal("Case 4: Start time : {}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
logger.debug("Static Log");
}
logger.fatal("Case 4: End time : {}", System.currentTimeMillis());
logger.fatal("Case 5: Start time : {}", System.currentTimeMillis());
for (int i = 0; i < 100000; i++) {
if(logger.isDebugEnabled()){
logger.debug("Static Log");
}
}
logger.fatal("Case 5: End time : {}", System.currentTimeMillis());
}
}

Test Results "org.apache.logging.log4j.Logger"
23:36:44.427 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: Start time : 1355249204421
23:36:44.449 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: End time : 1355249204449
23:36:44.450 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: Start time : 1355249204450
23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: End time : 1355249204455
23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: Start time : 1355249204455
23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: End time : 1355249204505
23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: Start time : 1355249204505
23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: End time : 1355249204506
23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: Start time : 1355249204506
23:36:44.507 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: End time : 1355249204507


Conclusion
  1. Apache Logger is more efficient in logging than java default logger.
  2. String concatenation technique in less efficient than new placeholder technique. [But for log4j placeholder technique is available in  log4j 2.0 only.]
  3. Its very efficient to check log level before logging command for dynamic logs [The logs which require string concatenation or placing values in placeholders ]
  4. Its inefficient to check log level before logging command for simple/static logs.
Reference:
http://logging.apache.org/log4j/2.x/performance.html