simpledateformat is known to be not tread-safe. Yet the valve.invoke() will result in concurrent access to the 4 simpledateformat.format() which is not thread safe (internally shares a Calendar instance).
Good point, and I can see several fixes, not sure which one I'd like best. This point also applies to FastCommonAccessLogValve. Suggestions?
The dumb fix is to create a new simpledateformat every method call (a bit memory trashing for high volume servers) I smarter is to use threadlocal caching: the valve creates a threadlocal to put a simpledate format. 25 thread would imply 25 simpledateformat. Only costs are the threadlocal map lookup and a bit larger heap (more long lived objects implies a bit longer full GC, but less young gc).
Good idea! Can please send patch for the three Logger, AccessLoggerValve, FastCommonAccessLogValve and ExtendedAccessLogValve?
No, I cannot provide a patch. Simple code example: (not the real format) static final ThreadLocal DF_TL = new ThreadLocal() { protected Object initialValue() { return new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS"); } }; static String df(long t) { SimpleDateFormat DF = (SimpleDateFormat)DF_TL.get(); return t<=0 ? "-" : DF.format(new Date(t)); }
Peter, still interested in this?
*** Bug 44748 has been marked as a duplicate of this bug. ***
Is this bug going to be fixed and what additional comments you may need? As we know it's very hard to reproduce this errors. Thanks
Yes it will be fixed. To answer the obvious next question: "When?" - when someone gets to it. There are current ~170 open bugs against TC5 and TC6. A patch will speed the process up but one that uses syncs is likely to get rejected.
The question is also: How we can fix it: Critical section at AccessLogValve is (LL 581 (current tomcat 5.5 trunk): result.append("["); result.append(dayFormatter.format(date)); // Day result.append('/'); result.append(lookup(monthFormatter.format(date))); // Month result.append('/'); result.append(yearFormatter.format(date)); // Year result.append(':'); result.append(timeFormatter.format(date)); // Time result.append(space); result.append(getTimeZone(date)); // Time Zone result.append("] \""); Not only the timeFormatter is the problem :-( Option to fix: a) synchronize the complete formatter access easy to implement, but can be a performance problem b) use a cache with some threadLocals can be a memory leak at shrinking request thread pools c) use some formatter object pools little implementation overhead and we must also use a sync datastructure! Peter
Since we are collecting ideas: - FastDateFormat from commons.lang - Joda Time (also seems to be ASL licensed) Both would add another foreign dependency but are thread safe in their formatters. I didn't look at their performance though. A concurrent microbenchmark could be adequate here. Peter: why do you expect a leak, if we put the SimpleDateFormat into a ThreadLocal? Do we have any indication, that when shrinking the pool, any references to the removed Threads remain?
In this case - syncs aren't really that evil. All the syncing is occuring during the logging phase. Which occurs after the request has been served to the client. So yes - there is a performance penalty for syncing but its not critical path which will slow the server down. With the exception that you had run out of workers - in which case you have bigger issues to deal with.
I don't see that theres a problem any more - the block that uses most (i.e. all except fileDateFormatter) of the SimpleDateFormats is now in a synchronized block: synchronized (this) { if (currentDate != date) { StringBuffer current = new StringBuffer(32); current.append('['); current.append(dayFormatter.format(date)); // Day current.append('/'); current.append(lookup(monthFormatter.format(date))); // Month current.append('/'); current.append(yearFormatter.format(date)); // Year current.append(':'); current.append(timeFormatter.format(date)); // Time current.append(' '); current.append(getTimeZone(date)); // Timezone current.append(']'); currentDateString = current.toString(); currentDate = date; } } ...and fileDateFormatter is used in the rotate() method which is also synchronized Looks to me like this was resolved in the following revision: http://svn.apache.org/viewvc?view=rev&revision=494191 But perhaps I'm looking at the wrong version - as code I see differs from what Peter quotes (StringBuffer is called current rather than result)
I would agree with the comment about using a thread safe data formatter. After all, there is no need for anything more than threadstack variables to format a date. FastDateFormat is right on. Note: since date formatters can't use StringBuilder, it is a good idea to get away from SimpleDateFormat and use whatever lib that can work on StringBuilder. You should probably file a RFE for FastDateFormat using StringBuilder too.
After reading all comments I agree with Tim that a simple sync fix the problem. The use of ThreadLocal or thread safe API add complexity and new dependencies. Vote +1 to add simple sync statements a 5.5 AccessLog valve code base
The fix was applied to trunk and 6.0.x but not 5.5.x. I have proposed a patch for 5.5.x
I think synchronize on "this" is not a good idea, since all synchronized method and those blocks which is synchronized on "this" in this class will wait for the lock. Separate those locks for different formatter will be much better. Or we can use some threadLocal field for those formatter. I think both of the options could fix this.
This has been fixed in 5.5.x (along with a handful of related issues) and will be included in 5.5.28 onwards.