AccessLogValve.DateAndTimeElement() can currently be configured only with %t which output the date/time in Common Log Format. By adding the capability to configure with %{TIME_FORMAT}, one could override (at least) the timeFormatter property of the class ... or it could go further and allow overriding of all the [day, month, year, time]Formatter properties. Justification for enhancement: The log currenlty provide the ability to log processing time in millis (via %T), but an accurate log of the order in which requests are received cannot be determined without the capabilities of logging a a format with milliseconds using the %t element.
Created attachment 25778 [details] #49165 fix (added %t{TIME_FORMAT} support) Introduced new format for %t for AccesLogValve. - new format %{TIME_FORMAT}t available. - if custom pattern contains milliseconds field, then optimizations, which performs new current date time object creation only once per 1000 millis, will be turned off. - unit tests for added/changed functionality - performance tests Results of perfomance testing (tested on MacOS X 10.6.4): AccessLogValve: 5 threads and 1000000 iterations using oldValve took 8381ms AccessLogValve: 5 threads and 1000000 iterations using newValve took 7742ms AccessLogValve: 5 threads and 1000000 iterations using newValveWithMillis took 8651ms AccessLogValve: 5 threads and 2000000 iterations using oldValve took 16864ms AccessLogValve: 5 threads and 2000000 iterations using newValve took 15945ms AccessLogValve: 5 threads and 2000000 iterations using newValveWithMillis took 16806ms AccessLogValve: 5 threads and 3000000 iterations using oldValve took 25010ms AccessLogValve: 5 threads and 3000000 iterations using newValve took 24575ms AccessLogValve: 5 threads and 3000000 iterations using newValveWithMillis took 26674ms AccessLogValve: 5 threads and 4000000 iterations using oldValve took 33775ms AccessLogValve: 5 threads and 4000000 iterations using newValve took 33043ms AccessLogValve: 5 threads and 4000000 iterations using newValveWithMillis took 33796ms
Introduced new format for %t for AccesLogValve. - new format %{TIME_FORMAT}t available. - if custom pattern contains milliseconds field, then optimizations, which performs new current date time object creation only once per 1000 millis, will be turned off. - unit tests for added/changed functionality - performance tests Results of perfomance testing (tested on MacOS X 10.6.4): AccessLogValve: 5 threads and 1000000 iterations using oldValve took 8381ms AccessLogValve: 5 threads and 1000000 iterations using newValve took 7742ms AccessLogValve: 5 threads and 1000000 iterations using newValveWithMillis took 8651ms AccessLogValve: 5 threads and 2000000 iterations using oldValve took 16864ms AccessLogValve: 5 threads and 2000000 iterations using newValve took 15945ms AccessLogValve: 5 threads and 2000000 iterations using newValveWithMillis took 16806ms AccessLogValve: 5 threads and 3000000 iterations using oldValve took 25010ms AccessLogValve: 5 threads and 3000000 iterations using newValve took 24575ms AccessLogValve: 5 threads and 3000000 iterations using newValveWithMillis took 26674ms AccessLogValve: 5 threads and 4000000 iterations using oldValve took 33775ms AccessLogValve: 5 threads and 4000000 iterations using newValve took 33043ms AccessLogValve: 5 threads and 4000000 iterations using newValveWithMillis took 33796ms
Created attachment 25779 [details] 49615 + unit tests updated patch file (unit tests added to version control)
done
(In reply to comment #4) Thanks for the patch. I have reviewed it and have the following comments: 1. It uses a mix of tabs and spaces for indenting. Only spaces should be used. 2. Log messages should use the StringManager to provide i18n support. 3. Setting currentDate in the AccessDateStruct serves no purpose 4. Same for currentDateString 5. DateAndTimeElementVolumeTest can probably be added to the existing Benchmarks test. Out of curiosity, if you remove the code that manages the only creating the date once a second entirely and use a date format that does not include millis, what is the performance like? I'm wondering if we can just remove that code entirely. If you can update the patch, I'll take another look. With the issues above fixed it should be ready to apply.
(In reply to comment #5) > 1. It uses a mix of tabs and spaces for indenting. Only spaces should be used. Done. > 2. Log messages should use the StringManager to provide i18n support. Done (only English string was added). BTW there are others Strings in class used in exception. I haven't touched them, because they're not related to this bug. Please let me know if this should be done. > 3. Setting currentDate in the AccessDateStruct serves no purpose Removed initialization in variable declaration. Leaved as is in constructor: otherwise NPE will be thrown on first AccessDateStruct access in startInternal(). > 4. Same for currentDateString Removed > 5. DateAndTimeElementVolumeTest can probably be added to the existing > Benchmarks test. Done. > Out of curiosity, if you remove the code that manages the only creating the > date once a second entirely and use a date format that does not include millis, > what is the performance like? I'm wondering if we can just remove that code > entirely. Without millis chunks we have small performance drop on same %t pattern: 5 thr x 1000000 iter. newValve 7772ms 5 thr x 1000000 iter. newValveNoChunks 8483ms 5 thr x 1000000 iter. newValveWithMillis 8630ms 5 thr x 2000000 iter. newValve 14857ms 5 thr x 2000000 iter. newValveNoChunks 15633ms 5 thr x 2000000 iter. newValveWithMillis 19687ms 5 thr x 3000000 iter. newValve 22171ms 5 thr x 3000000 iter. newValveNoChunks 23433ms 5 thr x 3000000 iter. newValveWithMillis 26765ms 5 thr x 4000000 iter. newValve 29615ms 5 thr x 4000000 iter. newValveNoChunks 31525ms 5 thr x 4000000 iter. newValveWithMillis 35067ms 5 thr x 5000000 iter. newValve 36889ms 5 thr x 5000000 iter. newValveNoChunks 39176ms 5 thr x 5000000 iter. newValveWithMillis 43527ms Looks like performance graphs are linear for all cases. I think if we remove chunks, this could possible cause slight load increase on GC under heavy load (new Date instances will keep creating). Test was done under MacOS X 10.6. Please let me know your decision: are we going to go with this or leave it as is. BTW there will be error up to 1000 mills in output, because we're creating date once in 1000 millis. Note: volume benchmark is writing output in real file to $CATALINA_HOME/logs and shouldn't be included in automatic test pack (it's slow and it's it's generating REALLY big output file, so CI server will quickly run out of disk space). > If you can update the patch, I'll take another look. With the issues above > fixed it should be ready to apply. Will provide patch file after your decision.
Created attachment 25834 [details] #49165 fix with requested changes Please let me know if version without 1000 millis chunk is required (in this case some unit test should be removed).
(In reply to comment #6) > Note: volume benchmark is writing output in real file to $CATALINA_HOME/logs > and shouldn't be included in automatic test pack (it's slow and it's it's > generating REALLY big output file, so CI server will quickly run out of disk > space). Could you modify the volume benchmark to dump to /dev/null or some kind of null logger? That would give you a better benchmark since you aren't at the mercy of disk I/O to skew your results.
I added support for full SimpleDateFormat in r1137336. It also supports: - choosing the timestamp, either begin of request and finish of response By using multiple %{xxx}t tokens one can also log bot timestamps. - logging second, milliseconds since the epoch Documented in r1137338.