How to improve performance of SimpleDateFormat wrapped in ThreadLocal?
This is on Java 7 (51) on RHEL with 24 cores We are noticing a rise in average response times of a java SimpleDateFormat wrapped in thread local as we increase the thread pool size. Is this expected? or, I am just doing something stupid ?
Test program
public class DateFormatterLoadTest {
private static final Logger LOG = Logger.getLogger(DateFormatterLoadTest .class);
private final static int CONCURRENCY = 10;
public static void main(String[] args) throws Exception {
final AtomicLong total = new AtomicLong(0);
ExecutorService es = Executors.newFixedThreadPool(CONCURRENCY);
final CountDownLatch cdl = new CountDownLatch(CONCURRENCY);
for (int i = 0; i < CONCURRENCY; i++) {
es.execute(new Runnable() {
@Override
public void run() {
try {
int size = 65000;
Date d = new Date();
long time = System.currentTimeMillis();
for (int i = 0; i < size; i++) {
String sd = ISODateFormatter.convertDateToString(d);
assert (sd != null);
}
total.addAndGet((System.currentTimeMillis() - time));
} catch (Throwable t) {
t.printStackTrace();
} finally {
cdl.countDown();
}
}
});
}
cdl.await();
es.shutdown();
LOG.info("TOTAL TIME:" + total.get());
LOG.info("AVERAGE TIME:" + (total.get() / CONCURRENCY));
}
}
DateFormatter class:
public class ISODateFormatter {
private static final Logger LOG = Logger.getLogger(ISODateFormatter.class);
private static ThreadLocal<DateFormat> dfWithTZ = new ThreadLocal<DateFormat>() {
@Override
public DateFormat get() {
return super.get();
}
@Override
protected DateFormat initialValue() {
return new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ssZ",
Locale.ENGLISH);
}
@Override
public void remove() {
super.remove();
}
@Override
public void set(DateFormat value) {
super.set(value);
}
};
public static String convertDateToString(Date date) {
if (date == null) {
return null;
}
try {
return dfWithTZ.get().format(date);
} catch (Exception e) {
LOG.error("!!! Error parsing dateString: " + date, e);
return null;
}
}
}
Someone suggested to take out the AtomicLong so just wanted to share that it is not playing any role in increasing the average time:
##NOT USING ATOMIC LONG##
2014-02-28 11:03:52,790 [pool-1-thread-1] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:328
2014-02-28 11:03:52,868 [pool-1-thread-6] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:406
2014-02-28 11:03:52,821 [pool-1-thread-2] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:359
2014-02-28 11:03:52,821 [pool-1-thread-8] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:359
2014-02-28 11:03:52,868 [pool-1-thread-4] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:406
2014-02-28 11:03:52,915 [pool-1-thread-5] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:453
2014-02-28 11:03:52,930 [pool-1-thread-7] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:468
2014-02-28 11:03:52,930 [pool-1-thread-3] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:468
2014-02-28 11:03:52,930 [main] INFO net.ahm.graph.DateFormatterLoadTest - CONCURRENCY:8
##USING ATOMIC LONG##
2014-02-28 11:02:53,852 [main] INFO net.ahm.graph.DateFormatterLoadTest - TOTAL TIME:2726
2014-02-28 11:02:53,852 [main] INFO net.ahm.graph.DateFormatterLoadTest - CONCURRENCY:8
2014-02-28 11:02:53,852 [main] INFO net.ahm.graph.DateFormatterLoadTest - AVERAGE TIME:340
##NOT USING ATOMIC LONG##
2014-02-28 11:06:57,980 [pool-1-thread-3] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:312
2014-02-28 11:06:58,339 [pool-1-thread-8] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:671
2014-02-28 11:06:58,339 [pool-1-thread-4] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:671
2014-02-28 11:06:58,307 [pool-1-thread-7] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:639
2014-02-28 11:06:58,261 [pool-1-thread-6] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:593
2014-02-28 11:06:58,105 [pool-1-thread-15] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:437
2014-02-28 11:06:58,089 [pool-1-thread-13] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:421
2014-02-28 11:06:58,073 [pool-1-thread-1] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:405
2014-02-28 11:06:58,073 [pool-1-thread-12] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:405
2014-02-28 11:06:58,042 [pool-1-thread-14] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:374
2014-02-28 11:06:57,995 [pool-1-thread-2] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:327
2014-02-28 11:06:57,995 [pool-1-thread-16] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:327
2014-02-28 11:06:58,385 [pool-1-thread-10] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:717
2014-02-28 11:06:58,385 [pool-1-thread-11] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:717
2014-02-28 11:06:58,417 [pool-1-thread-9] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:749
2014-02-28 11:06:58,418 [pool-1-thread-5] INFO net.ahm.graph.DateFormatterLoadTest - THREAD TIME:750
2014-02-28 11:06:58,418 [main] INFO net.ahm.graph.DateFormatterLoadTest - CONCURRENCY:16
##USING ATOMIC LONG##
2014-02-28 11:07:57,510 [main] INFO net.ahm.graph.DateFormatterLoadTest - TOTAL TIME:9365
2014-02-28 11:07:57,510 [main] INFO net.ahm.graph.DateFormatterLoadTest - CONCURRENCY:16
2014-02-28 11:07:57,510 [main] INFO net.ahm.graph.DateFormatterLoadTest - AVERAGE TIME:585
Answer
Creating an instance of SimpleDateFormat is very expensive (this article shows some profiling/benchmarking). If this is true, compared with the parsing of the dates into strings, then it follows that as you increase the number of threads (and therefore the number of SimpleDateFormat instances as they are threadlocals) your average time is going to increase.