Bug 49165 - Enhancement - Allow %{TIME_FORMAT}t As Configuration for AccessLogValve
Summary: Enhancement - Allow %{TIME_FORMAT}t As Configuration for AccessLogValve
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Catalina (show other bugs)
Version: unspecified
Hardware: All All
: P2 enhancement (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-04-21 14:20 UTC by Jacob Zwiers
Modified: 2011-06-19 11:28 UTC (History)
0 users



Attachments
#49165 fix (added %t{TIME_FORMAT} support) (12.65 KB, patch)
2010-07-16 23:26 UTC, Alexander Shirkov
Details | Diff
49615 + unit tests (27.69 KB, application/octet-stream)
2010-07-16 23:51 UTC, Alexander Shirkov
Details
#49165 fix with requested changes (34.67 KB, application/octet-stream)
2010-08-03 18:44 UTC, Alexander Shirkov
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jacob Zwiers 2010-04-21 14:20:08 UTC
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.
Comment 1 Alexander Shirkov 2010-07-16 23:26:31 UTC
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
Comment 2 Alexander Shirkov 2010-07-16 23:27:44 UTC
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
Comment 3 Alexander Shirkov 2010-07-16 23:51:26 UTC
Created attachment 25779 [details]
49615 + unit tests

updated patch file (unit tests added to version control)
Comment 4 Alexander Shirkov 2010-07-19 13:22:19 UTC
done
Comment 5 Mark Thomas 2010-07-21 13:47:59 UTC
(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.
Comment 6 Alexander Shirkov 2010-07-22 22:38:38 UTC
(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.
Comment 7 Alexander Shirkov 2010-08-03 18:44:56 UTC
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).
Comment 8 Christopher Schultz 2010-12-14 14:58:37 UTC
(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.
Comment 9 Rainer Jung 2011-06-19 11:28:35 UTC
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.