Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FastDateFormat is not very fast #437

Closed
wsargent opened this issue Sep 28, 2020 · 2 comments
Closed

FastDateFormat is not very fast #437

wsargent opened this issue Sep 28, 2020 · 2 comments

Comments

@wsargent
Copy link
Contributor

I've been doing some profiling using the chronicle appender with JSON output. It looks like the FastDateFormat used by FormattedTimestampJsonProvider is creating a calendar with `newCalendar and formatting it every time, which creates unnecessary garbage and is a good chunk of the JSON formatting.

https://github.com/apache/commons-lang/blob/master/src/main/java/org/apache/commons/lang3/time/FastDatePrinter.java#L444

It might be good to use DateTimeFormatter.ISO_DATETIME_FORMAT directly and compare it.

logback-appender-CHRONICLE-2  Runnable CPU usage on sample: 236ms
  net.logstash.logback.encoder.org.apache.commons.lang3.time.FastDatePrinter.format(long) FastDatePrinter.java:446
  net.logstash.logback.encoder.org.apache.commons.lang3.time.FastDateFormat.format(long) FastDateFormat.java:428
  net.logstash.logback.composite.FormattedTimestampJsonProvider$PatternTimestampWriter.getTimestampAsString(long) FormattedTimestampJsonProvider.java:101
  net.logstash.logback.composite.FormattedTimestampJsonProvider$PatternTimestampWriter.writeTo(JsonGenerator, String, long) FormattedTimestampJsonProvider.java:96
  net.logstash.logback.composite.FormattedTimestampJsonProvider.writeTo(JsonGenerator, DeferredProcessingAware) FormattedTimestampJsonProvider.java:149
  net.logstash.logback.composite.JsonProviders.writeTo(JsonGenerator, DeferredProcessingAware) JsonProviders.java:77
  net.logstash.logback.composite.CompositeJsonFormatter.writeEventToGenerator(JsonGenerator, DeferredProcessingAware) CompositeJsonFormatter.java:193
  net.logstash.logback.composite.CompositeJsonFormatter.writeEventToOutputStream(DeferredProcessingAware, OutputStream) CompositeJsonFormatter.java:170
  net.logstash.logback.encoder.CompositeJsonEncoder.encode(DeferredProcessingAware) CompositeJsonEncoder.java:122
  net.logstash.logback.encoder.CompositeJsonEncoder.encode(Object) CompositeJsonEncoder.java:34
  net.openhft.chronicle.logger.logback.UnsynchronizedChronicleAppender.append(ILoggingEvent) UnsynchronizedChronicleAppender.java:34
  net.openhft.chronicle.logger.logback.UnsynchronizedChronicleAppender.append(Object) UnsynchronizedChronicleAppender.java:30
  ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(Object) UnsynchronizedAppenderBase.java:84
  ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(Object) AppenderAttachableImpl.java:51
  net.logstash.logback.appender.DelegatingAsyncDisruptorAppender$DelegatingEventHandler.onEvent(AsyncDisruptorAppender$LogEvent, long, boolean) DelegatingAsyncDisruptorAppender.java:55
  net.logstash.logback.appender.DelegatingAsyncDisruptorAppender$DelegatingEventHandler.onEvent(Object, long, boolean) DelegatingAsyncDisruptorAppender.java:51
  net.logstash.logback.appender.AsyncDisruptorAppender$EventClearingEventHandler.onEvent(AsyncDisruptorAppender$LogEvent, long, boolean) AsyncDisruptorAppender.java:339
  net.logstash.logback.appender.AsyncDisruptorAppender$EventClearingEventHandler.onEvent(Object, long, boolean) AsyncDisruptorAppender.java:327
  net.logstash.logback.encoder.com.lmax.disruptor.BatchEventProcessor.processEvents() BatchEventProcessor.java:168
  net.logstash.logback.encoder.com.lmax.disruptor.BatchEventProcessor.run() BatchEventProcessor.java:125
  java.util.concurrent.Executors$RunnableAdapter.call() Executors.java:515
  java.util.concurrent.FutureTask.run() FutureTask.java:264
  java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run() ScheduledThreadPoolExecutor.java:304
  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) ThreadPoolExecutor.java:1128
  java.util.concurrent.ThreadPoolExecutor$Worker.run() ThreadPoolExecutor.java:628
  java.lang.Thread.run() Thread.java:834
@philsttr
Copy link
Collaborator

Hey @wsargent ,

Luckily the switch to DateTimeFormatter is already implemented in #377, but not merged yet. It's not fully backwards compatible, so it will require a major version bump. I was holding off on merging it to see if there were any other major (non-backwards compatible) changes that needed to be made, that could be grouped with it. And I wasn't in a rush to merge it, because FastDateFormat has worked for a long time. If it is causing serious problems, I'll consider merging it and bumping the major version soon.

@wsargent
Copy link
Contributor Author

@philsttr I think there's a smaller workaround, which is to use a format(calendar, buf) and reuse the calendar instances. Not sure how much of an improvement that would be as I haven't benchmarked it.

https://github.com/apache/commons-lang/blob/master/src/main/java/org/apache/commons/lang3/time/FastDatePrinter.java#L537

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants