From eefca5920cf33e4815cf2c949b3299bc6fd54082 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Thu, 31 Oct 2024 13:37:34 +0100 Subject: [PATCH] Rewrite date & time formatting (#3121) Co-authored-by: Piotr P. Karwasz --- .../log4j/core/layout/HtmlLayoutTest.java | 14 - .../pattern/DatePatternConverterTestBase.java | 200 ++--- .../instant/InstantNumberFormatterTest.java | 70 ++ .../InstantPatternDynamicFormatterTest.java | 424 +++++++++ ...PatternThreadLocalCachedFormatterTest.java | 292 ++++++ .../log4j-rolling-size-with-time.xml | 2 +- .../core/pattern/DatePatternConverter.java | 490 +++++------ .../log4j/core/util/datetime/DatePrinter.java | 2 + .../core/util/datetime/FastDateFormat.java | 2 + .../core/util/datetime/FastDatePrinter.java | 2 + .../core/util/datetime/FixedDateFormat.java | 7 +- .../log4j/core/util/datetime/Format.java | 3 + .../log4j/core/util/datetime/FormatCache.java | 2 + .../core/util/datetime/package-info.java | 10 +- .../internal/instant/InstantFormatter.java | 32 +- .../instant/InstantNumberFormatter.java | 128 +++ .../InstantPatternDynamicFormatter.java | 831 ++++++++++++++++++ .../instant/InstantPatternFormatter.java | 186 ++++ .../InstantPatternLegacyFormatter.java | 118 +++ ...tantPatternThreadLocalCachedFormatter.java | 134 +++ .../util/internal/instant/package-info.java | 37 + .../layout/template/json/LogEventFixture.java | 27 +- .../layout/template/json/GelfLayoutTest.java | 22 +- .../json/util/InstantFormatterTest.java | 114 --- .../json/resolver/TimestampResolver.java | 269 ++---- .../template/json/util/InstantFormatter.java | 3 + .../perf/jmh/DateTimeFormatBenchmark.java | 117 --- .../perf/jmh/InstantFormatBenchmark.java | 1 + .../log4j/perf/jmh/TimeFormatBenchmark.java | 299 ------- ...rnDynamicFormatterSequencingBenchmark.java | 96 ++ .../InstantPatternFormatterBenchmark.java | 215 +++++ ...nstantPatternFormatterImpactBenchmark.java | 187 ++++ src/changelog/.2.x.x/.release-notes.adoc.ftl | 7 + ...ate_AbstractLogger_checkMessageFactory.xml | 2 +- .../.2.x.x/3121_deprecate_FixedDateFormat.xml | 8 + src/changelog/.2.x.x/3121_instant_format.xml | 9 + src/changelog/.index.adoc.ftl | 2 +- .../fix_StatusLogger_instant_formatting.xml | 4 +- .../ROOT/pages/manual/pattern-layout.adoc | 37 +- .../properties-log4j-core-misc.adoc | 14 + 40 files changed, 3197 insertions(+), 1222 deletions(-) create mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatterTest.java create mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatterTest.java create mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java rename log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/package-info.java => log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantFormatter.java (53%) create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatter.java create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatter.java create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternFormatter.java create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternLegacyFormatter.java create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/package-info.java delete mode 100644 log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java delete mode 100644 log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java delete mode 100644 log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/TimeFormatBenchmark.java create mode 100644 log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternDynamicFormatterSequencingBenchmark.java create mode 100644 log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterBenchmark.java create mode 100644 log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterImpactBenchmark.java create mode 100644 src/changelog/.2.x.x/3121_deprecate_FixedDateFormat.xml create mode 100644 src/changelog/.2.x.x/3121_instant_format.xml diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/layout/HtmlLayoutTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/layout/HtmlLayoutTest.java index 6a85b012641..9a222e5145f 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/layout/HtmlLayoutTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/layout/HtmlLayoutTest.java @@ -43,7 +43,6 @@ import org.apache.logging.log4j.core.test.appender.ListAppender; import org.apache.logging.log4j.core.time.Instant; import org.apache.logging.log4j.core.time.MutableInstant; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.test.junit.UsingAnyThreadContext; @@ -285,19 +284,6 @@ private void testLayoutWithDatePatternFixedFormat(final FixedFormat format, fina format.getPattern().replace('n', 'S').replace('X', 'x'), locale); String expected = zonedDateTime.format(dateTimeFormatter); - final String offset = zonedDateTime.getOffset().toString(); - - // Truncate minutes if timeZone format is HH and timeZone has minutes. This is required because according to - // DateTimeFormatter, - // One letter outputs just the hour, such as '+01', unless the minute is non-zero in which case the minute is - // also output, such as '+0130' - // ref : https://docs.oracle.com/javase/8/docs/api/java/time/format/DateTimeFormatter.html - if (FixedDateFormat.FixedTimeZoneFormat.HH.equals(format.getFixedTimeZoneFormat()) - && offset.contains(":") - && !"00".equals(offset.split(":")[1])) { - expected = expected.substring(0, expected.length() - 2); - } - assertEquals( "" + expected + "", actual, diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTestBase.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTestBase.java index b9680290a01..cdd279c6910 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTestBase.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTestBase.java @@ -20,6 +20,9 @@ import static org.junit.jupiter.api.Assertions.assertNull; import java.text.SimpleDateFormat; +import java.time.ZoneId; +import java.time.format.DateTimeFormatter; +import java.time.temporal.TemporalAccessor; import java.util.Calendar; import java.util.Date; import java.util.TimeZone; @@ -28,8 +31,6 @@ import org.apache.logging.log4j.core.time.Instant; import org.apache.logging.log4j.core.time.MutableInstant; import org.apache.logging.log4j.core.util.Constants; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat.FixedTimeZoneFormat; import org.apache.logging.log4j.util.Strings; import org.junit.jupiter.api.Test; @@ -54,27 +55,13 @@ public long getTimeMillis() { } } - /** - * SimpleTimePattern for DEFAULT. - */ - private static final String DEFAULT_PATTERN = FixedDateFormat.FixedFormat.DEFAULT.getPattern(); + private static final String DEFAULT_PATTERN = "yyyy-MM-dd HH:mm:ss,SSS"; - /** - * ISO8601 string literal. - */ - private static final String ISO8601 = FixedDateFormat.FixedFormat.ISO8601.name(); + private static final String ISO8601 = "ISO8601"; - /** - * ISO8601_OFFSET_DATE_TIME_XX string literal. - */ - private static final String ISO8601_OFFSET_DATE_TIME_HHMM = - FixedDateFormat.FixedFormat.ISO8601_OFFSET_DATE_TIME_HHMM.name(); + private static final String ISO8601_OFFSET_DATE_TIME_HHMM = "ISO8601_OFFSET_DATE_TIME_HHMM"; - /** - * ISO8601_OFFSET_DATE_TIME_XXX string literal. - */ - private static final String ISO8601_OFFSET_DATE_TIME_HHCMM = - FixedDateFormat.FixedFormat.ISO8601_OFFSET_DATE_TIME_HHCMM.name(); + private static final String ISO8601_OFFSET_DATE_TIME_HHCMM = "ISO8601_OFFSET_DATE_TIME_HHCMM"; private static final String[] ISO8601_FORMAT_OPTIONS = {ISO8601}; @@ -91,14 +78,6 @@ private static Date date(final int year, final int month, final int date) { return cal.getTime(); } - private String precisePattern(final String pattern, final int precision) { - final String search = "SSS"; - final int foundIndex = pattern.indexOf(search); - final String seconds = pattern.substring(0, foundIndex); - final String remainder = pattern.substring(foundIndex + search.length()); - return seconds + "nnnnnnnnn".substring(0, precision) + remainder; - } - @Test void testThreadLocalsConstant() { assertEquals(threadLocalsEnabled, Constants.ENABLE_THREADLOCALS); @@ -109,6 +88,7 @@ public void testFormatDateStringBuilderDefaultPattern() { assertDatePattern(null, date(2001, 1, 1), "2001-02-01 14:15:16,123"); } + @SuppressWarnings("deprecation") @Test public void testFormatDateStringBuilderIso8601() { final DatePatternConverter converter = DatePatternConverter.newInstance(ISO8601_FORMAT_OPTIONS); @@ -121,19 +101,18 @@ public void testFormatDateStringBuilderIso8601() { @Test public void testFormatDateStringBuilderIso8601BasicWithPeriod() { - assertDatePattern( - FixedDateFormat.FixedFormat.ISO8601_BASIC_PERIOD.name(), date(2001, 1, 1), "20010201T141516.123"); + assertDatePattern("ISO8601_BASIC_PERIOD", date(2001, 1, 1), "20010201T141516.123"); } @Test public void testFormatDateStringBuilderIso8601WithPeriod() { - assertDatePattern( - FixedDateFormat.FixedFormat.ISO8601_PERIOD.name(), date(2001, 1, 1), "2001-02-01T14:15:16.123"); + assertDatePattern("ISO8601_PERIOD", date(2001, 1, 1), "2001-02-01T14:15:16.123"); } + @SuppressWarnings("deprecation") @Test public void testFormatDateStringBuilderIso8601WithPeriodMicroseconds() { - final String[] pattern = {FixedDateFormat.FixedFormat.ISO8601_PERIOD_MICROS.name(), "Z"}; + final String[] pattern = {"ISO8601_PERIOD_MICROS", "Z"}; final DatePatternConverter converter = DatePatternConverter.newInstance(pattern); final StringBuilder sb = new StringBuilder(); final MutableInstant instant = new MutableInstant(); @@ -180,11 +159,12 @@ public void testFormatAmericanPatterns() { assertDatePattern("US_MONTH_DAY_YEAR4_TIME", date, "11/03/2011 14:15:16.123"); assertDatePattern("US_MONTH_DAY_YEAR2_TIME", date, "11/03/11 14:15:16.123"); assertDatePattern("dd/MM/yyyy HH:mm:ss.SSS", date, "11/03/2011 14:15:16.123"); - assertDatePattern("dd/MM/yyyy HH:mm:ss.nnnnnn", date, "11/03/2011 14:15:16.123000"); + assertDatePattern("dd/MM/yyyy HH:mm:ss.SSSSSS", date, "11/03/2011 14:15:16.123000"); assertDatePattern("dd/MM/yy HH:mm:ss.SSS", date, "11/03/11 14:15:16.123"); - assertDatePattern("dd/MM/yy HH:mm:ss.nnnnnn", date, "11/03/11 14:15:16.123000"); + assertDatePattern("dd/MM/yy HH:mm:ss.SSSSSS", date, "11/03/11 14:15:16.123000"); } + @SuppressWarnings("deprecation") private static void assertDatePattern(final String format, final Date date, final String expected) { final DatePatternConverter converter = DatePatternConverter.newInstance(new String[] {format}); final StringBuilder sb = new StringBuilder(); @@ -219,9 +199,9 @@ public void testFormatLogEventStringBuilderIso8601TimezoneOffsetHHCMM() { final StringBuilder sb = new StringBuilder(); converter.format(event, sb); - final SimpleDateFormat sdf = new SimpleDateFormat(converter.getPattern()); - final String format = sdf.format(new Date(event.getTimeMillis())); - final String expected = format.endsWith("Z") ? format.substring(0, format.length() - 1) + "+00:00" : format; + final String expected = DateTimeFormatter.ofPattern(converter.getPattern()) + .withZone(ZoneId.systemDefault()) + .format((TemporalAccessor) event.getInstant()); assertEquals(expected, sb.toString()); } @@ -233,9 +213,9 @@ public void testFormatLogEventStringBuilderIso8601TimezoneOffsetHHMM() { final StringBuilder sb = new StringBuilder(); converter.format(event, sb); - final SimpleDateFormat sdf = new SimpleDateFormat(converter.getPattern()); - final String format = sdf.format(new Date(event.getTimeMillis())); - final String expected = format.endsWith("Z") ? format.substring(0, format.length() - 1) + "+0000" : format; + final String expected = DateTimeFormatter.ofPattern(converter.getPattern()) + .withZone(ZoneId.systemDefault()) + .format((TemporalAccessor) event.getInstant()); assertEquals(expected, sb.toString()); } @@ -311,7 +291,7 @@ public void testGetPatternReturnsDefaultForEmptyOptionsArray() { @Test public void testGetPatternReturnsDefaultForInvalidPattern() { - final String[] invalid = {"ABC I am not a valid date pattern"}; + final String[] invalid = {"A single `V` is not allow by `DateTimeFormatter` and should cause an exception"}; assertEquals(DEFAULT_PATTERN, DatePatternConverter.newInstance(invalid).getPattern()); } @@ -344,126 +324,52 @@ public void testGetPatternReturnsNullForUnixMillis() { assertNull(DatePatternConverter.newInstance(options).getPattern()); } - @Test - public void testInvalidLongPatternIgnoresExcessiveDigits() { - final StringBuilder preciseBuilder = new StringBuilder(); - final StringBuilder milliBuilder = new StringBuilder(); - final LogEvent event = new MyLogEvent(); - - for (final FixedDateFormat.FixedFormat format : FixedDateFormat.FixedFormat.values()) { - final String pattern = format.getPattern(); - final String search = "SSS"; - final int foundIndex = pattern.indexOf(search); - if (pattern.endsWith("n") || pattern.matches(".+n+X*") || pattern.matches(".+n+Z*")) { - // ignore patterns that already have precise time formats - // ignore patterns that do not use seconds. - continue; - } - preciseBuilder.setLength(0); - milliBuilder.setLength(0); - - final DatePatternConverter preciseConverter; - final String precisePattern; - if (foundIndex < 0) { - precisePattern = pattern; - } else { - final String subPattern = pattern.substring(0, foundIndex); - final String remainder = pattern.substring(foundIndex + search.length()); - precisePattern = subPattern + "nnnnnnnnn" + "n" + remainder; // nanos too long - } - preciseConverter = DatePatternConverter.newInstance(new String[] {precisePattern}); - preciseConverter.format(event, preciseBuilder); - - final String[] milliOptions = {pattern}; - DatePatternConverter.newInstance(milliOptions).format(event, milliBuilder); - final FixedTimeZoneFormat timeZoneFormat = format.getFixedTimeZoneFormat(); - final int truncateLen = 3 + (timeZoneFormat != null ? timeZoneFormat.getLength() : 0); - final String tz = timeZoneFormat != null - ? milliBuilder.substring(milliBuilder.length() - timeZoneFormat.getLength(), milliBuilder.length()) - : Strings.EMPTY; - milliBuilder.setLength(milliBuilder.length() - truncateLen); // truncate millis - if (foundIndex >= 0) { - milliBuilder.append("987123456"); - } - final String expected = milliBuilder.append(tz).toString(); - - assertEquals( - expected, - preciseBuilder.toString(), - "format = " + format + ", pattern = " + pattern + ", precisePattern = " + precisePattern); - // System.out.println(preciseOptions[0] + ": " + precise); - } - } - @Test public void testNewInstanceAllowsNullParameter() { DatePatternConverter.newInstance(null); // no errors } - // test with all formats from one 'n' (100s of millis) to 'nnnnnnnnn' (nanosecond precision) - @Test - public void testPredefinedFormatWithAnyValidNanoPrecision() { - final StringBuilder preciseBuilder = new StringBuilder(); - final StringBuilder milliBuilder = new StringBuilder(); - final LogEvent event = new MyLogEvent(); - - for (final String timeZone : new String[] {"PST", null}) { // Pacific Standard Time=UTC-8:00 - for (final FixedDateFormat.FixedFormat format : FixedDateFormat.FixedFormat.values()) { - for (int i = 1; i <= 9; i++) { - final String pattern = format.getPattern(); - if (pattern.endsWith("n") - || pattern.matches(".+n+X*") - || pattern.matches(".+n+Z*") - || !pattern.contains("SSS")) { - // ignore patterns that already have precise time formats - // ignore patterns that do not use seconds. - continue; - } - preciseBuilder.setLength(0); - milliBuilder.setLength(0); - - final String precisePattern = precisePattern(pattern, i); - final String[] preciseOptions = {precisePattern, timeZone}; - final DatePatternConverter preciseConverter = DatePatternConverter.newInstance(preciseOptions); - preciseConverter.format(event, preciseBuilder); - - final String[] milliOptions = {pattern, timeZone}; - DatePatternConverter.newInstance(milliOptions).format(event, milliBuilder); - final FixedTimeZoneFormat timeZoneFormat = format.getFixedTimeZoneFormat(); - final int truncateLen = 3 + (timeZoneFormat != null ? timeZoneFormat.getLength() : 0); - final String tz = timeZoneFormat != null - ? milliBuilder.substring( - milliBuilder.length() - timeZoneFormat.getLength(), milliBuilder.length()) - : Strings.EMPTY; - milliBuilder.setLength(milliBuilder.length() - truncateLen); // truncate millis - final String expected = - milliBuilder.append("987123456", 0, i).append(tz).toString(); - - assertEquals( - expected, - preciseBuilder.toString(), - "format = " + format + ", pattern = " + pattern + ", precisePattern = " + precisePattern); - // System.out.println(preciseOptions[0] + ": " + precise); - } - } - } - } + private static final String[] PATTERN_NAMES = { + "ABSOLUTE", + "ABSOLUTE_MICROS", + "ABSOLUTE_NANOS", + "ABSOLUTE_PERIOD", + "COMPACT", + "DATE", + "DATE_PERIOD", + "DEFAULT", + "DEFAULT_MICROS", + "DEFAULT_NANOS", + "DEFAULT_PERIOD", + "ISO8601_BASIC", + "ISO8601_BASIC_PERIOD", + "ISO8601", + "ISO8601_OFFSET_DATE_TIME_HH", + "ISO8601_OFFSET_DATE_TIME_HHMM", + "ISO8601_OFFSET_DATE_TIME_HHCMM", + "ISO8601_PERIOD", + "ISO8601_PERIOD_MICROS", + "US_MONTH_DAY_YEAR2_TIME", + "US_MONTH_DAY_YEAR4_TIME" + }; @Test public void testPredefinedFormatWithoutTimezone() { - for (final FixedDateFormat.FixedFormat format : FixedDateFormat.FixedFormat.values()) { - final String[] options = {format.name()}; + for (final String patternName : PATTERN_NAMES) { + final String[] options = {patternName}; final DatePatternConverter converter = DatePatternConverter.newInstance(options); - assertEquals(format.getPattern(), converter.getPattern()); + final String expectedPattern = DatePatternConverter.decodeNamedPattern(patternName); + assertEquals(expectedPattern, converter.getPattern()); } } @Test public void testPredefinedFormatWithTimezone() { - for (final FixedDateFormat.FixedFormat format : FixedDateFormat.FixedFormat.values()) { - final String[] options = {format.name(), "PST"}; // Pacific Standard Time=UTC-8:00 + for (final String patternName : PATTERN_NAMES) { + final String[] options = {patternName, "PST"}; // Pacific Standard Time=UTC-8:00 final DatePatternConverter converter = DatePatternConverter.newInstance(options); - assertEquals(format.getPattern(), converter.getPattern()); + final String expectedPattern = DatePatternConverter.decodeNamedPattern(patternName); + assertEquals(expectedPattern, converter.getPattern()); } } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatterTest.java new file mode 100644 index 00000000000..3521d4d4105 --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatterTest.java @@ -0,0 +1,70 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.Arrays; +import java.util.stream.Stream; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.MethodSource; + +class InstantNumberFormatterTest { + + @ParameterizedTest + @MethodSource("testCases") + void should_produce_expected_output( + final InstantFormatter formatter, final Instant instant, final String expectedOutput) { + final String actualOutput = formatter.format(instant); + assertThat(actualOutput).isEqualTo(expectedOutput); + } + + static Stream testCases() { + return Stream.concat( + testCases(1581082727, 982123456, new Object[][] { + {InstantNumberFormatter.EPOCH_SECONDS, "1581082727.982123456"}, + {InstantNumberFormatter.EPOCH_SECONDS_ROUNDED, "1581082727"}, + {InstantNumberFormatter.EPOCH_SECONDS_NANOS, "982123456"}, + {InstantNumberFormatter.EPOCH_MILLIS, "1581082727982.123456"}, + {InstantNumberFormatter.EPOCH_MILLIS_ROUNDED, "1581082727982"}, + {InstantNumberFormatter.EPOCH_MILLIS_NANOS, "123456"}, + {InstantNumberFormatter.EPOCH_NANOS, "1581082727982123456"} + }), + testCases(1591177590, 5000001, new Object[][] { + {InstantNumberFormatter.EPOCH_SECONDS, "1591177590.005000001"}, + {InstantNumberFormatter.EPOCH_SECONDS_ROUNDED, "1591177590"}, + {InstantNumberFormatter.EPOCH_SECONDS_NANOS, "5000001"}, + {InstantNumberFormatter.EPOCH_MILLIS, "1591177590005.000001"}, + {InstantNumberFormatter.EPOCH_MILLIS_ROUNDED, "1591177590005"}, + {InstantNumberFormatter.EPOCH_MILLIS_NANOS, "1"}, + {InstantNumberFormatter.EPOCH_NANOS, "1591177590005000001"} + })); + } + + private static Stream testCases( + long epochSeconds, int epochSecondsNanos, Object[][] formatterAndOutputPairs) { + return Arrays.stream(formatterAndOutputPairs).map(formatterAndOutputPair -> { + final InstantFormatter formatter = (InstantFormatter) formatterAndOutputPair[0]; + final String expectedOutput = (String) formatterAndOutputPair[1]; + final MutableInstant instant = new MutableInstant(); + instant.initFromEpochSecond(epochSeconds, epochSecondsNanos); + return new Object[] {formatter, instant, expectedOutput}; + }); + } +} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatterTest.java new file mode 100644 index 00000000000..ddb8c311039 --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatterTest.java @@ -0,0 +1,424 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static java.util.Arrays.asList; +import static java.util.Collections.singletonList; +import static org.apache.logging.log4j.core.util.internal.instant.InstantPatternDynamicFormatter.sequencePattern; +import static org.assertj.core.api.Assertions.assertThat; + +import java.time.format.DateTimeFormatter; +import java.time.temporal.ChronoUnit; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; +import java.util.Locale; +import java.util.Random; +import java.util.TimeZone; +import java.util.stream.IntStream; +import java.util.stream.Stream; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternDynamicFormatter.CompositePatternSequence; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternDynamicFormatter.DynamicPatternSequence; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternDynamicFormatter.PatternSequence; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternDynamicFormatter.StaticPatternSequence; +import org.apache.logging.log4j.util.Constants; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; +import org.junit.jupiter.params.provider.ValueSource; + +public class InstantPatternDynamicFormatterTest { + + @ParameterizedTest + @MethodSource("sequencingTestCases") + void sequencing_should_work( + final String pattern, final ChronoUnit thresholdPrecision, final List expectedSequences) { + final List actualSequences = sequencePattern(pattern, thresholdPrecision); + assertThat(actualSequences).isEqualTo(expectedSequences); + } + + static List sequencingTestCases() { + final List testCases = new ArrayList<>(); + + // `SSSX` should be treated constant for daily updates + testCases.add(Arguments.of("SSSX", ChronoUnit.DAYS, singletonList(pCom(pDyn("SSS"), pDyn("X"))))); + + // `yyyyMMddHHmmssSSSX` instant cache updated hourly + testCases.add(Arguments.of( + "yyyyMMddHHmmssSSSX", + ChronoUnit.HOURS, + asList( + pCom(pDyn("yyyy"), pDyn("MM"), pDyn("dd"), pDyn("HH")), + pCom(pDyn("mm"), pDyn("ss"), pDyn("SSS")), + pDyn("X")))); + + // `yyyyMMddHHmmssSSSX` instant cache updated per minute + testCases.add(Arguments.of( + "yyyyMMddHHmmssSSSX", + ChronoUnit.MINUTES, + asList( + pCom(pDyn("yyyy"), pDyn("MM"), pDyn("dd"), pDyn("HH"), pDyn("mm")), + pCom(pDyn("ss"), pDyn("SSS")), + pDyn("X")))); + + // ISO9601 instant cache updated daily + final String iso8601InstantPattern = "yyyy-MM-dd'T'HH:mm:ss.SSSX"; + testCases.add(Arguments.of( + iso8601InstantPattern, + ChronoUnit.DAYS, + asList( + pCom(pDyn("yyyy"), pSta("-"), pDyn("MM"), pSta("-"), pDyn("dd"), pSta("T")), + pCom( + pDyn("HH"), + pSta(":"), + pDyn("mm"), + pSta(":"), + pDyn("ss"), + pSta("."), + pDyn("SSS"), + pDyn("X"))))); + + // ISO9601 instant cache updated per minute + testCases.add(Arguments.of( + iso8601InstantPattern, + ChronoUnit.MINUTES, + asList( + pCom( + pDyn("yyyy"), + pSta("-"), + pDyn("MM"), + pSta("-"), + pDyn("dd"), + pSta("T"), + pDyn("HH"), + pSta(":"), + pDyn("mm"), + pSta(":")), + pCom(pDyn("ss"), pSta("."), pDyn("SSS")), + pDyn("X")))); + + // ISO9601 instant cache updated per second + testCases.add(Arguments.of( + iso8601InstantPattern, + ChronoUnit.SECONDS, + asList( + pCom( + pDyn("yyyy"), + pSta("-"), + pDyn("MM"), + pSta("-"), + pDyn("dd"), + pSta("T"), + pDyn("HH"), + pSta(":"), + pDyn("mm"), + pSta(":"), + pDyn("ss"), + pSta(".")), + pDyn("SSS"), + pDyn("X")))); + + return testCases; + } + + private static CompositePatternSequence pCom(final PatternSequence... sequences) { + return new CompositePatternSequence(asList(sequences)); + } + + private static DynamicPatternSequence pDyn(final String pattern) { + return new DynamicPatternSequence(pattern); + } + + private static StaticPatternSequence pSta(final String literal) { + return new StaticPatternSequence(literal); + } + + @ParameterizedTest + @ValueSource( + strings = { + // Basics + "S", + "SSSSSSS", + "SSSSSSSSS", + "n", + "nn", + "N", + "NN", + // Mixed with other stuff + "yyyy-MM-dd HH:mm:ss,SSSSSSS", + "yyyy-MM-dd HH:mm:ss,SSSSSSSS", + "yyyy-MM-dd HH:mm:ss,SSSSSSSSS", + "yyyy-MM-dd'T'HH:mm:ss.SSSSSSSSS", + "yyyy-MM-dd'T'HH:mm:ss.SXXX" + }) + void should_recognize_patterns_of_nano_precision(final String pattern) { + assertPatternPrecision(pattern, ChronoUnit.NANOS); + } + + @ParameterizedTest + @ValueSource( + strings = { + // Basics + "SSSS", + "SSSSS", + "SSSSSS", + // Mixed with other stuff + "yyyy-MM-dd HH:mm:ss,SSSS", + "yyyy-MM-dd HH:mm:ss,SSSSS", + "yyyy-MM-dd HH:mm:ss,SSSSSS", + "yyyy-MM-dd'T'HH:mm:ss.SSSSSS", + // Single-quoted text containing nanosecond directives + "yyyy-MM-dd'S'HH:mm:ss.SSSSSSXXX", + "yyyy-MM-dd'n'HH:mm:ss.SSSSSSXXX", + "yyyy-MM-dd'N'HH:mm:ss.SSSSSSXXX", + }) + void should_recognize_patterns_of_micro_precision(final String pattern) { + assertPatternPrecision(pattern, ChronoUnit.MICROS); + } + + @ParameterizedTest + @ValueSource( + strings = { + // Basics + "SS", + "SSS", + "A", + "AA", + // Mixed with other stuff + "yyyy-MM-dd HH:mm:ss,SS", + "yyyy-MM-dd HH:mm:ss,SSS", + "yyyy-MM-dd'T'HH:mm:ss.SSSXXX", + // Single-quoted text containing nanosecond directives + "yyyy-MM-dd'S'HH:mm:ss.SSSXXX", + "yyyy-MM-dd'n'HH:mm:ss.SSSXXX", + "yyyy-MM-dd'N'HH:mm:ss.SSSXXX", + }) + void should_recognize_patterns_of_milli_precision(final String pattern) { + assertPatternPrecision(pattern, ChronoUnit.MILLIS); + } + + @ParameterizedTest + @ValueSource( + strings = { + // Basics + "s", + "ss", + // Mixed with other stuff + "yyyy-MM-dd HH:mm:s", + "yyyy-MM-dd HH:mm:ss", + "yyyy-MM-dd'T'HH:mm:ss", + "HH:mm:s", + // Single-quoted text containing nanosecond and millisecond directives + "yyyy-MM-dd'S'HH:mm:ss", + "yyyy-MM-dd'n'HH:mm:ss", + "yyyy-MM-dd'N'HH:mm:ss", + "yyyy-MM-dd'A'HH:mm:ss" + }) + void should_recognize_patterns_of_second_precision(final String pattern) { + assertPatternPrecision(pattern, ChronoUnit.SECONDS); + } + + @ParameterizedTest + @ValueSource( + strings = { + // Basics + "m", + "mm", + // Mixed with other stuff + "yyyy-MM-dd HH:mm", + "yyyy-MM-dd'T'HH:mm", + "HH:mm", + // Single-quoted text containing nanosecond and millisecond directives + "yyyy-MM-dd'S'HH:mm", + "yyyy-MM-dd'n'HH:mm" + }) + void should_recognize_patterns_of_minute_precision(final String pattern) { + assertPatternPrecision(pattern, ChronoUnit.MINUTES); + } + + @ParameterizedTest + @MethodSource("hourPrecisionPatterns") + void should_recognize_patterns_of_hour_precision(final String pattern) { + assertPatternPrecision(pattern, ChronoUnit.HOURS); + } + + static List hourPrecisionPatterns() { + final List java8Patterns = new ArrayList<>(asList( + // Basics + "H", + "HH", + "a", + "h", + "K", + "k", + "H", + "Z", + "x", + "X", + "O", + "z", + "VV", + // Mixed with other stuff + "yyyy-MM-dd HH", + "yyyy-MM-dd'T'HH", + "yyyy-MM-dd HH x", + "yyyy-MM-dd'T'HH XX", + "ddHH", + // Single-quoted text containing nanosecond and millisecond directives + "yyyy-MM-dd'S'HH", + "yyyy-MM-dd'n'HH")); + if (Constants.JAVA_MAJOR_VERSION > 8) { + java8Patterns.add("B"); + java8Patterns.add("v"); + } + return java8Patterns; + } + + private static void assertPatternPrecision(final String pattern, final ChronoUnit expectedPrecision) { + final InstantPatternFormatter formatter = + new InstantPatternDynamicFormatter(pattern, Locale.getDefault(), TimeZone.getDefault()); + assertThat(formatter.getPrecision()).as("pattern=`%s`", pattern).isEqualTo(expectedPrecision); + } + + @ParameterizedTest + @MethodSource("formatterInputs") + void output_should_match_DateTimeFormatter( + final String pattern, final Locale locale, final TimeZone timeZone, final MutableInstant instant) { + final String log4jOutput = formatInstant(pattern, locale, timeZone, instant); + final String javaOutput = DateTimeFormatter.ofPattern(pattern, locale) + .withZone(timeZone.toZoneId()) + .format(instant); + assertThat(log4jOutput).isEqualTo(javaOutput); + } + + static Stream formatterInputs() { + return Stream.of( + // Complete list of `FixedDateFormat`-supported patterns in version `2.24.1` + "HH:mm:ss,SSS", + "HH:mm:ss,SSSSSS", + "HH:mm:ss,SSSSSSSSS", + "HH:mm:ss.SSS", + "yyyyMMddHHmmssSSS", + "dd MMM yyyy HH:mm:ss,SSS", + "dd MMM yyyy HH:mm:ss.SSS", + "yyyy-MM-dd HH:mm:ss,SSS", + "yyyy-MM-dd HH:mm:ss,SSSSSS", + "yyyy-MM-dd HH:mm:ss,SSSSSSSSS", + "yyyy-MM-dd HH:mm:ss.SSS", + "yyyyMMdd'T'HHmmss,SSS", + "yyyyMMdd'T'HHmmss.SSS", + "yyyy-MM-dd'T'HH:mm:ss,SSS", + "yyyy-MM-dd'T'HH:mm:ss,SSSx", + "yyyy-MM-dd'T'HH:mm:ss,SSSxx", + "yyyy-MM-dd'T'HH:mm:ss,SSSxxx", + "yyyy-MM-dd'T'HH:mm:ss.SSS", + "yyyy-MM-dd'T'HH:mm:ss.SSSSSS", + "dd/MM/yy HH:mm:ss.SSS", + "dd/MM/yyyy HH:mm:ss.SSS") + .flatMap(InstantPatternDynamicFormatterTest::formatterInputs); + } + + private static final Random RANDOM = new Random(0); + + private static final Locale[] LOCALES = Locale.getAvailableLocales(); + + private static final TimeZone[] TIME_ZONES = + Arrays.stream(TimeZone.getAvailableIDs()).map(TimeZone::getTimeZone).toArray(TimeZone[]::new); + + static Stream formatterInputs(final String pattern) { + return IntStream.range(0, 500).mapToObj(ignoredIndex -> { + final Locale locale = LOCALES[RANDOM.nextInt(LOCALES.length)]; + final TimeZone timeZone = TIME_ZONES[RANDOM.nextInt(TIME_ZONES.length)]; + final MutableInstant instant = randomInstant(); + return Arguments.of(pattern, locale, timeZone, instant); + }); + } + + private static MutableInstant randomInstant() { + final MutableInstant instant = new MutableInstant(); + final long epochSecond = RANDOM.nextInt(1_621_280_470); // 2021-05-17 21:41:10 + final int epochSecondNano = randomNanos(); + instant.initFromEpochSecond(epochSecond, epochSecondNano); + return instant; + } + + private static int randomNanos() { + int total = 0; + for (int digitIndex = 0; digitIndex < 9; digitIndex++) { + int number; + do { + number = RANDOM.nextInt(10); + } while (digitIndex == 0 && number == 0); + total = total * 10 + number; + } + return total; + } + + private static String formatInstant( + final String pattern, final Locale locale, final TimeZone timeZone, final MutableInstant instant) { + final InstantPatternFormatter formatter = new InstantPatternDynamicFormatter(pattern, locale, timeZone); + final StringBuilder buffer = new StringBuilder(); + formatter.formatTo(buffer, instant); + return buffer.toString(); + } + + @ParameterizedTest + @MethodSource("formatterInputs") + void verify_manually_computed_sub_minute_precision_values( + final String ignoredPattern, + final Locale ignoredLocale, + final TimeZone timeZone, + final MutableInstant instant) { + final DateTimeFormatter formatter = DateTimeFormatter.ofPattern( + "HH:mm:ss.S-SS-SSS-SSSS-SSSSS-SSSSSS-SSSSSSS-SSSSSSSS-SSSSSSSSS|n") + .withZone(timeZone.toZoneId()); + final String formatterOutput = formatter.format(instant); + final int offsetMillis = timeZone.getOffset(instant.getEpochMillisecond()); + final long adjustedEpochSeconds = (instant.getEpochMillisecond() + offsetMillis) / 1000; + // 86400 seconds per day, 3600 seconds per hour + final int local_H = (int) ((adjustedEpochSeconds % 86400L) / 3600L); + final int local_m = (int) ((adjustedEpochSeconds / 60) % 60); + final int local_s = (int) (adjustedEpochSeconds % 60); + final int local_S = instant.getNanoOfSecond() / 100000000; + final int local_SS = instant.getNanoOfSecond() / 10000000; + final int local_SSS = instant.getNanoOfSecond() / 1000000; + final int local_SSSS = instant.getNanoOfSecond() / 100000; + final int local_SSSSS = instant.getNanoOfSecond() / 10000; + final int local_SSSSSS = instant.getNanoOfSecond() / 1000; + final int local_SSSSSSS = instant.getNanoOfSecond() / 100; + final int local_SSSSSSSS = instant.getNanoOfSecond() / 10; + final int local_SSSSSSSSS = instant.getNanoOfSecond(); + final int local_n = instant.getNanoOfSecond(); + final String output = String.format( + "%02d:%02d:%02d.%d-%d-%d-%d-%d-%d-%d-%d-%d|%d", + local_H, + local_m, + local_s, + local_S, + local_SS, + local_SSS, + local_SSSS, + local_SSSSS, + local_SSSSSS, + local_SSSSSSS, + local_SSSSSSSS, + local_SSSSSSSSS, + local_n); + assertThat(output).isEqualTo(formatterOutput); + } +} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java new file mode 100644 index 00000000000..b25fb85d741 --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java @@ -0,0 +1,292 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doAnswer; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.verifyNoMoreInteractions; +import static org.mockito.Mockito.when; + +import java.time.temporal.ChronoUnit; +import java.util.Locale; +import java.util.Random; +import java.util.TimeZone; +import java.util.function.Function; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.MethodSource; +import org.junit.jupiter.params.provider.ValueSource; + +class InstantPatternThreadLocalCachedFormatterTest { + + private static final Locale LOCALE = Locale.getDefault(); + + private static final TimeZone TIME_ZONE = TimeZone.getDefault(); + + @ParameterizedTest + @MethodSource("getterTestCases") + void getters_should_work( + final Function cachedFormatterSupplier, + final String pattern, + final Locale locale, + final TimeZone timeZone) { + final InstantPatternDynamicFormatter dynamicFormatter = + new InstantPatternDynamicFormatter(pattern, locale, timeZone); + final InstantPatternThreadLocalCachedFormatter cachedFormatter = + cachedFormatterSupplier.apply(dynamicFormatter); + assertThat(cachedFormatter.getPattern()).isEqualTo(pattern); + assertThat(cachedFormatter.getLocale()).isEqualTo(locale); + assertThat(cachedFormatter.getTimeZone()).isEqualTo(timeZone); + } + + static Object[][] getterTestCases() { + + // Choosing two different locale & time zone pairs to ensure having one that doesn't match the system default + final Locale locale1 = Locale.forLanguageTag("nl_NL"); + final Locale locale2 = Locale.forLanguageTag("tr_TR"); + final String[] timeZoneIds = TimeZone.getAvailableIDs(); + final int timeZone1IdIndex = new Random(0).nextInt(timeZoneIds.length); + final int timeZone2IdIndex = (timeZone1IdIndex + 1) % timeZoneIds.length; + final TimeZone timeZone1 = TimeZone.getTimeZone(timeZoneIds[timeZone1IdIndex]); + final TimeZone timeZone2 = TimeZone.getTimeZone(timeZoneIds[timeZone2IdIndex]); + + // Create test cases + return new Object[][] { + // For `ofMilliPrecision()` + { + (Function) + InstantPatternThreadLocalCachedFormatter::ofMilliPrecision, + "HH:mm.SSS", + locale1, + timeZone1 + }, + { + (Function) + InstantPatternThreadLocalCachedFormatter::ofMilliPrecision, + "HH:mm.SSS", + locale2, + timeZone2 + }, + // For `ofSecondPrecision()` + { + (Function) + InstantPatternThreadLocalCachedFormatter::ofSecondPrecision, + "yyyy", + locale1, + timeZone1 + }, + { + (Function) + InstantPatternThreadLocalCachedFormatter::ofSecondPrecision, + "yyyy", + locale2, + timeZone2 + } + }; + } + + @ParameterizedTest + @ValueSource(strings = {"S", "SSSS", "SSSSS", "SSSSSS", "SSSSSSS", "SSSSSSSS", "SSSSSSSSS", "n", "N"}) + void ofMilliPrecision_should_fail_on_inconsistent_precision(final String subMilliPattern) { + final InstantPatternDynamicFormatter dynamicFormatter = + new InstantPatternDynamicFormatter(subMilliPattern, LOCALE, TIME_ZONE); + assertThatThrownBy(() -> InstantPatternThreadLocalCachedFormatter.ofMilliPrecision(dynamicFormatter)) + .isInstanceOf(IllegalArgumentException.class) + .hasMessage( + "instant formatter `%s` is of `%s` precision, whereas the requested cache precision is `%s`", + dynamicFormatter, dynamicFormatter.getPrecision(), ChronoUnit.MILLIS); + } + + @ParameterizedTest + @ValueSource(strings = {"SSS", "s", "ss", "m", "mm", "H", "HH"}) + void ofMilliPrecision_should_truncate_precision_to_milli(final String superMilliPattern) { + final InstantPatternDynamicFormatter dynamicFormatter = + new InstantPatternDynamicFormatter(superMilliPattern, LOCALE, TIME_ZONE); + final InstantPatternThreadLocalCachedFormatter cachedFormatter = + InstantPatternThreadLocalCachedFormatter.ofMilliPrecision(dynamicFormatter); + assertThat(cachedFormatter.getPrecision()).isEqualTo(ChronoUnit.MILLIS); + assertThat(cachedFormatter.getPrecision().compareTo(dynamicFormatter.getPrecision())) + .isLessThanOrEqualTo(0); + } + + @ParameterizedTest + @ValueSource( + strings = {"S", "SS", "SSS", "SSSS", "SSSSS", "SSSSSS", "SSSSSSS", "SSSSSSSS", "SSSSSSSSS", "n", "N", "A"}) + void ofSecondPrecision_should_fail_on_inconsistent_precision(final String subSecondPattern) { + final InstantPatternDynamicFormatter dynamicFormatter = + new InstantPatternDynamicFormatter(subSecondPattern, LOCALE, TIME_ZONE); + assertThatThrownBy(() -> InstantPatternThreadLocalCachedFormatter.ofSecondPrecision(dynamicFormatter)) + .isInstanceOf(IllegalArgumentException.class) + .hasMessage( + "instant formatter `%s` is of `%s` precision, whereas the requested cache precision is `%s`", + dynamicFormatter, dynamicFormatter.getPrecision(), ChronoUnit.SECONDS); + } + + @ParameterizedTest + @ValueSource(strings = {"s", "ss", "m", "mm", "H", "HH"}) + void ofSecondPrecision_should_truncate_precision_to_second(final String superSecondPattern) { + final InstantPatternDynamicFormatter dynamicFormatter = + new InstantPatternDynamicFormatter(superSecondPattern, LOCALE, TIME_ZONE); + final InstantPatternThreadLocalCachedFormatter cachedFormatter = + InstantPatternThreadLocalCachedFormatter.ofSecondPrecision(dynamicFormatter); + assertThat(cachedFormatter.getPrecision()).isEqualTo(ChronoUnit.SECONDS); + assertThat(cachedFormatter.getPrecision().compareTo(dynamicFormatter.getPrecision())) + .isLessThanOrEqualTo(0); + } + + private static final MutableInstant INSTANT0 = createInstant(0, 0); + + @Test + void ofMilliPrecision_should_cache() { + + // Mock a pattern formatter + final InstantPatternFormatter patternFormatter = mock(InstantPatternFormatter.class); + when(patternFormatter.getPrecision()).thenReturn(ChronoUnit.MILLIS); + + // Configure the pattern formatter for the 1st instant + final Instant instant1 = INSTANT0; + final String output1 = "instant1"; + doAnswer(invocation -> { + final StringBuilder buffer = invocation.getArgument(0); + buffer.append(output1); + return null; + }) + .when(patternFormatter) + .formatTo(any(StringBuilder.class), eq(instant1)); + + // Create a 2nd distinct instant that shares the same milliseconds with the 1st instant. + // That is, the 2nd instant should trigger a cache hit. + final MutableInstant instant2 = offsetInstant(instant1, 0, 1); + assertThat(instant1.getEpochMillisecond()).isEqualTo(instant2.getEpochMillisecond()); + assertThat(instant1).isNotEqualTo(instant2); + + // Configure the pattern for a 3rd distinct instant. + // The 3rd instant should be of different milliseconds with the 1st (and 2nd) instants to trigger a cache miss. + final MutableInstant instant3 = offsetInstant(instant2, 1, 0); + assertThat(instant2.getEpochMillisecond()).isNotEqualTo(instant3.getEpochMillisecond()); + final String output3 = "instant3"; + doAnswer(invocation -> { + final StringBuilder buffer = invocation.getArgument(0); + buffer.append(output3); + return null; + }) + .when(patternFormatter) + .formatTo(any(StringBuilder.class), eq(instant3)); + + // Create a 4th distinct instant that shares the same milliseconds with the 3rd instant. + // That is, the 4th instant should trigger a cache hit. + final MutableInstant instant4 = offsetInstant(instant3, 0, 1); + assertThat(instant3.getEpochMillisecond()).isEqualTo(instant4.getEpochMillisecond()); + assertThat(instant3).isNotEqualTo(instant4); + + // Create the cached formatter and verify its output + final InstantFormatter cachedFormatter = + InstantPatternThreadLocalCachedFormatter.ofMilliPrecision(patternFormatter); + assertThat(cachedFormatter.format(instant1)).isEqualTo(output1); // Cache miss + assertThat(cachedFormatter.format(instant2)).isEqualTo(output1); // Cache hit + assertThat(cachedFormatter.format(instant2)).isEqualTo(output1); // Repeated cache hit + assertThat(cachedFormatter.format(instant3)).isEqualTo(output3); // Cache miss + assertThat(cachedFormatter.format(instant4)).isEqualTo(output3); // Cache hit + assertThat(cachedFormatter.format(instant4)).isEqualTo(output3); // Repeated cache hit + + // Verify the pattern formatter interaction + verify(patternFormatter).getPrecision(); + verify(patternFormatter).formatTo(any(StringBuilder.class), eq(instant1)); + verify(patternFormatter).formatTo(any(StringBuilder.class), eq(instant3)); + verifyNoMoreInteractions(patternFormatter); + } + + @Test + void ofSecondPrecision_should_cache() { + + // Mock a pattern formatter + final InstantPatternFormatter patternFormatter = mock(InstantPatternFormatter.class); + when(patternFormatter.getPrecision()).thenReturn(ChronoUnit.SECONDS); + + // Configure the pattern formatter for the 1st instant + final Instant instant1 = INSTANT0; + final String output1 = "instant1"; + doAnswer(invocation -> { + final StringBuilder buffer = invocation.getArgument(0); + buffer.append(output1); + return null; + }) + .when(patternFormatter) + .formatTo(any(StringBuilder.class), eq(instant1)); + + // Create a 2nd distinct instant that shares the same seconds with the 1st instant. + // That is, the 2nd instant should trigger a cache hit. + final MutableInstant instant2 = offsetInstant(instant1, 1, 0); + assertThat(instant1.getEpochSecond()).isEqualTo(instant2.getEpochSecond()); + assertThat(instant1).isNotEqualTo(instant2); + + // Configure the pattern for a 3rd distinct instant. + // The 3rd instant should be of different seconds with the 1st (and 2nd) instants to trigger a cache miss. + final MutableInstant instant3 = offsetInstant(instant2, 1_000, 0); + assertThat(instant2.getEpochSecond()).isNotEqualTo(instant3.getEpochSecond()); + final String output3 = "instant3"; + doAnswer(invocation -> { + final StringBuilder buffer = invocation.getArgument(0); + buffer.append(output3); + return null; + }) + .when(patternFormatter) + .formatTo(any(StringBuilder.class), eq(instant3)); + + // Create a 4th distinct instant that shares the same seconds with the 3rd instant. + // That is, the 4th instant should trigger a cache hit. + final MutableInstant instant4 = offsetInstant(instant3, 1, 0); + assertThat(instant3.getEpochSecond()).isEqualTo(instant4.getEpochSecond()); + assertThat(instant3).isNotEqualTo(instant4); + + // Create the cached formatter and verify its output + final InstantFormatter cachedFormatter = + InstantPatternThreadLocalCachedFormatter.ofSecondPrecision(patternFormatter); + assertThat(cachedFormatter.format(instant1)).isEqualTo(output1); // Cache miss + assertThat(cachedFormatter.format(instant2)).isEqualTo(output1); // Cache hit + assertThat(cachedFormatter.format(instant2)).isEqualTo(output1); // Repeated cache hit + assertThat(cachedFormatter.format(instant3)).isEqualTo(output3); // Cache miss + assertThat(cachedFormatter.format(instant4)).isEqualTo(output3); // Cache hit + assertThat(cachedFormatter.format(instant4)).isEqualTo(output3); // Repeated cache hit + + // Verify the pattern formatter interaction + verify(patternFormatter).getPrecision(); + verify(patternFormatter).formatTo(any(StringBuilder.class), eq(instant1)); + verify(patternFormatter).formatTo(any(StringBuilder.class), eq(instant3)); + verifyNoMoreInteractions(patternFormatter); + } + + private static MutableInstant offsetInstant( + final Instant instant, final long epochMillisOffset, final int epochMillisNanosOffset) { + final long epochMillis = Math.addExact(instant.getEpochMillisecond(), epochMillisOffset); + final int epochMillisNanos = Math.addExact(instant.getNanoOfMillisecond(), epochMillisNanosOffset); + return createInstant(epochMillis, epochMillisNanos); + } + + private static MutableInstant createInstant(final long epochMillis, final int epochMillisNanos) { + final MutableInstant instant = new MutableInstant(); + instant.initFromEpochMilli(epochMillis, epochMillisNanos); + return instant; + } +} diff --git a/log4j-core-test/src/test/resources/log4j-rolling-size-with-time.xml b/log4j-core-test/src/test/resources/log4j-rolling-size-with-time.xml index 25083065536..c6a411c8732 100644 --- a/log4j-core-test/src/test/resources/log4j-rolling-size-with-time.xml +++ b/log4j-core-test/src/test/resources/log4j-rolling-size-with-time.xml @@ -23,7 +23,7 @@ + filePattern="target/rolling-size-test/rollingtest-%d{yyyy-MM-dd'T'HH-mm-ss-SSS}.log"> %m%n diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java index 05157f812a3..f26a6d54c56 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java @@ -16,200 +16,213 @@ */ package org.apache.logging.log4j.core.pattern; +import static java.util.Objects.requireNonNull; + +import java.time.format.DateTimeFormatter; import java.util.Arrays; import java.util.Date; import java.util.Locale; -import java.util.Objects; import java.util.TimeZone; -import java.util.concurrent.atomic.AtomicReference; +import java.util.stream.Collectors; +import org.apache.commons.lang3.time.FastDateFormat; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.config.plugins.Plugin; import org.apache.logging.log4j.core.time.Instant; import org.apache.logging.log4j.core.time.MutableInstant; -import org.apache.logging.log4j.core.util.Constants; -import org.apache.logging.log4j.core.util.datetime.FastDateFormat; import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat.FixedFormat; +import org.apache.logging.log4j.core.util.internal.instant.InstantFormatter; +import org.apache.logging.log4j.core.util.internal.instant.InstantNumberFormatter; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternFormatter; import org.apache.logging.log4j.util.PerformanceSensitive; +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; /** * Converts and formats the event's date in a StringBuilder. */ +@SuppressWarnings("deprecation") @Plugin(name = "DatePatternConverter", category = PatternConverter.CATEGORY) @ConverterKeys({"d", "date"}) @PerformanceSensitive("allocation") +@NullMarked public final class DatePatternConverter extends LogEventPatternConverter implements ArrayPatternConverter { - private abstract static class Formatter { - long previousTime; // for ThreadLocal caching mode - int nanos; - - abstract String format(final Instant instant); + private static final String CLASS_NAME = DatePatternConverter.class.getSimpleName(); - abstract void formatToBuffer(final Instant instant, StringBuilder destination); + private static final String DEFAULT_PATTERN = "yyyy-MM-dd HH:mm:ss,SSS"; - public String toPattern() { - return null; - } + private final InstantFormatter formatter; - public TimeZone getTimeZone() { - return TimeZone.getDefault(); - } + private DatePatternConverter(@Nullable final String[] options) { + super("Date", "date"); + this.formatter = createFormatter(options); } - private static final class PatternFormatter extends Formatter { - private final FastDateFormat fastDateFormat; - - // this field is only used in ThreadLocal caching mode - private final StringBuilder cachedBuffer = new StringBuilder(64); - - PatternFormatter(final FastDateFormat fastDateFormat) { - this.fastDateFormat = fastDateFormat; - } - - @Override - String format(final Instant instant) { - return fastDateFormat.format(instant.getEpochMillisecond()); - } - - @Override - void formatToBuffer(final Instant instant, final StringBuilder destination) { - final long timeMillis = instant.getEpochMillisecond(); - if (previousTime != timeMillis) { - cachedBuffer.setLength(0); - fastDateFormat.format(timeMillis, cachedBuffer); - } - destination.append(cachedBuffer); - } - - @Override - public String toPattern() { - return fastDateFormat.getPattern(); - } - - @Override - public TimeZone getTimeZone() { - return fastDateFormat.getTimeZone(); + private static InstantFormatter createFormatter(@Nullable final String[] options) { + try { + return createFormatterUnsafely(options); + } catch (final Exception error) { + logOptionReadFailure(options, error, "failed for options: {}, falling back to the default instance"); } + return InstantPatternFormatter.newBuilder().setPattern(DEFAULT_PATTERN).build(); } - private static final class FixedFormatter extends Formatter { - private final FixedDateFormat fixedDateFormat; + private static InstantFormatter createFormatterUnsafely(@Nullable final String[] options) { - // below fields are only used in ThreadLocal caching mode - private final char[] cachedBuffer = new char[70]; // max length of formatted date-time in any format < 70 - private int length = 0; + // Read options + final String pattern = readPattern(options); + final TimeZone timeZone = readTimeZone(options); + final Locale locale = readLocale(options); - FixedFormatter(final FixedDateFormat fixedDateFormat) { - this.fixedDateFormat = fixedDateFormat; + // Is it epoch seconds? + if ("UNIX".equals(pattern)) { + return InstantNumberFormatter.EPOCH_SECONDS_ROUNDED; } - @Override - String format(final Instant instant) { - return fixedDateFormat.formatInstant(instant); + // Is it epoch milliseconds? + if ("UNIX_MILLIS".equals(pattern)) { + return InstantNumberFormatter.EPOCH_MILLIS_ROUNDED; } - @Override - void formatToBuffer(final Instant instant, final StringBuilder destination) { - final long epochSecond = instant.getEpochSecond(); - final int nanoOfSecond = instant.getNanoOfSecond(); - if (!fixedDateFormat.isEquivalent(previousTime, nanos, epochSecond, nanoOfSecond)) { - length = fixedDateFormat.formatInstant(instant, cachedBuffer, 0); - previousTime = epochSecond; - nanos = nanoOfSecond; - } - destination.append(cachedBuffer, 0, length); - } - - @Override - public String toPattern() { - return fixedDateFormat.getFormat(); - } - - @Override - public TimeZone getTimeZone() { - return fixedDateFormat.getTimeZone(); - } + return InstantPatternFormatter.newBuilder() + .setPattern(pattern) + .setTimeZone(timeZone) + .setLocale(locale) + .build(); } - private static final class UnixFormatter extends Formatter { - - @Override - String format(final Instant instant) { - return Long.toString(instant.getEpochSecond()); - } - - @Override - void formatToBuffer(final Instant instant, final StringBuilder destination) { - destination.append(instant.getEpochSecond()); // no need for caching - } + private static String readPattern(@Nullable final String[] options) { + return options != null && options.length > 0 && options[0] != null + ? decodeNamedPattern(options[0]) + : DEFAULT_PATTERN; } - private static final class UnixMillisFormatter extends Formatter { - - @Override - String format(final Instant instant) { - return Long.toString(instant.getEpochMillisecond()); - } - - @Override - void formatToBuffer(final Instant instant, final StringBuilder destination) { - destination.append(instant.getEpochMillisecond()); // no need for caching + /** + * Decodes {@link FixedDateFormat} named patterns into their corresponding {@link DateTimeFormatter} representations. + *

+ * In version {@code 2.25.0}, {@link FixedDateFormat} and {@link FastDateFormat} are deprecated in favor of {@link InstantPatternFormatter}. + * We introduced this method to keep backward compatibility with the named patterns provided by {@link FixedDateFormat}. + *

+ * + * @param pattern a user provided date & time formatting pattern + * @return the transformed formatting pattern where {@link FixedDateFormat} named patterns are replaced with their corresponding {@link DateTimeFormatter} representations + * @since 2.25.0 + */ + static String decodeNamedPattern(final String pattern) { + + // If legacy formatters are enabled, we need to produce output aimed for `FixedDateFormat` and `FastDateFormat`. + // Otherwise, we need to produce output aimed for `DateTimeFormatter`. + // In conclusion, we need to check if legacy formatters enabled and apply following transformations. + // + // | Microseconds | Nanoseconds | Time-zone + // ------------------------------+--------------+-------------+----------- + // Legacy formatter directive | nnnnnn | nnnnnnnnn | X, XX, XXX + // `DateTimeFormatter` directive | SSSSSS | SSSSSSSSS | x, xx, xxx + // + // Enabling legacy formatters mean that user requests the pattern to be formatted using deprecated + // `FixedDateFormat` and `FastDateFormat`. + // These two have, let's not say _bogus_, but an _interesting_ way of handling certain pattern directives: + // + // - They say they adhere to `SimpleDateFormat` specification, but use `n` directive. + // `n` is neither defined by `SimpleDateFormat`, nor `SimpleDateFormat` supports sub-millisecond precisions. + // `n` is probably manually introduced by Log4j to support sub-millisecond precisions. + // + // - `n` denotes nano-of-second for `DateTimeFormatter`. + // In Java 17, `n` and `N` (nano-of-day) always output nanosecond precision. + // This is independent of how many times they occur consequently. + // Yet legacy formatters use repeated `n` to denote sub-milliseconds precision of certain length. + // This doesn't work for `DateTimeFormatter`, which needs + // + // - `SSSSSS` for 6-digit microsecond precision + // - `SSSSSSSSS` for 9-digit nanosecond precision + // + // - Legacy formatters use `X`, `XX,` and `XXX` to choose between `+00`, `+0000`, or `+00:00`. + // This is the correct behaviour for `SimpleDateFormat`. + // Though `X` in `DateTimeFormatter` produces `Z` for zero-offset. + // To avoid the `Z` output, one needs to use `x` with `DateTimeFormatter`. + final boolean compat = InstantPatternFormatter.LEGACY_FORMATTERS_ENABLED; + + switch (pattern) { + case "ABSOLUTE": + return "HH:mm:ss,SSS"; + case "ABSOLUTE_MICROS": + return "HH:mm:ss," + (compat ? "nnnnnn" : "SSSSSS"); + case "ABSOLUTE_NANOS": + return "HH:mm:ss," + (compat ? "nnnnnnnnn" : "SSSSSSSSS"); + case "ABSOLUTE_PERIOD": + return "HH:mm:ss.SSS"; + case "COMPACT": + return "yyyyMMddHHmmssSSS"; + case "DATE": + return "dd MMM yyyy HH:mm:ss,SSS"; + case "DATE_PERIOD": + return "dd MMM yyyy HH:mm:ss.SSS"; + case "DEFAULT": + return "yyyy-MM-dd HH:mm:ss,SSS"; + case "DEFAULT_MICROS": + return "yyyy-MM-dd HH:mm:ss," + (compat ? "nnnnnn" : "SSSSSS"); + case "DEFAULT_NANOS": + return "yyyy-MM-dd HH:mm:ss," + (compat ? "nnnnnnnnn" : "SSSSSSSSS"); + case "DEFAULT_PERIOD": + return "yyyy-MM-dd HH:mm:ss.SSS"; + case "ISO8601_BASIC": + return "yyyyMMdd'T'HHmmss,SSS"; + case "ISO8601_BASIC_PERIOD": + return "yyyyMMdd'T'HHmmss.SSS"; + case "ISO8601": + return "yyyy-MM-dd'T'HH:mm:ss,SSS"; + case "ISO8601_OFFSET_DATE_TIME_HH": + return "yyyy-MM-dd'T'HH:mm:ss,SSS" + (compat ? "X" : "x"); + case "ISO8601_OFFSET_DATE_TIME_HHMM": + return "yyyy-MM-dd'T'HH:mm:ss,SSS" + (compat ? "XX" : "xx"); + case "ISO8601_OFFSET_DATE_TIME_HHCMM": + return "yyyy-MM-dd'T'HH:mm:ss,SSS" + (compat ? "XXX" : "xxx"); + case "ISO8601_PERIOD": + return "yyyy-MM-dd'T'HH:mm:ss.SSS"; + case "ISO8601_PERIOD_MICROS": + return "yyyy-MM-dd'T'HH:mm:ss." + (compat ? "nnnnnn" : "SSSSSS"); + case "US_MONTH_DAY_YEAR2_TIME": + return "dd/MM/yy HH:mm:ss.SSS"; + case "US_MONTH_DAY_YEAR4_TIME": + return "dd/MM/yyyy HH:mm:ss.SSS"; } + return pattern; } - private final class CachedTime { - public long epochSecond; - public int nanoOfSecond; - public String formatted; - - public CachedTime(final Instant instant) { - this.epochSecond = instant.getEpochSecond(); - this.nanoOfSecond = instant.getNanoOfSecond(); - this.formatted = formatter.format(instant); + private static TimeZone readTimeZone(@Nullable final String[] options) { + try { + if (options != null && options.length > 1 && options[1] != null) { + return TimeZone.getTimeZone(options[1]); + } + } catch (final Exception error) { + logOptionReadFailure( + options, + error, + "failed to read the time zone at index 1 of options: {}, falling back to the default time zone"); } + return TimeZone.getDefault(); } - /** - * UNIX formatter in seconds (standard). - */ - private static final String UNIX_FORMAT = "UNIX"; - - /** - * UNIX formatter in milliseconds - */ - private static final String UNIX_MILLIS_FORMAT = "UNIX_MILLIS"; - - private final String[] options; - private final ThreadLocal threadLocalMutableInstant = new ThreadLocal<>(); - private final ThreadLocal threadLocalFormatter = new ThreadLocal<>(); - private final AtomicReference cachedTime; - private final Formatter formatter; - - /** - * Private constructor. - * - * @param options options, may be null. - */ - private DatePatternConverter(final String[] options) { - super("Date", "date"); - this.options = options == null ? null : Arrays.copyOf(options, options.length); - this.formatter = createFormatter(options); - cachedTime = new AtomicReference<>(fromEpochMillis(System.currentTimeMillis())); - } - - private CachedTime fromEpochMillis(final long epochMillis) { - final MutableInstant temp = new MutableInstant(); - temp.initFromEpochMilli(epochMillis, 0); - return new CachedTime(temp); + private static Locale readLocale(@Nullable final String[] options) { + try { + if (options != null && options.length > 2 && options[2] != null) { + return Locale.forLanguageTag(options[2]); + } + } catch (final Exception error) { + logOptionReadFailure( + options, + error, + "failed to read the locale at index 2 of options: {}, falling back to the default locale"); + } + return Locale.getDefault(); } - private Formatter createFormatter(final String[] options) { - final FixedDateFormat fixedDateFormat = FixedDateFormat.createIfSupported(options); - if (fixedDateFormat != null) { - return createFixedFormatter(fixedDateFormat); + private static void logOptionReadFailure(final String[] options, final Exception error, final String message) { + if (LOGGER.isWarnEnabled()) { + final String quotedOptions = + Arrays.stream(options).map(option -> '`' + option + '`').collect(Collectors.joining(", ")); + LOGGER.warn("[{}] " + message, CLASS_NAME, quotedOptions, error); } - return createNonFixedFormatter(options); } /** @@ -222,155 +235,98 @@ public static DatePatternConverter newInstance(final String[] options) { return new DatePatternConverter(options); } - private static Formatter createFixedFormatter(final FixedDateFormat fixedDateFormat) { - return new FixedFormatter(fixedDateFormat); - } - - private static Formatter createNonFixedFormatter(final String[] options) { - // if we get here, options is a non-null array with at least one element (first of which non-null) - Objects.requireNonNull(options); - if (options.length == 0) { - throw new IllegalArgumentException("Options array must have at least one element"); - } - Objects.requireNonNull(options[0]); - final String patternOption = options[0]; - if (UNIX_FORMAT.equals(patternOption)) { - return new UnixFormatter(); - } - if (UNIX_MILLIS_FORMAT.equals(patternOption)) { - return new UnixMillisFormatter(); - } - // LOG4J2-1149: patternOption may be a name (if a time zone was specified) - final FixedDateFormat.FixedFormat fixedFormat = FixedDateFormat.FixedFormat.lookup(patternOption); - final String pattern = fixedFormat == null ? patternOption : fixedFormat.getPattern(); - - // if the option list contains a TZ option, then set it. - TimeZone tz = null; - if (options.length > 1 && options[1] != null) { - tz = TimeZone.getTimeZone(options[1]); - } - - Locale locale = null; - if (options.length > 2 && options[2] != null) { - locale = Locale.forLanguageTag(options[2]); - } - - try { - final FastDateFormat tempFormat = FastDateFormat.getInstance(pattern, tz, locale); - return new PatternFormatter(tempFormat); - } catch (final IllegalArgumentException e) { - LOGGER.warn("Could not instantiate FastDateFormat with pattern " + pattern, e); - - // default to the DEFAULT format - return createFixedFormatter(FixedDateFormat.create(FixedFormat.DEFAULT, tz)); - } - } - /** - * Appends formatted date to string buffer. + * Formats the given date to the provided buffer. * - * @param date date - * @param toAppendTo buffer to which formatted date is appended. + * @param date a date + * @param buffer a buffer to append to + * @deprecated Starting with version {@code 2.25.0}, this method is deprecated and planned to be removed in the next major release. */ - public void format(final Date date, final StringBuilder toAppendTo) { - format(date.getTime(), toAppendTo); + @Deprecated + public void format(final Date date, final StringBuilder buffer) { + format(date.getTime(), buffer); } - /** - * {@inheritDoc} - */ @Override public void format(final LogEvent event, final StringBuilder output) { format(event.getInstant(), output); } - public void format(final long epochMilli, final StringBuilder output) { - final MutableInstant instant = getMutableInstant(); - instant.initFromEpochMilli(epochMilli, 0); - format(instant, output); - } - - private MutableInstant getMutableInstant() { - if (Constants.ENABLE_THREADLOCALS) { - MutableInstant result = threadLocalMutableInstant.get(); - if (result == null) { - result = new MutableInstant(); - threadLocalMutableInstant.set(result); - } - return result; - } - return new MutableInstant(); - } - - public void format(final Instant instant, final StringBuilder output) { - if (Constants.ENABLE_THREADLOCALS) { - formatWithoutAllocation(instant, output); - } else { - formatWithoutThreadLocals(instant, output); - } - } - - private void formatWithoutAllocation(final Instant instant, final StringBuilder output) { - getThreadLocalFormatter().formatToBuffer(instant, output); - } - - private Formatter getThreadLocalFormatter() { - Formatter result = threadLocalFormatter.get(); - if (result == null) { - result = createFormatter(options); - threadLocalFormatter.set(result); - } - return result; - } - - private void formatWithoutThreadLocals(final Instant instant, final StringBuilder output) { - final CachedTime effective; - final CachedTime cached = cachedTime.get(); - if (instant.getEpochSecond() != cached.epochSecond || instant.getNanoOfSecond() != cached.nanoOfSecond) { - effective = new CachedTime(instant); - cachedTime.compareAndSet(cached, effective); - } else { - effective = cached; - } - output.append(effective.formatted); + /** + * Formats the given epoch milliseconds to the provided buffer. + * + * @param epochMillis epoch milliseconds + * @param buffer a buffer to append to + * @deprecated Starting with version {@code 2.25.0}, this method is deprecated and planned to be removed in the next major release. + */ + @Deprecated + public void format(final long epochMillis, final StringBuilder buffer) { + final MutableInstant instant = new MutableInstant(); + instant.initFromEpochMilli(epochMillis, 0); + format(instant, buffer); } /** - * {@inheritDoc} + * Formats the given instant to the provided buffer. + * + * @param instant an instant + * @param buffer a buffer to append to + * @deprecated Starting with version {@code 2.25.0}, this method is deprecated and planned to be removed in the next major release. */ + @Deprecated + public void format(final Instant instant, final StringBuilder buffer) { + formatter.formatTo(buffer, instant); + } + @Override - public void format(final Object obj, final StringBuilder output) { - if (obj instanceof Date) { - format((Date) obj, output); + public void format(@Nullable final Object object, final StringBuilder buffer) { + requireNonNull(buffer, "buffer"); + if (object == null) { + return; } - super.format(obj, output); + if (object instanceof LogEvent) { + format((LogEvent) object, buffer); + } else if (object instanceof Date) { + format((Date) object, buffer); + } else if (object instanceof Instant) { + format((Instant) object, buffer); + } else if (object instanceof Long) { + format((long) object, buffer); + } + LOGGER.warn( + "[{}]: unsupported object type `{}`", + CLASS_NAME, + object.getClass().getCanonicalName()); } @Override - public void format(final StringBuilder toAppendTo, final Object... objects) { - for (final Object obj : objects) { - if (obj instanceof Date) { - format(obj, toAppendTo); - break; + public void format(final StringBuilder buffer, @Nullable final Object... objects) { + requireNonNull(buffer, "buffer"); + if (objects != null) { + for (final Object object : objects) { + if (object instanceof Date) { + format((Date) object, buffer); + break; + } } } } /** - * Gets the pattern string describing this date format. - * - * @return the pattern string describing this date format or {@code null} if the format does not have a pattern. + * @return the pattern string describing this date format or {@code null} if the format does not have a pattern. */ public String getPattern() { - return formatter.toPattern(); + return (formatter instanceof InstantPatternFormatter) + ? ((InstantPatternFormatter) formatter).getPattern() + : null; } /** - * Gets the timezone used by this date format. - * - * @return the timezone used by this date format. + * @return the time zone used by this date format */ public TimeZone getTimeZone() { - return formatter.getTimeZone(); + return (formatter instanceof InstantPatternFormatter) + ? ((InstantPatternFormatter) formatter).getTimeZone() + : null; } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/DatePrinter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/DatePrinter.java index ef4052fc275..ed62303492e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/DatePrinter.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/DatePrinter.java @@ -36,7 +36,9 @@ *

* * @since Apache Commons Lang 3.2 + * @deprecated Starting with version {@code 2.25.0}, this class is assumed to be internal and planned to be removed in the next major release. */ +@Deprecated public interface DatePrinter { /** diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDateFormat.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDateFormat.java index 8cd06c45708..6dc56242abf 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDateFormat.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDateFormat.java @@ -69,7 +69,9 @@ *

* * @since Apache Commons Lang 2.0 + * @deprecated Starting with version {@code 2.25.0}, this class is assumed to be internal and planned to be removed in the next major release. */ +@Deprecated public class FastDateFormat extends Format implements DatePrinter { /** diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDatePrinter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDatePrinter.java index 96541cd57cd..f4df3ebfa03 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDatePrinter.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FastDatePrinter.java @@ -78,7 +78,9 @@ *

* * @since Apache Commons Lang 3.2 + * @deprecated Starting with version {@code 2.25.0}, this class is assumed to be internal and planned to be removed in the next major release. */ +@Deprecated public class FastDatePrinter implements DatePrinter, Serializable { // A lot of the speed in this class comes from caching, but some comes // from the special int to StringBuffer conversion. diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java index 9a0d7e2cd64..89c0c0c6974 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.java @@ -27,11 +27,10 @@ /** * Custom time formatter that trades flexibility for performance. This formatter only supports the date patterns defined * in {@link FixedFormat}. For any other date patterns use {@link FastDateFormat}. - *

- * Related benchmarks: /log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/TimeFormatBenchmark.java and - * /log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadsafeDateFormatBenchmark.java - *

+ * + * @deprecated Starting with version {@code 2.25.0}, this class is assumed to be internal and planned to be removed in the next major release. */ +@Deprecated @ProviderType public class FixedDateFormat { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/Format.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/Format.java index b77cfc7adf6..8ec012e1671 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/Format.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/Format.java @@ -20,7 +20,10 @@ /** * The basic methods for performing date formatting. + * + * @deprecated Starting with version {@code 2.25.0}, this class is assumed to be internal and planned to be removed in the next major release. */ +@Deprecated public abstract class Format { public final String format(final Object obj) { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FormatCache.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FormatCache.java index 5434a3413cc..ed47bc1f83f 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FormatCache.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/FormatCache.java @@ -32,8 +32,10 @@ *

* * @since Apache Commons Lang 3.0 + * @deprecated Starting with version {@code 2.25.0}, this class is assumed to be internal and planned to be removed in the next major release. */ // TODO: Before making public move from getDateTimeInstance(Integer,...) to int; or some other approach. +@Deprecated abstract class FormatCache { /** diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/package-info.java index dd5eea74619..6b4ae367b69 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/package-info.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/datetime/package-info.java @@ -14,14 +14,16 @@ * See the license for the specific language governing permissions and * limitations under the license. */ + /** - * Log4j 2 date formatting classes. + * Log4j date and time formatting classes. + * + * @deprecated Starting with version {@code 2.25.0}, these classes are assumed to be internal and planned to be moved to an internal package in the next major release. */ +@Deprecated @Export -@Version("2.21.1") -@BaselineIgnore("2.22.0") +@Version("2.21.2") package org.apache.logging.log4j.core.util.datetime; -import aQute.bnd.annotation.baseline.BaselineIgnore; import org.osgi.annotation.bundle.Export; import org.osgi.annotation.versioning.Version; diff --git a/log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantFormatter.java similarity index 53% rename from log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/package-info.java rename to log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantFormatter.java index d4d9924283c..e53777813da 100644 --- a/log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/package-info.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantFormatter.java @@ -14,9 +14,31 @@ * See the License for the specific language governing permissions and * limitations under the License. */ -@Export -@Version("2.20.1") -package org.apache.logging.log4j.layout.template.json; +package org.apache.logging.log4j.core.util.internal.instant; -import org.osgi.annotation.bundle.Export; -import org.osgi.annotation.versioning.Version; +import static java.util.Objects.requireNonNull; + +import java.time.temporal.ChronoUnit; +import org.apache.logging.log4j.core.time.Instant; + +/** + * Contract for formatting {@link Instant}s. + * + * @since 2.25.0 + */ +public interface InstantFormatter { + + /** + * @return the time precision of the formatted output + */ + ChronoUnit getPrecision(); + + default String format(final Instant instant) { + requireNonNull(instant, "instant"); + final StringBuilder buffer = new StringBuilder(); + formatTo(buffer, instant); + return buffer.toString(); + } + + void formatTo(StringBuilder buffer, Instant instant); +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatter.java new file mode 100644 index 00000000000..0ca4a982b31 --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantNumberFormatter.java @@ -0,0 +1,128 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static java.util.Objects.requireNonNull; + +import java.time.temporal.ChronoUnit; +import java.util.function.BiConsumer; +import org.apache.logging.log4j.core.time.Instant; + +/** + * Formats an {@link Instant} numerically; e.g., formats its epoch1 seconds. + *

+ * 1 Epoch is a fixed instant on {@code 1970-01-01Z}. + *

+ *

Internal usage only!

+ *

+ * This class is intended only for internal Log4j usage. + * Log4j users should not use this class! + * This class is not subject to any backward compatibility concerns. + *

+ * + * @since 2.25.0 + */ +public enum InstantNumberFormatter implements InstantFormatter { + + /** + * Formats nanoseconds since epoch; e.g., {@code 1581082727982123456}. + */ + EPOCH_NANOS(ChronoUnit.NANOS, (instant, buffer) -> { + final long nanos = epochNanos(instant); + buffer.append(nanos); + }), + + /** + * Formats milliseconds since epoch, including the nanosecond fraction; e.g., {@code 1581082727982.123456}. + * The nanosecond fraction will be skipped if it is zero. + */ + EPOCH_MILLIS(ChronoUnit.NANOS, (instant, buffer) -> { + final long nanos = epochNanos(instant); + buffer.append(nanos); + buffer.insert(buffer.length() - 6, '.'); + }), + + /** + * Formats milliseconds since epoch, excluding the nanosecond fraction; e.g., {@code 1581082727982}. + */ + EPOCH_MILLIS_ROUNDED(ChronoUnit.MILLIS, (instant, buffer) -> { + final long millis = instant.getEpochMillisecond(); + buffer.append(millis); + }), + + /** + * Formats the nanosecond fraction of milliseconds since epoch; e.g., {@code 123456}. + */ + EPOCH_MILLIS_NANOS(ChronoUnit.NANOS, (instant, buffer) -> { + final long nanos = epochNanos(instant); + final long fraction = nanos % 1_000_000L; + buffer.append(fraction); + }), + + /** + * Formats seconds since epoch, including the nanosecond fraction; e.g., {@code 1581082727.982123456}. + * The nanosecond fraction will be skipped if it is zero. + */ + EPOCH_SECONDS(ChronoUnit.NANOS, (instant, buffer) -> { + final long nanos = epochNanos(instant); + buffer.append(nanos); + buffer.insert(buffer.length() - 9, '.'); + }), + + /** + * Formats seconds since epoch, excluding the nanosecond fraction; e.g., {@code 1581082727}. + * The nanosecond fraction will be skipped if it is zero. + */ + EPOCH_SECONDS_ROUNDED(ChronoUnit.SECONDS, (instant, buffer) -> { + final long seconds = instant.getEpochSecond(); + buffer.append(seconds); + }), + + /** + * Formats the nanosecond fraction of seconds since epoch; e.g., {@code 982123456}. + */ + EPOCH_SECONDS_NANOS(ChronoUnit.NANOS, (instant, buffer) -> { + final long secondsNanos = instant.getNanoOfSecond(); + buffer.append(secondsNanos); + }); + + private static long epochNanos(final Instant instant) { + final long nanos = Math.multiplyExact(1_000_000_000L, instant.getEpochSecond()); + return Math.addExact(nanos, instant.getNanoOfSecond()); + } + + private final ChronoUnit precision; + + private final BiConsumer formatter; + + InstantNumberFormatter(final ChronoUnit precision, final BiConsumer formatter) { + this.precision = precision; + this.formatter = formatter; + } + + @Override + public ChronoUnit getPrecision() { + return precision; + } + + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + requireNonNull(buffer, "buffer"); + requireNonNull(instant, "instant"); + formatter.accept(instant, buffer); + } +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatter.java new file mode 100644 index 00000000000..9c93dd34066 --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternDynamicFormatter.java @@ -0,0 +1,831 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static java.util.Objects.requireNonNull; + +import java.time.format.DateTimeFormatter; +import java.time.temporal.ChronoUnit; +import java.time.temporal.TemporalAccessor; +import java.util.ArrayList; +import java.util.Collections; +import java.util.Comparator; +import java.util.List; +import java.util.Locale; +import java.util.Objects; +import java.util.TimeZone; +import java.util.concurrent.atomic.AtomicReference; +import java.util.function.Supplier; +import java.util.stream.Collectors; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.jspecify.annotations.Nullable; + +/** + * An {@link InstantPatternFormatter} that uses {@link DateTimeFormatter} under the hood. + * The pattern is analyzed and parts that require a precision lower than or equal to {@value InstantPatternDynamicFormatter#PRECISION_THRESHOLD} are precomputed, cached, and updated once every {@value InstantPatternDynamicFormatter#PRECISION_THRESHOLD}. + * The rest is computed dynamically. + *

+ * For instance, given the pattern {@code yyyy-MM-dd'T'HH:mm:ss.SSSX}, the generated formatter will + *

+ *
    + *
  1. Sequence the pattern and assign a time precision to each part (e.g., {@code MM} is of month precision)
    2. + *
  2. Precompute and cache the output for parts that are of precision lower than or equal to {@value InstantPatternDynamicFormatter#PRECISION_THRESHOLD} (i.e., {@code yyyy-MM-dd'T'HH:mm:} and {@code X}) and cache it
    3. + *
  3. Upon a formatting request, combine the cached outputs with the dynamic parts (i.e., {@code ss.SSS})
    4. + *
+ *

Implementation note

+ *

+ * Formatting can actually even be made faster and garbage-free by manually formatting sub-minute precision directives as follows: + *

+ * 
{@code
+ * int offsetMillis = timeZone.getOffset(mutableInstant.getEpochMillisecond());
+ * long adjustedEpochSeconds = (instant.getEpochMillisecond() + offsetMillis) / 1000;
+ * int local_s = (int) (adjustedEpochSeconds % 60);
+ * int local_S = instant.getNanoOfSecond() / 100000000;
+ * int local_SS = instant.getNanoOfSecond() / 10000000;
+ * int local_SSS = instant.getNanoOfSecond() / 1000000;
+ * int local_SSSS = instant.getNanoOfSecond() / 100000;
+ * int local_SSSSS = instant.getNanoOfSecond() / 10000;
+ * int local_SSSSSS = instant.getNanoOfSecond() / 1000;
+ * int local_SSSSSSS = instant.getNanoOfSecond() / 100;
+ * int local_SSSSSSSS = instant.getNanoOfSecond() / 10;
+ * int local_SSSSSSSSS = instant.getNanoOfSecond();
+ * int local_n = instant.getNanoOfSecond();
+ * }
+ *

+ * Though this will require more hardcoded formatting and a change in the sequence merging strategies. + * Hence, this optimization is intentionally shelved off due to involved complexity. + * See {@code verify_manually_computed_sub_minute_precision_values()} in {@code InstantPatternDynamicFormatterTest} for a demonstration of this optimization. + *

+ * + * @since 2.25.0 + */ +final class InstantPatternDynamicFormatter implements InstantPatternFormatter { + + static final ChronoUnit PRECISION_THRESHOLD = ChronoUnit.MINUTES; + + private final AtomicReference timestampedFormatterRef; + + InstantPatternDynamicFormatter(final String pattern, final Locale locale, final TimeZone timeZone) { + final TimestampedFormatter timestampedFormatter = createTimestampedFormatter(pattern, locale, timeZone, null); + this.timestampedFormatterRef = new AtomicReference<>(timestampedFormatter); + } + + @Override + public String getPattern() { + return timestampedFormatterRef.get().formatter.getPattern(); + } + + @Override + public Locale getLocale() { + return timestampedFormatterRef.get().formatter.getLocale(); + } + + @Override + public TimeZone getTimeZone() { + return timestampedFormatterRef.get().formatter.getTimeZone(); + } + + @Override + public ChronoUnit getPrecision() { + return timestampedFormatterRef.get().formatter.getPrecision(); + } + + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + requireNonNull(buffer, "buffer"); + requireNonNull(instant, "instant"); + getEffectiveFormatter(instant).formatTo(buffer, instant); + } + + private InstantPatternFormatter getEffectiveFormatter(final Instant instant) { + + // Reuse the instance formatter, if timestamps match + TimestampedFormatter oldTimestampedFormatter = timestampedFormatterRef.get(); + final long instantEpochMinutes = toEpochMinutes(instant); + final InstantPatternFormatter oldFormatter = oldTimestampedFormatter.formatter; + if (oldTimestampedFormatter.instantEpochMinutes == instantEpochMinutes) { + return oldFormatter; + } + + // Create a new formatter, [try to] update the instance formatter, and return that + final TimestampedFormatter newTimestampedFormatter = createTimestampedFormatter( + oldFormatter.getPattern(), oldFormatter.getLocale(), oldFormatter.getTimeZone(), instant); + timestampedFormatterRef.compareAndSet(oldTimestampedFormatter, newTimestampedFormatter); + return newTimestampedFormatter.formatter; + } + + private static TimestampedFormatter createTimestampedFormatter( + final String pattern, final Locale locale, final TimeZone timeZone, @Nullable Instant creationInstant) { + if (creationInstant == null) { + creationInstant = new MutableInstant(); + final java.time.Instant currentInstant = java.time.Instant.now(); + ((MutableInstant) creationInstant) + .initFromEpochSecond(currentInstant.getEpochSecond(), creationInstant.getNanoOfSecond()); + } + final InstantPatternFormatter formatter = + createFormatter(pattern, locale, timeZone, PRECISION_THRESHOLD, creationInstant); + final long creationInstantEpochMinutes = toEpochMinutes(creationInstant); + return new TimestampedFormatter(creationInstantEpochMinutes, formatter); + } + + private static final class TimestampedFormatter { + + private final long instantEpochMinutes; + + private final InstantPatternFormatter formatter; + + private TimestampedFormatter(final long instantEpochMinutes, final InstantPatternFormatter formatter) { + this.instantEpochMinutes = instantEpochMinutes; + this.formatter = formatter; + } + } + + @SuppressWarnings("SameParameterValue") + private static InstantPatternFormatter createFormatter( + final String pattern, + final Locale locale, + final TimeZone timeZone, + final ChronoUnit precisionThreshold, + final Instant creationInstant) { + + // Sequence the pattern and create associated formatters + final List sequences = sequencePattern(pattern, precisionThreshold); + final List formatters = sequences.stream() + .map(sequence -> { + final InstantPatternFormatter formatter = sequence.createFormatter(locale, timeZone); + final boolean constant = sequence.isConstantForDurationOf(precisionThreshold); + if (!constant) { + return formatter; + } + final String formattedInstant; + { + final StringBuilder buffer = new StringBuilder(); + formatter.formatTo(buffer, creationInstant); + formattedInstant = buffer.toString(); + } + return new AbstractFormatter(formatter.getPattern(), locale, timeZone, formatter.getPrecision()) { + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + buffer.append(formattedInstant); + } + }; + }) + .collect(Collectors.toList()); + + switch (formatters.size()) { + + // If found an empty pattern, return an empty formatter + case 0: + return new AbstractFormatter(pattern, locale, timeZone, ChronoUnit.FOREVER) { + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + // Do nothing + } + }; + + // If extracted a single formatter, return it as is + case 1: + return formatters.get(0); + + // Combine all extracted formatters into one + default: + final ChronoUnit precision = new CompositePatternSequence(sequences).precision; + return new AbstractFormatter(pattern, locale, timeZone, precision) { + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + // noinspection ForLoopReplaceableByForEach (avoid iterator allocation) + for (int formatterIndex = 0; formatterIndex < formatters.size(); formatterIndex++) { + final InstantPatternFormatter formatter = formatters.get(formatterIndex); + formatter.formatTo(buffer, instant); + } + } + }; + } + } + + static List sequencePattern(final String pattern, final ChronoUnit precisionThreshold) { + List sequences = sequencePattern(pattern); + final List mergedSequences = mergeDynamicSequences(sequences, precisionThreshold); + return mergeConsequentEffectivelyConstantSequences(mergedSequences, precisionThreshold); + } + + private static List sequencePattern(final String pattern) { + if (pattern.isEmpty()) { + return Collections.emptyList(); + } + final List sequences = new ArrayList<>(); + for (int startIndex = 0; startIndex < pattern.length(); ) { + final char c = pattern.charAt(startIndex); + + // Handle dynamic pattern letters + final boolean dynamic = isDynamicPatternLetter(c); + if (dynamic) { + int endIndex = startIndex + 1; + while (endIndex < pattern.length() && pattern.charAt(endIndex) == c) { + endIndex++; + } + final String sequenceContent = pattern.substring(startIndex, endIndex); + final PatternSequence sequence = new DynamicPatternSequence(sequenceContent); + sequences.add(sequence); + startIndex = endIndex; + } + + // Handle single-quotes + else if (c == '\'') { + final int endIndex = pattern.indexOf('\'', startIndex + 1); + if (endIndex < 0) { + final String message = String.format( + "pattern ends with an incomplete string literal that started at index %d: `%s`", + startIndex, pattern); + throw new IllegalArgumentException(message); + } + final String sequenceLiteral = + (startIndex + 1) == endIndex ? "'" : pattern.substring(startIndex + 1, endIndex); + final PatternSequence sequence = new StaticPatternSequence(sequenceLiteral); + sequences.add(sequence); + startIndex = endIndex + 1; + } + + // Handle unknown literal + else { + final PatternSequence sequence = new StaticPatternSequence("" + c); + sequences.add(sequence); + startIndex++; + } + } + return mergeConsequentStaticPatternSequences(sequences); + } + + private static boolean isDynamicPatternLetter(final char c) { + return "GuyDMLdgQqYwWEecFaBhKkHmsSAnNVvzOXxZ".indexOf(c) >= 0; + } + + /** + * Merges consequent static sequences. + * + *

+ * For example, the sequencing of the {@code [MM-dd] HH:mm} pattern will create two static sequences for {@code ]} (right brace) and {@code } (whitespace) characters. + * This method will combine such consequent static sequences into one. + *

+ * + *

Example

+ * + *

+ * The {@code [MM-dd] HH:mm} pattern will result in following sequences: + *

+ * + * 
{@code
+     * [
+     *     static(literal="["),
+     *     dynamic(pattern="MM", precision=MONTHS),
+     *     static(literal="-"),
+     *     dynamic(pattern="dd", precision=DAYS),
+     *     static(literal="]"),
+     *     static(literal=" "),
+     *     dynamic(pattern="HH", precision=HOURS),
+     *     static(literal=":"),
+     *     dynamic(pattern="mm", precision=MINUTES)
+     * ]
+     * }
+ * + *

+ * The above sequencing implies creation of 9 {@link AbstractFormatter}s. + * This method transforms it to the following: + *

+ * + * 
{@code
+     * [
+     *     static(literal="["),
+     *     dynamic(pattern="MM", precision=MONTHS),
+     *     static(literal="-"),
+     *     dynamic(pattern="dd", precision=DAYS),
+     *     static(literal="] "),
+     *     dynamic(pattern="HH", precision=HOURS),
+     *     static(literal=":"),
+     *     dynamic(pattern="mm", precision=MINUTES)
+     * ]
+     * }
+ * + *

+ * The above sequencing implies creation of 8 {@link AbstractFormatter}s. + *

+ * + * @param sequences sequences to be transformed + * @return transformed sequencing where consequent static sequences are merged + */ + private static List mergeConsequentStaticPatternSequences(final List sequences) { + + // Short-circuit if there is nothing to merge + if (sequences.size() < 2) { + return sequences; + } + + final List mergedSequences = new ArrayList<>(); + final List accumulatedSequences = new ArrayList<>(); + for (final PatternSequence sequence : sequences) { + + // Spotted a static sequence? Stage it for merging. + if (sequence instanceof StaticPatternSequence) { + accumulatedSequences.add((StaticPatternSequence) sequence); + } + + // Spotted a dynamic sequence. + // Merge the accumulated static sequences, and then append the dynamic sequence. + else { + mergeConsequentStaticPatternSequences(mergedSequences, accumulatedSequences); + mergedSequences.add(sequence); + } + } + + // Merge leftover static sequences + mergeConsequentStaticPatternSequences(mergedSequences, accumulatedSequences); + return mergedSequences; + } + + private static void mergeConsequentStaticPatternSequences( + final List mergedSequences, final List accumulatedSequences) { + mergeAccumulatedSequences(mergedSequences, accumulatedSequences, () -> { + final String literal = accumulatedSequences.stream() + .map(sequence -> sequence.literal) + .collect(Collectors.joining()); + return new StaticPatternSequence(literal); + }); + } + + /** + * Merges the sequences in between the first and the last found dynamic (i.e., non-constant) sequences. + * + *

+ * For example, given the {@code ss.SSS} pattern – where {@code ss} and {@code SSS} is effectively not constant, yet {@code .} is – this method will combine it into a single dynamic sequence. + * Because, as demonstrated in {@code DateTimeFormatterSequencingBenchmark}, formatting {@code ss.SSS} is approximately 20% faster than formatting first {@code ss}, then manually appending a {@code .}, and then formatting {@code SSS}. + *

+ * + *

Example

+ * + *

+ * Assume {@link #mergeConsequentStaticPatternSequences(List)} produced the following: + *

+ * + * 
{@code
+     * [
+     *     dynamic(pattern="yyyy", precision=YEARS),
+     *     static(literal="-"),
+     *     dynamic(pattern="MM", precision=MONTHS),
+     *     static(literal="-"),
+     *     dynamic(pattern="dd", precision=DAYS),
+     *     static(literal="T"),
+     *     dynamic(pattern="HH", precision=HOURS),
+     *     static(literal=":"),
+     *     dynamic(pattern="mm", precision=MINUTES),
+     *     static(literal=":"),
+     *     dynamic(pattern="ss", precision=SECONDS),
+     *     static(literal="."),
+     *     dynamic(pattern="SSS", precision=MILLISECONDS),
+     *     dynamic(pattern="X", precision=HOURS),
+     * ]
+     * }
+ * + *

+ * For a threshold precision of {@link ChronoUnit#MINUTES}, this sequencing effectively translates to two {@link DateTimeFormatter#formatTo(TemporalAccessor, Appendable)} invocations for each {@link #formatTo(StringBuilder, Instant)} call: one for {@code ss}, and another one for {@code SSS}. + * This method transforms the above sequencing into the following: + *

+ * + * 
{@code
+     * [
+     *     dynamic(pattern="yyyy", precision=YEARS),
+     *     static(literal="-"),
+     *     dynamic(pattern="MM", precision=MONTHS),
+     *     static(literal="-"),
+     *     dynamic(pattern="dd", precision=DAYS),
+     *     static(literal="T"),
+     *     dynamic(pattern="HH", precision=HOURS),
+     *     static(literal=":"),
+     *     dynamic(pattern="mm", precision=MINUTES),
+     *     static(literal=":"),
+     *     composite(
+     *         sequences=[
+     *             dynamic(pattern="ss", precision=SECONDS),
+     *             static(literal="."),
+     *             dynamic(pattern="SSS", precision=MILLISECONDS)
+     *         ],
+     *         precision=MILLISECONDS),
+     *     dynamic(pattern="X", precision=HOURS),
+     * ]
+     * }
+ * + *

+ * The resultant sequencing effectively translates to a single {@link DateTimeFormatter#formatTo(TemporalAccessor, Appendable)} invocation for each {@link #formatTo(StringBuilder, Instant)} call: only one fore {@code ss.SSS}. + *

+ * + * @param sequences sequences, preferable produced by {@link #mergeConsequentStaticPatternSequences(List)}, to be transformed + * @param precisionThreshold a precision threshold to determine dynamic (i.e., non-constant) sequences + * @return transformed sequencing where sequences in between the first and the last found dynamic (i.e., non-constant) sequences are merged + */ + private static List mergeDynamicSequences( + final List sequences, final ChronoUnit precisionThreshold) { + + // Locate the first and the last dynamic (i.e., non-constant) sequence indices + int firstDynamicSequenceIndex = -1; + int lastDynamicSequenceIndex = -1; + for (int sequenceIndex = 0; sequenceIndex < sequences.size(); sequenceIndex++) { + final PatternSequence sequence = sequences.get(sequenceIndex); + final boolean constant = sequence.isConstantForDurationOf(precisionThreshold); + if (!constant) { + if (firstDynamicSequenceIndex < 0) { + firstDynamicSequenceIndex = sequenceIndex; + } + lastDynamicSequenceIndex = sequenceIndex; + } + } + + // Short-circuit if there are less than 2 dynamic sequences + if (firstDynamicSequenceIndex < 0 || firstDynamicSequenceIndex == lastDynamicSequenceIndex) { + return sequences; + } + + // Merge dynamic sequences + final List mergedSequences = new ArrayList<>(); + if (firstDynamicSequenceIndex > 0) { + mergedSequences.addAll(sequences.subList(0, firstDynamicSequenceIndex)); + } + final PatternSequence mergedDynamicSequence = new CompositePatternSequence( + sequences.subList(firstDynamicSequenceIndex, lastDynamicSequenceIndex + 1)); + mergedSequences.add(mergedDynamicSequence); + if ((lastDynamicSequenceIndex + 1) < sequences.size()) { + mergedSequences.addAll(sequences.subList(lastDynamicSequenceIndex + 1, sequences.size())); + } + return mergedSequences; + } + + /** + * Merges sequences that are consequent and effectively constant for the provided precision threshold. + * + *

+ * For example, given the {@code yyyy-MM-dd'T'HH:mm:ss.SSS} pattern and a precision threshold of {@link ChronoUnit#MINUTES}, this method will combine sequences associated with {@code yyyy-MM-dd'T'HH:mm:} into a single sequence, since these are consequent and effectively constant sequences. + *

+ * + *

Example

+ * + *

+ * Assume {@link #mergeDynamicSequences(List, ChronoUnit)} produced the following: + *

+ * + * 
{@code
+     * [
+     *     dynamic(pattern="yyyy", precision=YEARS),
+     *     static(literal="-"),
+     *     dynamic(pattern="MM", precision=MONTHS),
+     *     static(literal="-"),
+     *     dynamic(pattern="dd", precision=DAYS),
+     *     static(literal="T"),
+     *     dynamic(pattern="HH", precision=HOURS),
+     *     static(literal=":"),
+     *     dynamic(pattern="mm", precision=MINUTES),
+     *     static(literal=":"),
+     *     composite(
+     *         sequences=[
+     *             dynamic(pattern="ss", precision=SECONDS),
+     *             static(literal="."),
+     *             dynamic(pattern="SSS", precision=MILLISECONDS)
+     *         ],
+     *         precision=MILLISECONDS),
+     *     dynamic(pattern="X", precision=HOURS),
+     * ]
+     * }
+ * + *

+ * The above sequencing implies creation of 12 {@link AbstractFormatter}s. + * This method transforms it to the following: + *

+ * + * 
{@code
+     * [
+     *     composite(
+     *         sequences=[
+     *             dynamic(pattern="yyyy", precision=YEARS),
+     *             static(literal="-"),
+     *             dynamic(pattern="MM", precision=MONTHS),
+     *             static(literal="-"),
+     *             dynamic(pattern="dd", precision=DAYS),
+     *             static(literal="T"),
+     *             dynamic(pattern="HH", precision=HOURS),
+     *             static(literal=":"),
+     *             dynamic(pattern="mm", precision=MINUTES),
+     *             static(literal=":")
+     *         ],
+     *         precision=MINUTES),
+     *     composite(
+     *         sequences=[
+     *             dynamic(pattern="ss", precision=SECONDS),
+     *             static(literal="."),
+     *             dynamic(pattern="SSS", precision=MILLISECONDS)
+     *         ],
+     *         precision=MILLISECONDS),
+     *     dynamic(pattern="X", precision=HOURS),
+     * ]
+     * }
+ * + *

+ * The resultant sequencing effectively translates to 3 {@link AbstractFormatter}s. + *

+ * + * @param sequences sequences, preferable produced by {@link #mergeDynamicSequences(List, ChronoUnit)}, to be transformed + * @param precisionThreshold a precision threshold to determine effectively constant sequences + * @return transformed sequencing where sequences that are consequent and effectively constant for the provided precision threshold are merged + */ + private static List mergeConsequentEffectivelyConstantSequences( + final List sequences, final ChronoUnit precisionThreshold) { + + // Short-circuit if there is nothing to merge + if (sequences.size() < 2) { + return sequences; + } + + final List mergedSequences = new ArrayList<>(); + boolean accumulatorConstant = true; + final List accumulatedSequences = new ArrayList<>(); + for (final PatternSequence sequence : sequences) { + final boolean sequenceConstant = sequence.isConstantForDurationOf(precisionThreshold); + if (sequenceConstant != accumulatorConstant) { + mergeConsequentEffectivelyConstantSequences(mergedSequences, accumulatedSequences); + accumulatorConstant = sequenceConstant; + } + accumulatedSequences.add(sequence); + } + + // Merge the accumulator leftover + mergeConsequentEffectivelyConstantSequences(mergedSequences, accumulatedSequences); + return mergedSequences; + } + + private static void mergeConsequentEffectivelyConstantSequences( + final List mergedSequences, final List accumulatedSequences) { + mergeAccumulatedSequences( + mergedSequences, accumulatedSequences, () -> new CompositePatternSequence(accumulatedSequences)); + } + + private static void mergeAccumulatedSequences( + final List mergedSequences, + final List accumulatedSequences, + final Supplier mergedSequenceSupplier) { + if (accumulatedSequences.isEmpty()) { + return; + } + final PatternSequence mergedSequence = + accumulatedSequences.size() == 1 ? accumulatedSequences.get(0) : mergedSequenceSupplier.get(); + mergedSequences.add(mergedSequence); + accumulatedSequences.clear(); + } + + private static long toEpochMinutes(final Instant instant) { + return instant.getEpochSecond() / 60; + } + + private static TemporalAccessor toTemporalAccessor(final Instant instant) { + return instant instanceof TemporalAccessor + ? (TemporalAccessor) instant + : java.time.Instant.ofEpochSecond(instant.getEpochSecond(), instant.getNanoOfSecond()); + } + + private abstract static class AbstractFormatter implements InstantPatternFormatter { + + private final String pattern; + + private final Locale locale; + + private final TimeZone timeZone; + + private final ChronoUnit precision; + + private AbstractFormatter( + final String pattern, final Locale locale, final TimeZone timeZone, final ChronoUnit precision) { + this.pattern = pattern; + this.locale = locale; + this.timeZone = timeZone; + this.precision = precision; + } + + @Override + public ChronoUnit getPrecision() { + return precision; + } + + @Override + public String getPattern() { + return pattern; + } + + @Override + public Locale getLocale() { + return locale; + } + + @Override + public TimeZone getTimeZone() { + return timeZone; + } + } + + abstract static class PatternSequence { + + final String pattern; + + final ChronoUnit precision; + + @SuppressWarnings("ReturnValueIgnored") + PatternSequence(final String pattern, final ChronoUnit precision) { + DateTimeFormatter.ofPattern(pattern); // Validate the pattern + this.pattern = pattern; + this.precision = precision; + } + + InstantPatternFormatter createFormatter(final Locale locale, final TimeZone timeZone) { + final DateTimeFormatter dateTimeFormatter = + DateTimeFormatter.ofPattern(pattern, locale).withZone(timeZone.toZoneId()); + return new AbstractFormatter(pattern, locale, timeZone, precision) { + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + final TemporalAccessor instantAccessor = toTemporalAccessor(instant); + dateTimeFormatter.formatTo(instantAccessor, buffer); + } + }; + } + + private boolean isConstantForDurationOf(final ChronoUnit thresholdPrecision) { + return precision.compareTo(thresholdPrecision) >= 0; + } + + @Override + public boolean equals(final Object object) { + if (this == object) { + return true; + } + if (object == null || getClass() != object.getClass()) { + return false; + } + PatternSequence sequence = (PatternSequence) object; + return Objects.equals(pattern, sequence.pattern) && precision == sequence.precision; + } + + @Override + public int hashCode() { + return Objects.hash(pattern, precision); + } + + @Override + public String toString() { + return String.format("<%s>%s", pattern, precision); + } + } + + static final class StaticPatternSequence extends PatternSequence { + + private final String literal; + + StaticPatternSequence(final String literal) { + super(literal.equals("'") ? "''" : ("'" + literal + "'"), ChronoUnit.FOREVER); + this.literal = literal; + } + + @Override + InstantPatternFormatter createFormatter(final Locale locale, final TimeZone timeZone) { + return new AbstractFormatter(pattern, locale, timeZone, precision) { + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + buffer.append(literal); + } + }; + } + } + + static final class DynamicPatternSequence extends PatternSequence { + + DynamicPatternSequence(final String content) { + super(content, contentPrecision(content)); + } + + /** + * @param content a single-letter directive content complying (e.g., {@code H}, {@code HH}, or {@code pHH}) + * @return the time precision of the directive + */ + @Nullable + private static ChronoUnit contentPrecision(final String content) { + + validateContent(content); + final String paddingRemovedContent = removePadding(content); + + if (paddingRemovedContent.matches("[GuyY]+")) { + return ChronoUnit.YEARS; + } else if (paddingRemovedContent.matches("[MLQq]+")) { + return ChronoUnit.MONTHS; + } else if (paddingRemovedContent.matches("[wW]+")) { + return ChronoUnit.WEEKS; + } else if (paddingRemovedContent.matches("[DdgEecF]+")) { + return ChronoUnit.DAYS; + } else if (paddingRemovedContent.matches("[aBhKkH]+") + // Time-zone directives + || paddingRemovedContent.matches("[ZxXOzvV]+")) { + return ChronoUnit.HOURS; + } else if (paddingRemovedContent.contains("m")) { + return ChronoUnit.MINUTES; + } else if (paddingRemovedContent.contains("s")) { + return ChronoUnit.SECONDS; + } + + // 2 to 3 consequent `S` characters output millisecond precision + else if (paddingRemovedContent.matches("S{2,3}") + // `A` (milli-of-day) outputs millisecond precision. + || paddingRemovedContent.contains("A")) { + return ChronoUnit.MILLIS; + } + + // 4 to 6 consequent `S` characters output microsecond precision + else if (paddingRemovedContent.matches("S{4,6}")) { + return ChronoUnit.MICROS; + } + + // A single `S` (fraction-of-second) outputs nanosecond precision + else if (paddingRemovedContent.equals("S") + // 7 to 9 consequent `S` characters output nanosecond precision + || paddingRemovedContent.matches("S{7,9}") + // `n` (nano-of-second) and `N` (nano-of-day) always output nanosecond precision. + // This is independent of how many times they occur sequentially. + || paddingRemovedContent.matches("[nN]+")) { + return ChronoUnit.NANOS; + } + + final String message = String.format("unrecognized pattern: `%s`", content); + throw new IllegalArgumentException(message); + } + + private static void validateContent(final String content) { + + // Is the content empty? + final String paddingRemovedContent = removePadding(content); + if (paddingRemovedContent.isEmpty()) { + final String message = String.format("empty content: `%s`", content); + throw new IllegalArgumentException(message); + } + + // Does the content start with a recognized letter? + final char letter = paddingRemovedContent.charAt(0); + final boolean dynamic = isDynamicPatternLetter(letter); + if (!dynamic) { + String message = + String.format("pattern sequence doesn't start with a dynamic pattern letter: `%s`", content); + throw new IllegalArgumentException(message); + } + + // Is the content composed of repetitions of the first letter? + final boolean repeated = paddingRemovedContent.matches("^(\\Q" + letter + "\\E)+$"); + if (!repeated) { + String message = String.format( + "was expecting letter `%c` to be repeated through the entire pattern sequence: `%s`", + letter, content); + throw new IllegalArgumentException(message); + } + } + + private static String removePadding(final String content) { + return content.replaceAll("^p+", ""); + } + } + + static final class CompositePatternSequence extends PatternSequence { + + CompositePatternSequence(final List sequences) { + super(concatSequencePatterns(sequences), findSequenceMaxPrecision(sequences)); + // Only allow two or more sequences + if (sequences.size() < 2) { + throw new IllegalArgumentException("was expecting two or more sequences: " + sequences); + } + } + + @SuppressWarnings("OptionalGetWithoutIsPresent") + private static ChronoUnit findSequenceMaxPrecision(List sequences) { + return sequences.stream() + .map(sequence -> sequence.precision) + .min(Comparator.comparing(ChronoUnit::getDuration)) + .get(); + } + + private static String concatSequencePatterns(List sequences) { + return sequences.stream().map(sequence -> sequence.pattern).collect(Collectors.joining()); + } + } +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternFormatter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternFormatter.java new file mode 100644 index 00000000000..0ec8598ce9e --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternFormatter.java @@ -0,0 +1,186 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static java.util.Objects.requireNonNull; +import static org.apache.logging.log4j.util.Strings.isBlank; + +import java.time.temporal.ChronoUnit; +import java.util.Locale; +import java.util.TimeZone; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.util.Constants; +import org.apache.logging.log4j.util.PropertiesUtil; + +/** + * Contract for formatting {@link Instant}s using a date and time formatting pattern. + *

Internal usage only!

+ *

+ * This class is intended only for internal Log4j usage. + * Log4j users should not use this class! + * This class is not subject to any backward compatibility concerns. + *

+ * + * @since 2.25.0 + */ +public interface InstantPatternFormatter extends InstantFormatter { + + boolean LEGACY_FORMATTERS_ENABLED = + "legacy".equalsIgnoreCase(PropertiesUtil.getProperties().getStringProperty("log4j2.instant.formatter")); + + String getPattern(); + + Locale getLocale(); + + TimeZone getTimeZone(); + + static Builder newBuilder() { + return new Builder(); + } + + final class Builder { + + private String pattern; + + private Locale locale = Locale.getDefault(); + + private TimeZone timeZone = TimeZone.getDefault(); + + private boolean cachingEnabled = Constants.ENABLE_THREADLOCALS; + + private boolean legacyFormattersEnabled = LEGACY_FORMATTERS_ENABLED; + + private Builder() {} + + public String getPattern() { + return pattern; + } + + public Builder setPattern(final String pattern) { + this.pattern = pattern; + return this; + } + + public Locale getLocale() { + return locale; + } + + public Builder setLocale(final Locale locale) { + this.locale = locale; + return this; + } + + public TimeZone getTimeZone() { + return timeZone; + } + + public Builder setTimeZone(final TimeZone timeZone) { + this.timeZone = timeZone; + return this; + } + + public boolean isCachingEnabled() { + return cachingEnabled; + } + + public Builder setCachingEnabled(boolean cachingEnabled) { + this.cachingEnabled = cachingEnabled; + return this; + } + + public boolean isLegacyFormattersEnabled() { + return legacyFormattersEnabled; + } + + public Builder setLegacyFormattersEnabled(boolean legacyFormattersEnabled) { + this.legacyFormattersEnabled = legacyFormattersEnabled; + return this; + } + + public InstantPatternFormatter build() { + + // Validate arguments + requireNonNull(locale, "locale"); + requireNonNull(timeZone, "timeZone"); + + // Return a literal formatter if the pattern is blank + if (isBlank(pattern)) { + return createLiteralFormatter(pattern, locale, timeZone); + } + + // Return legacy formatters, if requested + if (legacyFormattersEnabled) { + return new InstantPatternLegacyFormatter(pattern, locale, timeZone); + } + + // Create the formatter, and return it, if caching is disabled + final InstantPatternDynamicFormatter formatter = + new InstantPatternDynamicFormatter(pattern, locale, timeZone); + if (!cachingEnabled) { + return formatter; + } + + // Wrap the formatter with caching, if necessary + switch (formatter.getPrecision()) { + + // It is not worth caching when a precision equal to or higher than microsecond is requested + case NANOS: + case MICROS: + return formatter; + + // Millisecond precision cache + case MILLIS: + return InstantPatternThreadLocalCachedFormatter.ofMilliPrecision(formatter); + + // Cache everything else with second precision + default: + return InstantPatternThreadLocalCachedFormatter.ofSecondPrecision(formatter); + } + } + + private static InstantPatternFormatter createLiteralFormatter( + final String literal, final Locale locale, final TimeZone timeZone) { + return new InstantPatternFormatter() { + + @Override + public String getPattern() { + return literal; + } + + @Override + public Locale getLocale() { + return locale; + } + + @Override + public TimeZone getTimeZone() { + return timeZone; + } + + @Override + public ChronoUnit getPrecision() { + return ChronoUnit.FOREVER; + } + + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + buffer.append(literal); + } + }; + } + } +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternLegacyFormatter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternLegacyFormatter.java new file mode 100644 index 00000000000..aaf380c7f0a --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternLegacyFormatter.java @@ -0,0 +1,118 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static java.util.Objects.requireNonNull; + +import java.time.temporal.ChronoUnit; +import java.util.Calendar; +import java.util.Locale; +import java.util.TimeZone; +import java.util.function.Supplier; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.util.Constants; +import org.apache.logging.log4j.core.util.datetime.FastDateFormat; +import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; +import org.apache.logging.log4j.util.BiConsumer; + +/** + * A {@link InstantPatternFormatter} implementation using {@link FixedDateFormat} and {@link FastDateFormat} under the hood. + */ +@SuppressWarnings("deprecation") +final class InstantPatternLegacyFormatter implements InstantPatternFormatter { + + private final ChronoUnit precision; + + private final String pattern; + + private final Locale locale; + + private final TimeZone timeZone; + + private final BiConsumer formatter; + + InstantPatternLegacyFormatter(final String pattern, final Locale locale, final TimeZone timeZone) { + this.precision = new InstantPatternDynamicFormatter(pattern, locale, timeZone).getPrecision(); + this.pattern = pattern; + this.locale = locale; + this.timeZone = timeZone; + this.formatter = createFormatter(pattern, locale, timeZone); + } + + private static BiConsumer createFormatter( + final String pattern, final Locale locale, final TimeZone timeZone) { + final FixedDateFormat fixedFormatter = FixedDateFormat.createIfSupported(pattern, timeZone.getID()); + return fixedFormatter != null + ? adaptFixedFormatter(fixedFormatter) + : createFastFormatter(pattern, locale, timeZone); + } + + private static BiConsumer adaptFixedFormatter(final FixedDateFormat formatter) { + final Supplier charBufferSupplier = memoryEfficientInstanceSupplier(() -> { + // Double size for locales with lengthy `DateFormatSymbols` + return new char[formatter.getLength() << 1]; + }); + return (buffer, instant) -> { + final char[] charBuffer = charBufferSupplier.get(); + final int length = formatter.formatInstant(instant, charBuffer, 0); + buffer.append(charBuffer, 0, length); + }; + } + + private static BiConsumer createFastFormatter( + final String pattern, final Locale locale, final TimeZone timeZone) { + final FastDateFormat formatter = FastDateFormat.getInstance(pattern, timeZone, locale); + final Supplier calendarSupplier = + memoryEfficientInstanceSupplier(() -> Calendar.getInstance(timeZone, locale)); + return (buffer, instant) -> { + final Calendar calendar = calendarSupplier.get(); + calendar.setTimeInMillis(instant.getEpochMillisecond()); + formatter.format(calendar, buffer); + }; + } + + private static Supplier memoryEfficientInstanceSupplier(final Supplier supplier) { + return Constants.ENABLE_THREADLOCALS ? ThreadLocal.withInitial(supplier)::get : supplier; + } + + @Override + public ChronoUnit getPrecision() { + return precision; + } + + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + requireNonNull(buffer, "buffer"); + requireNonNull(instant, "instant"); + formatter.accept(buffer, instant); + } + + @Override + public String getPattern() { + return pattern; + } + + @Override + public Locale getLocale() { + return locale; + } + + @Override + public TimeZone getTimeZone() { + return timeZone; + } +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java new file mode 100644 index 00000000000..96bf4504aa3 --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java @@ -0,0 +1,134 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util.internal.instant; + +import static java.util.Objects.requireNonNull; + +import java.time.temporal.ChronoUnit; +import java.util.Locale; +import java.util.TimeZone; +import java.util.function.Function; +import org.apache.logging.log4j.core.time.Instant; + +/** + * An {@link InstantFormatter} wrapper caching the last formatted output in a {@link ThreadLocal} and trying to reuse it. + * + * @since 2.25.0 + */ +final class InstantPatternThreadLocalCachedFormatter implements InstantPatternFormatter { + + private final InstantPatternFormatter formatter; + + private final Function epochInstantExtractor; + + private final ThreadLocal epochInstantAndBufferRef = + ThreadLocal.withInitial(InstantPatternThreadLocalCachedFormatter::createEpochInstantAndBuffer); + + private Object[] lastEpochInstantAndBuffer = createEpochInstantAndBuffer(); + + private static Object[] createEpochInstantAndBuffer() { + return new Object[] {-1L, new StringBuilder()}; + } + + private final ChronoUnit precision; + + private InstantPatternThreadLocalCachedFormatter( + final InstantPatternFormatter formatter, + final Function epochInstantExtractor, + final ChronoUnit precision) { + this.formatter = formatter; + this.epochInstantExtractor = epochInstantExtractor; + this.precision = precision; + } + + static InstantPatternThreadLocalCachedFormatter ofMilliPrecision(final InstantPatternFormatter formatter) { + final ChronoUnit precision = effectivePrecision(formatter, ChronoUnit.MILLIS); + return new InstantPatternThreadLocalCachedFormatter(formatter, Instant::getEpochMillisecond, precision); + } + + static InstantPatternThreadLocalCachedFormatter ofSecondPrecision(final InstantPatternFormatter formatter) { + final ChronoUnit precision = effectivePrecision(formatter, ChronoUnit.SECONDS); + return new InstantPatternThreadLocalCachedFormatter(formatter, Instant::getEpochSecond, precision); + } + + private static ChronoUnit effectivePrecision(final InstantFormatter formatter, final ChronoUnit cachePrecision) { + final ChronoUnit formatterPrecision = formatter.getPrecision(); + final int comparison = cachePrecision.compareTo(formatterPrecision); + if (comparison == 0) { + return formatterPrecision; + } else if (comparison > 0) { + final String message = String.format( + "instant formatter `%s` is of `%s` precision, whereas the requested cache precision is `%s`", + formatter, formatterPrecision, cachePrecision); + throw new IllegalArgumentException(message); + } else { + return cachePrecision; + } + } + + @Override + public ChronoUnit getPrecision() { + return precision; + } + + @Override + public void formatTo(final StringBuilder buffer, final Instant instant) { + requireNonNull(buffer, "buffer"); + requireNonNull(instant, "instant"); + final Object[] prevEpochInstantAndBuffer = lastEpochInstantAndBuffer; + final long prevEpochInstant = (long) prevEpochInstantAndBuffer[0]; + final StringBuilder prevBuffer = (StringBuilder) prevEpochInstantAndBuffer[1]; + final long nextEpochInstant = epochInstantExtractor.apply(instant); + if (prevEpochInstant == nextEpochInstant) { + buffer.append(prevBuffer); + } else { + + // We could have used `StringBuilders.trimToMaxSize()` on `prevBuffer`. + // That is, we wouldn't want exploded `StringBuilder`s in hundreds of `ThreadLocal`s. + // Though we are formatting instants and always expect to produce strings of more or less the same length. + // Hence, no need for truncation. + + // Populate a new cache entry + final Object[] nextEpochInstantAndBuffer = epochInstantAndBufferRef.get(); + nextEpochInstantAndBuffer[0] = nextEpochInstant; + final StringBuilder nextBuffer = (StringBuilder) nextEpochInstantAndBuffer[1]; + nextBuffer.setLength(0); + formatter.formatTo(nextBuffer, instant); + + // Update the effective cache entry + lastEpochInstantAndBuffer = nextEpochInstantAndBuffer; + + // Help out the request + buffer.append(nextBuffer); + } + } + + @Override + public String getPattern() { + return formatter.getPattern(); + } + + @Override + public Locale getLocale() { + return formatter.getLocale(); + } + + @Override + public TimeZone getTimeZone() { + return formatter.getTimeZone(); + } +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/package-info.java new file mode 100644 index 00000000000..3c87d12589e --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/package-info.java @@ -0,0 +1,37 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache license, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the license for the specific language governing permissions and + * limitations under the license. + */ +/** + * Utilities for formatting log event {@link org.apache.logging.log4j.core.time.Instant}s. + *

Internal usage only!

+ *

+ * This package is intended only for internal Log4j usage. + * Log4j users should not use this package! + * This package is not subject to any backward compatibility concerns. + *

+ * + * @since 2.25.0 + */ +@Export +@ExportTo("org.apache.logging.log4j.layout.template.json") +@Version("2.25.0") +@NullMarked +package org.apache.logging.log4j.core.util.internal.instant; + +import aQute.bnd.annotation.jpms.ExportTo; +import org.jspecify.annotations.NullMarked; +import org.osgi.annotation.bundle.Export; +import org.osgi.annotation.versioning.Version; diff --git a/log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/LogEventFixture.java b/log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/LogEventFixture.java index 21daa068190..bc9a36094da 100644 --- a/log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/LogEventFixture.java +++ b/log4j-layout-template-json-test/src/main/java/org/apache/logging/log4j/layout/template/json/LogEventFixture.java @@ -29,18 +29,24 @@ import org.apache.logging.log4j.spi.ThreadContextStack; import org.apache.logging.log4j.util.StringMap; -final class LogEventFixture { +public final class LogEventFixture { private LogEventFixture() {} private static final int TIME_OVERLAPPING_CONSECUTIVE_EVENT_COUNT = 10; - static List createLiteLogEvents(final int logEventCount) { + public static List createLiteLogEvents(final int logEventCount) { + return createLiteLogEvents(logEventCount, TIME_OVERLAPPING_CONSECUTIVE_EVENT_COUNT); + } + + public static List createLiteLogEvents( + final int logEventCount, final int timeOverlappingConsecutiveEventCount) { final List logEvents = new ArrayList<>(logEventCount); final long startTimeMillis = System.currentTimeMillis(); for (int logEventIndex = 0; logEventIndex < logEventCount; logEventIndex++) { final String logEventId = String.valueOf(logEventIndex); - final long logEventTimeMillis = createLogEventTimeMillis(startTimeMillis, logEventIndex); + final long logEventTimeMillis = + createLogEventTimeMillis(startTimeMillis, logEventIndex, timeOverlappingConsecutiveEventCount); final LogEvent logEvent = LogEventFixture.createLiteLogEvent(logEventId, logEventTimeMillis); logEvents.add(logEvent); } @@ -63,24 +69,31 @@ private static LogEvent createLiteLogEvent(final String id, final long timeMilli .build(); } - static List createFullLogEvents(final int logEventCount) { + public static List createFullLogEvents(final int logEventCount) { + return createFullLogEvents(logEventCount, TIME_OVERLAPPING_CONSECUTIVE_EVENT_COUNT); + } + + public static List createFullLogEvents( + final int logEventCount, final int timeOverlappingConsecutiveEventCount) { final List logEvents = new ArrayList<>(logEventCount); final long startTimeMillis = System.currentTimeMillis(); for (int logEventIndex = 0; logEventIndex < logEventCount; logEventIndex++) { final String logEventId = String.valueOf(logEventIndex); - final long logEventTimeMillis = createLogEventTimeMillis(startTimeMillis, logEventIndex); + final long logEventTimeMillis = + createLogEventTimeMillis(startTimeMillis, logEventIndex, timeOverlappingConsecutiveEventCount); final LogEvent logEvent = LogEventFixture.createFullLogEvent(logEventId, logEventTimeMillis); logEvents.add(logEvent); } return logEvents; } - private static long createLogEventTimeMillis(final long startTimeMillis, final int logEventIndex) { + private static long createLogEventTimeMillis( + final long startTimeMillis, final int logEventIndex, final int timeOverlappingConsecutiveEventCount) { // Create event time repeating every certain number of consecutive // events. This is better aligned with the real-world use case and // gives surface to timestamp formatter caches to perform their // magic, which is implemented for almost all layouts. - return startTimeMillis + logEventIndex / TIME_OVERLAPPING_CONSECUTIVE_EVENT_COUNT; + return startTimeMillis + logEventIndex / timeOverlappingConsecutiveEventCount; } private static LogEvent createFullLogEvent(final String id, final long timeMillis) { diff --git a/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/GelfLayoutTest.java b/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/GelfLayoutTest.java index 17ceba6791a..6454c89546a 100644 --- a/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/GelfLayoutTest.java +++ b/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/GelfLayoutTest.java @@ -18,7 +18,6 @@ import static org.apache.logging.log4j.layout.template.json.TestHelpers.serializeUsingLayout; -import java.math.BigDecimal; import java.util.Collection; import java.util.List; import java.util.Map; @@ -94,16 +93,15 @@ private static void verifyTimestamp( final Instant logEventInstant, final Map jsonTemplateLayoutMap, final Map gelfLayoutMap) { - final BigDecimal jsonTemplateLayoutTimestamp = (BigDecimal) jsonTemplateLayoutMap.remove("timestamp"); - final BigDecimal gelfLayoutTimestamp = (BigDecimal) gelfLayoutMap.remove("timestamp"); - final String description = String.format( - "instantEpochSecs=%d.%d, jsonTemplateLayoutTimestamp=%s, gelfLayoutTimestamp=%s", - logEventInstant.getEpochSecond(), - logEventInstant.getNanoOfSecond(), - jsonTemplateLayoutTimestamp, - gelfLayoutTimestamp); - Assertions.assertThat(jsonTemplateLayoutTimestamp.compareTo(gelfLayoutTimestamp)) - .as(description) - .isEqualTo(0); + final Number jsonTemplateLayoutTimestamp = (Number) jsonTemplateLayoutMap.remove("timestamp"); + final Number gelfLayoutTimestamp = (Number) gelfLayoutMap.remove("timestamp"); + Assertions.assertThat(jsonTemplateLayoutTimestamp.doubleValue()) + .as( + "instantEpochSecs=%d.%d, jsonTemplateLayoutTimestamp=%s, gelfLayoutTimestamp=%s", + logEventInstant.getEpochSecond(), + logEventInstant.getNanoOfSecond(), + jsonTemplateLayoutTimestamp, + gelfLayoutTimestamp) + .isEqualTo(gelfLayoutTimestamp.doubleValue()); } } diff --git a/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java b/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java deleted file mode 100644 index 87df6556988..00000000000 --- a/log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatterTest.java +++ /dev/null @@ -1,114 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to you under the Apache License, Version 2.0 - * (the "License"); you may not use this file except in compliance with - * the License. You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -package org.apache.logging.log4j.layout.template.json.util; - -import java.util.Locale; -import java.util.TimeZone; -import org.apache.logging.log4j.Level; -import org.apache.logging.log4j.core.time.MutableInstant; -import org.apache.logging.log4j.core.util.datetime.FastDateFormat; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; -import org.apache.logging.log4j.test.ListStatusListener; -import org.apache.logging.log4j.test.junit.UsingStatusListener; -import org.assertj.core.api.Assertions; -import org.junit.jupiter.api.Test; -import org.junit.jupiter.params.ParameterizedTest; -import org.junit.jupiter.params.provider.CsvSource; - -class InstantFormatterTest { - - @ParameterizedTest - @CsvSource({ - "yyyy-MM-dd'T'HH:mm:ss.SSS" + ",FixedDateFormat", - "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'" + ",FastDateFormat", - "yyyy-MM-dd'T'HH:mm:ss.SSSSSSSSS'Z'" + ",DateTimeFormatter" - }) - void all_internal_implementations_should_be_used(final String pattern, final String className) { - final InstantFormatter formatter = - InstantFormatter.newBuilder().setPattern(pattern).build(); - Assertions.assertThat(formatter.getInternalImplementationClass()) - .asString() - .describedAs("pattern=%s", pattern) - .endsWith("." + className); - } - - @Test - void nanoseconds_should_be_formatted() { - final InstantFormatter formatter = InstantFormatter.newBuilder() - .setPattern("yyyy-MM-dd'T'HH:mm:ss.SSSSSSSSS'Z'") - .setTimeZone(TimeZone.getTimeZone("UTC")) - .build(); - final MutableInstant instant = new MutableInstant(); - instant.initFromEpochSecond(0, 123_456_789); - Assertions.assertThat(formatter.format(instant)).isEqualTo("1970-01-01T00:00:00.123456789Z"); - } - - /** - * Reproduces LOG4J2-3614. - */ - @Test - void FastDateFormat_failures_should_be_handled() { - - // Define a pattern causing `FastDateFormat` to fail. - final String pattern = "ss.nnnnnnnnn"; - final TimeZone timeZone = TimeZone.getTimeZone("UTC"); - final Locale locale = Locale.US; - - // Assert that the pattern is not supported by `FixedDateFormat`. - final FixedDateFormat fixedDateFormat = FixedDateFormat.createIfSupported(pattern, timeZone.getID()); - Assertions.assertThat(fixedDateFormat).isNull(); - - // Assert that the pattern indeed causes a `FastDateFormat` failure. - Assertions.assertThatThrownBy(() -> FastDateFormat.getInstance(pattern, timeZone, locale)) - .isInstanceOf(IllegalArgumentException.class) - .hasMessage("Illegal pattern component: nnnnnnnnn"); - - // Assert that `InstantFormatter` falls back to `DateTimeFormatter`. - final InstantFormatter formatter = InstantFormatter.newBuilder() - .setPattern(pattern) - .setTimeZone(timeZone) - .build(); - Assertions.assertThat(formatter.getInternalImplementationClass()) - .asString() - .endsWith(".DateTimeFormatter"); - - // Assert that formatting works. - final MutableInstant instant = new MutableInstant(); - instant.initFromEpochSecond(0, 123_456_789); - Assertions.assertThat(formatter.format(instant)).isEqualTo("00.123456789"); - } - - @Test - @UsingStatusListener - void FixedFormatter_large_enough_buffer(ListStatusListener listener) { - final String pattern = "yyyy-MM-dd'T'HH:mm:ss,SSSXXX"; - final TimeZone timeZone = TimeZone.getTimeZone("America/Chicago"); - final Locale locale = Locale.ENGLISH; - final InstantFormatter formatter = InstantFormatter.newBuilder() - .setPattern(pattern) - .setTimeZone(timeZone) - .setLocale(locale) - .build(); - - // On this pattern the FixedFormatter used a buffer shorter than necessary, - // which caused exceptions and warnings. - Assertions.assertThat(listener.findStatusData(Level.WARN)).hasSize(0); - Assertions.assertThat(formatter.getInternalImplementationClass()) - .asString() - .endsWith(".FixedDateFormat"); - } -} diff --git a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java index f023f603aa3..1cd3f6bb0db 100644 --- a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java +++ b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/resolver/TimestampResolver.java @@ -18,13 +18,12 @@ import java.util.Locale; import java.util.TimeZone; -import java.util.concurrent.locks.Lock; -import java.util.concurrent.locks.ReentrantLock; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.time.Instant; -import org.apache.logging.log4j.core.time.MutableInstant; +import org.apache.logging.log4j.core.util.internal.instant.InstantFormatter; +import org.apache.logging.log4j.core.util.internal.instant.InstantNumberFormatter; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternFormatter; import org.apache.logging.log4j.layout.template.json.JsonTemplateLayoutDefaults; -import org.apache.logging.log4j.layout.template.json.util.InstantFormatter; import org.apache.logging.log4j.layout.template.json.util.JsonWriter; /** @@ -55,15 +54,14 @@ * rounded = "rounded" -> boolean * * - * If no configuration options are provided, pattern-config is - * employed. There {@link - * JsonTemplateLayoutDefaults#getTimestampFormatPattern()}, {@link - * JsonTemplateLayoutDefaults#getTimeZone()}, {@link - * JsonTemplateLayoutDefaults#getLocale()} are used as defaults for - * pattern, timeZone, and locale, respectively. + *

+ * If no configuration options are provided, pattern-config is employed. + * There {@link JsonTemplateLayoutDefaults#getTimestampFormatPattern()}, {@link JsonTemplateLayoutDefaults#getTimeZone()}, {@link JsonTemplateLayoutDefaults#getLocale()} are used as defaults for pattern, timeZone, and locale, respectively. + *

* - * In epoch-config, millis.nanos, secs.nanos stand - * for the fractional component in nanoseconds. + *

+ * In epoch-config, millis.nanos, secs.nanos stand for the fractional component in nanoseconds. + *

* *

Examples

* @@ -209,109 +207,53 @@ private static EventResolver createResolver(final TemplateResolverConfig config) return epochProvided ? createEpochResolver(config) : createPatternResolver(config); } - private static final class PatternResolverContext { - - private final InstantFormatter formatter; - - private final StringBuilder lastFormattedInstantBuffer = new StringBuilder(); - - private final MutableInstant lastFormattedInstant = new MutableInstant(); - - private PatternResolverContext(final String pattern, final TimeZone timeZone, final Locale locale) { - this.formatter = InstantFormatter.newBuilder() - .setPattern(pattern) - .setTimeZone(timeZone) - .setLocale(locale) - .build(); - lastFormattedInstant.initFromEpochSecond(-1, 0); - } + private static EventResolver createPatternResolver(final TemplateResolverConfig config) { + final String pattern = readPattern(config); + final TimeZone timeZone = readTimeZone(config); + final Locale locale = config.getLocale(new String[] {"pattern", "locale"}); + final InstantFormatter formatter = InstantPatternFormatter.newBuilder() + .setPattern(pattern) + .setTimeZone(timeZone) + .setLocale(locale) + .build(); + return new PatternResolver(formatter); + } - private static PatternResolverContext fromConfig(final TemplateResolverConfig config) { - final String pattern = readPattern(config); - final TimeZone timeZone = readTimeZone(config); - final Locale locale = config.getLocale(new String[] {"pattern", "locale"}); - return new PatternResolverContext(pattern, timeZone, locale); - } + private static String readPattern(final TemplateResolverConfig config) { + final String format = config.getString(new String[] {"pattern", "format"}); + return format != null ? format : JsonTemplateLayoutDefaults.getTimestampFormatPattern(); + } - private static String readPattern(final TemplateResolverConfig config) { - final String format = config.getString(new String[] {"pattern", "format"}); - return format != null ? format : JsonTemplateLayoutDefaults.getTimestampFormatPattern(); + private static TimeZone readTimeZone(final TemplateResolverConfig config) { + final String timeZoneId = config.getString(new String[] {"pattern", "timeZone"}); + if (timeZoneId == null) { + return JsonTemplateLayoutDefaults.getTimeZone(); } - - private static TimeZone readTimeZone(final TemplateResolverConfig config) { - final String timeZoneId = config.getString(new String[] {"pattern", "timeZone"}); - if (timeZoneId == null) { - return JsonTemplateLayoutDefaults.getTimeZone(); - } - boolean found = false; - for (final String availableTimeZone : TimeZone.getAvailableIDs()) { - if (availableTimeZone.equalsIgnoreCase(timeZoneId)) { - found = true; - break; - } - } - if (!found) { - throw new IllegalArgumentException("invalid timestamp time zone: " + config); + boolean found = false; + for (final String availableTimeZone : TimeZone.getAvailableIDs()) { + if (availableTimeZone.equalsIgnoreCase(timeZoneId)) { + found = true; + break; } - return TimeZone.getTimeZone(timeZoneId); } + if (!found) { + throw new IllegalArgumentException("invalid timestamp time zone: " + config); + } + return TimeZone.getTimeZone(timeZoneId); } private static final class PatternResolver implements EventResolver { - private final Lock lock = new ReentrantLock(); - - private final PatternResolverContext patternResolverContext; + private final InstantFormatter formatter; - private PatternResolver(final PatternResolverContext patternResolverContext) { - this.patternResolverContext = patternResolverContext; + private PatternResolver(final InstantFormatter formatter) { + this.formatter = formatter; } @Override public void resolve(final LogEvent logEvent, final JsonWriter jsonWriter) { - lock.lock(); - try { - unsynchronizedResolve(logEvent, jsonWriter); - } finally { - lock.unlock(); - } + jsonWriter.writeString(formatter::formatTo, logEvent.getInstant()); } - - private void unsynchronizedResolve(final LogEvent logEvent, final JsonWriter jsonWriter) { - - // Format timestamp if it doesn't match the last cached one. - final boolean instantMatching = patternResolverContext.formatter.isInstantMatching( - patternResolverContext.lastFormattedInstant, logEvent.getInstant()); - if (!instantMatching) { - - // Format the timestamp. - patternResolverContext.lastFormattedInstantBuffer.setLength(0); - patternResolverContext.lastFormattedInstant.initFrom(logEvent.getInstant()); - patternResolverContext.formatter.format( - patternResolverContext.lastFormattedInstant, patternResolverContext.lastFormattedInstantBuffer); - - // Write the formatted timestamp. - final StringBuilder jsonWriterStringBuilder = jsonWriter.getStringBuilder(); - final int startIndex = jsonWriterStringBuilder.length(); - jsonWriter.writeString(patternResolverContext.lastFormattedInstantBuffer); - - // Cache the written value. - patternResolverContext.lastFormattedInstantBuffer.setLength(0); - patternResolverContext.lastFormattedInstantBuffer.append( - jsonWriterStringBuilder, startIndex, jsonWriterStringBuilder.length()); - - } - - // Write the cached formatted timestamp. - else { - jsonWriter.writeRawString(patternResolverContext.lastFormattedInstantBuffer); - } - } - } - - private static EventResolver createPatternResolver(final TemplateResolverConfig config) { - final PatternResolverContext patternResolverContext = PatternResolverContext.fromConfig(config); - return new PatternResolver(patternResolverContext); } private static EventResolver createEpochResolver(final TemplateResolverConfig config) { @@ -331,119 +273,48 @@ private static EventResolver createEpochResolver(final TemplateResolverConfig co throw new IllegalArgumentException("invalid epoch configuration: " + config); } - private static final class EpochResolutionRecord { - - private static final int MAX_LONG_LENGTH = - String.valueOf(Long.MAX_VALUE).length(); - - private final MutableInstant instant = new MutableInstant(); - - private final char[] resolution = - new char[ /* integral: */MAX_LONG_LENGTH + /* dot: */ 1 + /* fractional: */ MAX_LONG_LENGTH]; - - private int resolutionLength; - - private EpochResolutionRecord() { - instant.initFromEpochSecond(-1, 0); - } - } - - private abstract static class EpochResolver implements EventResolver { - - private final Lock lock = new ReentrantLock(); - - private final EpochResolutionRecord resolutionRecord = new EpochResolutionRecord(); - - @Override - public void resolve(final LogEvent logEvent, final JsonWriter jsonWriter) { - lock.lock(); - try { - unsynchronizedResolve(logEvent, jsonWriter); - } finally { - lock.unlock(); - } - } - - private void unsynchronizedResolve(final LogEvent logEvent, final JsonWriter jsonWriter) { - final Instant logEventInstant = logEvent.getInstant(); - if (logEventInstant.equals(resolutionRecord.instant)) { - jsonWriter.writeRawString(resolutionRecord.resolution, 0, resolutionRecord.resolutionLength); - } else { - resolutionRecord.instant.initFrom(logEventInstant); - final StringBuilder stringBuilder = jsonWriter.getStringBuilder(); - final int startIndex = stringBuilder.length(); - resolve(logEventInstant, jsonWriter); - resolutionRecord.resolutionLength = stringBuilder.length() - startIndex; - stringBuilder.getChars(startIndex, stringBuilder.length(), resolutionRecord.resolution, 0); - } - } - - abstract void resolve(Instant logEventInstant, JsonWriter jsonWriter); - } - - private static final EventResolver EPOCH_NANOS_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - final long nanos = epochNanos(logEventInstant); - jsonWriter.writeNumber(nanos); - } + private static final EventResolver EPOCH_NANOS_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_NANOS.formatTo(buffer, instant); }; - private static final EventResolver EPOCH_MILLIS_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - final StringBuilder jsonWriterStringBuilder = jsonWriter.getStringBuilder(); - final long nanos = epochNanos(logEventInstant); - jsonWriterStringBuilder.append(nanos); - jsonWriterStringBuilder.insert(jsonWriterStringBuilder.length() - 6, '.'); - } + private static final EventResolver EPOCH_MILLIS_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_MILLIS.formatTo(buffer, instant); }; - private static final EventResolver EPOCH_MILLIS_ROUNDED_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - jsonWriter.writeNumber(logEventInstant.getEpochMillisecond()); - } + private static final EventResolver EPOCH_MILLIS_ROUNDED_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_MILLIS_ROUNDED.formatTo(buffer, instant); }; - private static final EventResolver EPOCH_MILLIS_NANOS_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - final long nanos = epochNanos(logEventInstant); - final long fraction = nanos % 1_000_000L; - jsonWriter.writeNumber(fraction); - } + private static final EventResolver EPOCH_MILLIS_NANOS_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_MILLIS_NANOS.formatTo(buffer, instant); }; - private static final EventResolver EPOCH_SECS_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - final StringBuilder jsonWriterStringBuilder = jsonWriter.getStringBuilder(); - final long nanos = epochNanos(logEventInstant); - jsonWriterStringBuilder.append(nanos); - jsonWriterStringBuilder.insert(jsonWriterStringBuilder.length() - 9, '.'); - } + private static final EventResolver EPOCH_SECS_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_SECONDS.formatTo(buffer, instant); }; - private static final EventResolver EPOCH_SECS_ROUNDED_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - jsonWriter.writeNumber(logEventInstant.getEpochSecond()); - } + private static final EventResolver EPOCH_SECS_ROUNDED_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_SECONDS_ROUNDED.formatTo(buffer, instant); }; - private static final EventResolver EPOCH_SECS_NANOS_RESOLVER = new EpochResolver() { - @Override - void resolve(final Instant logEventInstant, final JsonWriter jsonWriter) { - jsonWriter.writeNumber(logEventInstant.getNanoOfSecond()); - } + private static final EventResolver EPOCH_SECS_NANOS_RESOLVER = (logEvent, jsonWriter) -> { + final StringBuilder buffer = jsonWriter.getStringBuilder(); + final Instant instant = logEvent.getInstant(); + InstantNumberFormatter.EPOCH_SECONDS_NANOS.formatTo(buffer, instant); }; - private static long epochNanos(final Instant instant) { - final long nanos = Math.multiplyExact(1_000_000_000L, instant.getEpochSecond()); - return Math.addExact(nanos, instant.getNanoOfSecond()); - } - static String getName() { return "timestamp"; } diff --git a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java index c9a47d1f2c1..4b385da2315 100644 --- a/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java +++ b/log4j-layout-template-json/src/main/java/org/apache/logging/log4j/layout/template/json/util/InstantFormatter.java @@ -37,7 +37,10 @@ * Note that {@link FixedDateFormat} and {@link FastDateFormat} only support * millisecond precision. If the pattern asks for a higher precision, * {@link DateTimeFormatter} will be employed, which is significantly slower. + *

+ * @deprecated Starting with version {@code 2.25.0}, this class is planned to be removed in the next major release. */ +@Deprecated public final class InstantFormatter { private static final StatusLogger LOGGER = StatusLogger.getLogger(); diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java deleted file mode 100644 index 3ad0f039dbb..00000000000 --- a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/DateTimeFormatBenchmark.java +++ /dev/null @@ -1,117 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to you under the Apache License, Version 2.0 - * (the "License"); you may not use this file except in compliance with - * the License. You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -package org.apache.logging.log4j.perf.jmh; - -import java.time.Instant; -import java.time.format.DateTimeFormatter; -import java.util.Arrays; -import java.util.Calendar; -import java.util.Locale; -import java.util.Objects; -import java.util.TimeZone; -import java.util.stream.IntStream; -import org.apache.logging.log4j.core.time.MutableInstant; -import org.apache.logging.log4j.core.util.datetime.FastDatePrinter; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; -import org.openjdk.jmh.annotations.Benchmark; -import org.openjdk.jmh.annotations.Scope; -import org.openjdk.jmh.annotations.State; -import org.openjdk.jmh.infra.Blackhole; - -/** - * Compares {@link MutableInstant} formatting efficiency of - * {@link FastDatePrinter}, {@link FixedDateFormat}, and {@link DateTimeFormatter}. - *

- * The major formatting efficiency is mostly provided by caching, i.e., - * reusing the earlier formatter output if timestamps match. We deliberately - * exclude this optimization, since it is applicable to all formatters. This - * benchmark rather focuses on only and only the formatting efficiency. - */ -@State(Scope.Thread) -public class DateTimeFormatBenchmark { - - /** - * The pattern to be tested. - *

- * Note that neither {@link FastDatePrinter}, nor {@link FixedDateFormat} - * supports nanosecond precision. - */ - private static final String PATTERN = "yyyy-MM-dd'T'HH:mm:ss.SSS"; - - private static final Locale LOCALE = Locale.US; - - private static final TimeZone TIME_ZONE = TimeZone.getTimeZone("UTC"); - - private static final Instant INIT_INSTANT = Instant.parse("2020-05-14T10:44:23.901Z"); - - private static final MutableInstant[] INSTANTS = IntStream.range(0, 1_000) - .mapToObj((final int index) -> { - final MutableInstant instant = new MutableInstant(); - instant.initFromEpochSecond( - Math.addExact(INIT_INSTANT.getEpochSecond(), index), - Math.addExact(INIT_INSTANT.getNano(), index)); - return instant; - }) - .toArray(MutableInstant[]::new); - - private static final Calendar[] CALENDARS = Arrays.stream(INSTANTS) - .map((final MutableInstant instant) -> { - final Calendar calendar = Calendar.getInstance(TIME_ZONE, LOCALE); - calendar.setTimeInMillis(instant.getEpochMillisecond()); - return calendar; - }) - .toArray(Calendar[]::new); - - private static final FastDatePrinter FAST_DATE_PRINTER = new FastDatePrinter(PATTERN, TIME_ZONE, LOCALE) {}; - - private static final FixedDateFormat FIXED_DATE_FORMAT = Objects.requireNonNull( - FixedDateFormat.createIfSupported(PATTERN, TIME_ZONE.getID()), - "couldn't create FixedDateTime for pattern " + PATTERN + " and time zone " + TIME_ZONE.getID()); - - private static final DateTimeFormatter DATE_TIME_FORMATTER = - DateTimeFormatter.ofPattern(PATTERN).withZone(TIME_ZONE.toZoneId()).withLocale(LOCALE); - - private final StringBuilder stringBuilder = new StringBuilder(PATTERN.length() * 2); - - private final char[] charBuffer = new char[stringBuilder.capacity()]; - - @Benchmark - public void fastDatePrinter(final Blackhole blackhole) { - for (final Calendar calendar : CALENDARS) { - stringBuilder.setLength(0); - FAST_DATE_PRINTER.format(calendar, stringBuilder); - blackhole.consume(stringBuilder.length()); - } - } - - @Benchmark - public void fixedDateFormat(final Blackhole blackhole) { - for (final MutableInstant instant : INSTANTS) { - final int length = FIXED_DATE_FORMAT.formatInstant(instant, charBuffer, 0); - blackhole.consume(length); - } - } - - @Benchmark - public void dateTimeFormatter(final Blackhole blackhole) { - for (final MutableInstant instant : INSTANTS) { - stringBuilder.setLength(0); - DATE_TIME_FORMATTER.formatTo(instant, stringBuilder); - blackhole.consume(stringBuilder.length()); - } - } -} diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/InstantFormatBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/InstantFormatBenchmark.java index 6dfe084100d..6cd6de640e2 100644 --- a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/InstantFormatBenchmark.java +++ b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/InstantFormatBenchmark.java @@ -43,6 +43,7 @@ * Benchmarks certain {@link Instant} formatters with various patterns and instant collections. */ @State(Scope.Thread) +@SuppressWarnings("deprecation") public class InstantFormatBenchmark { private static final TimeZone TIME_ZONE = TimeZone.getTimeZone("UTC"); diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/TimeFormatBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/TimeFormatBenchmark.java deleted file mode 100644 index 0a59cb23903..00000000000 --- a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/TimeFormatBenchmark.java +++ /dev/null @@ -1,299 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to you under the Apache License, Version 2.0 - * (the "License"); you may not use this file except in compliance with - * the License. You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -package org.apache.logging.log4j.perf.jmh; - -import java.nio.ByteBuffer; -import java.text.SimpleDateFormat; -import java.util.Calendar; -import java.util.Date; -import java.util.concurrent.TimeUnit; -import org.apache.logging.log4j.core.util.datetime.FastDateFormat; -import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; -import org.openjdk.jmh.annotations.Benchmark; -import org.openjdk.jmh.annotations.BenchmarkMode; -import org.openjdk.jmh.annotations.Mode; -import org.openjdk.jmh.annotations.OutputTimeUnit; -import org.openjdk.jmh.annotations.Scope; -import org.openjdk.jmh.annotations.State; - -/** - * Tests performance of various time format implementation. - */ -@State(Scope.Benchmark) -public class TimeFormatBenchmark { - - ThreadLocal threadLocalSimpleDateFormat = new ThreadLocal<>() { - @Override - protected SimpleDateFormat initialValue() { - return new SimpleDateFormat("HH:mm:ss.SSS"); - } - }; - FastDateFormat fastDateFormat = FastDateFormat.getInstance("HH:mm:ss.SSS"); - FixedDateFormat fixedDateFormat = FixedDateFormat.createIfSupported("ABSOLUTE"); - volatile long midnightToday; - volatile long midnightTomorrow; - - @State(Scope.Thread) - public static class BufferState { - final ByteBuffer buffer = ByteBuffer.allocate(12); - final StringBuilder stringBuilder = new StringBuilder(12); - final char[] charArray = new char[12]; - } - - private long millisSinceMidnight(final long now) { - if (now >= midnightTomorrow) { - midnightToday = calcMidnightMillis(now, 0); - midnightTomorrow = calcMidnightMillis(now, 1); - } - return now - midnightToday; - } - - private long calcMidnightMillis(final long time, final int addDays) { - final Calendar cal = Calendar.getInstance(); - cal.setTimeInMillis(time); - cal.set(Calendar.HOUR_OF_DAY, 0); - cal.set(Calendar.MINUTE, 0); - cal.set(Calendar.SECOND, 0); - cal.set(Calendar.MILLISECOND, 0); - cal.add(Calendar.DATE, addDays); - return cal.getTimeInMillis(); - } - - public static void main(final String[] args) { - System.out.println(new TimeFormatBenchmark().fixedBitFiddlingReuseCharArray(new BufferState())); - System.out.println(new TimeFormatBenchmark().fixedFormatReuseStringBuilder(new BufferState())); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String simpleDateFormat() { - return threadLocalSimpleDateFormat.get().format(new Date()); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String fastDateFormatCreateNewStringBuilder() { - return fastDateFormat.format(new Date()); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String fastDateFormatReuseStringBuilder(final BufferState state) { - state.stringBuilder.setLength(0); - fastDateFormat.format(new Date(), state.stringBuilder); - return new String(state.stringBuilder); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String fixedBitFiddlingReuseCharArray(final BufferState state) { - final int len = formatCharArrayBitFiddling(System.currentTimeMillis(), state.charArray, 0); - return new String(state.charArray, 0, len); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String fixedDateFormatCreateNewCharArray(final BufferState state) { - return fixedDateFormat.format(System.currentTimeMillis()); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String fixedDateFormatReuseCharArray(final BufferState state) { - final int len = fixedDateFormat.format(System.currentTimeMillis(), state.charArray, 0); - return new String(state.charArray, 0, len); - } - - @Benchmark - @BenchmarkMode(Mode.SampleTime) - @OutputTimeUnit(TimeUnit.NANOSECONDS) - public String fixedFormatReuseStringBuilder(final BufferState state) { - state.stringBuilder.setLength(0); - formatStringBuilder(System.currentTimeMillis(), state.stringBuilder); - return new String(state.stringBuilder); - } - - int formatCharArrayBitFiddling(final long time, final char[] buffer, final int pos) { - // Calculate values by getting the ms values first and do then - // shave off the hour minute and second values with multiplications - // and bit shifts instead of simple but expensive divisions. - - // Get daytime in ms which does fit into an int - // int ms = (int) (time % 86400000); - int ms = (int) (millisSinceMidnight(time)); - - // well ... it works - final int hour = (int) (((ms >> 7) * 9773437L) >> 38); - ms -= 3600000 * hour; - - final int minute = (int) (((ms >> 5) * 2290650L) >> 32); - ms -= 60000 * minute; - - final int second = ((ms >> 3) * 67109) >> 23; - ms -= 1000 * second; - - // Hour - // 13/128 is nearly the same as /10 for values up to 65 - int temp = (hour * 13) >> 7; - int p = pos; - buffer[p++] = ((char) (temp + '0')); - - // Do subtract to get remainder instead of doing % 10 - buffer[p++] = ((char) (hour - 10 * temp + '0')); - buffer[p++] = ((char) ':'); - - // Minute - // 13/128 is nearly the same as /10 for values up to 65 - temp = (minute * 13) >> 7; - buffer[p++] = ((char) (temp + '0')); - - // Do subtract to get remainder instead of doing % 10 - buffer[p++] = ((char) (minute - 10 * temp + '0')); - buffer[p++] = ((char) ':'); - - // Second - // 13/128 is nearly the same as /10 for values up to 65 - temp = (second * 13) >> 7; - buffer[p++] = ((char) (temp + '0')); - buffer[p++] = ((char) (second - 10 * temp + '0')); - buffer[p++] = ((char) '.'); - - // Millisecond - // 41/4096 is nearly the same as /100 - temp = (ms * 41) >> 12; - buffer[p++] = ((char) (temp + '0')); - - ms -= 100 * temp; - temp = (ms * 205) >> 11; // 205/2048 is nearly the same as /10 - buffer[p++] = ((char) (temp + '0')); - - ms -= 10 * temp; - buffer[p++] = ((char) (ms + '0')); - return p; - } - - StringBuilder formatStringBuilder(final long time, final StringBuilder buffer) { - // Calculate values by getting the ms values first and do then - // calculate the hour minute and second values divisions. - - // Get daytime in ms which does fit into an int - // int ms = (int) (time % 86400000); - int ms = (int) (millisSinceMidnight(time)); - - final int hours = ms / 3600000; - ms -= 3600000 * hours; - - final int minutes = ms / 60000; - ms -= 60000 * minutes; - - final int seconds = ms / 1000; - ms -= 1000 * seconds; - - // Hour - int temp = hours / 10; - buffer.append((char) (temp + '0')); - - // Do subtract to get remainder instead of doing % 10 - buffer.append((char) (hours - 10 * temp + '0')); - buffer.append((char) ':'); - - // Minute - temp = minutes / 10; - buffer.append((char) (temp + '0')); - - // Do subtract to get remainder instead of doing % 10 - buffer.append((char) (minutes - 10 * temp + '0')); - buffer.append((char) ':'); - - // Second - temp = seconds / 10; - buffer.append((char) (temp + '0')); - buffer.append((char) (seconds - 10 * temp + '0')); - buffer.append((char) '.'); - - // Millisecond - temp = ms / 100; - buffer.append((char) (temp + '0')); - - ms -= 100 * temp; - temp = ms / 10; - buffer.append((char) (temp + '0')); - - ms -= 10 * temp; - buffer.append((char) (ms + '0')); - return buffer; - } - - int formatCharArray(final long time, final char[] buffer, final int pos) { - // Calculate values by getting the ms values first and do then - // calculate the hour minute and second values divisions. - - // Get daytime in ms which does fit into an int - // int ms = (int) (time % 86400000); - int ms = (int) (millisSinceMidnight(time)); - - final int hours = ms / 3600000; - ms -= 3600000 * hours; - - final int minutes = ms / 60000; - ms -= 60000 * minutes; - - final int seconds = ms / 1000; - ms -= 1000 * seconds; - - // Hour - int temp = hours / 10; - int p = pos; - buffer[p++] = ((char) (temp + '0')); - - // Do subtract to get remainder instead of doing % 10 - buffer[p++] = ((char) (hours - 10 * temp + '0')); - buffer[p++] = ((char) ':'); - - // Minute - temp = minutes / 10; - buffer[p++] = ((char) (temp + '0')); - - // Do subtract to get remainder instead of doing % 10 - buffer[p++] = ((char) (minutes - 10 * temp + '0')); - buffer[p++] = ((char) ':'); - - // Second - temp = seconds / 10; - buffer[p++] = ((char) (temp + '0')); - buffer[p++] = ((char) (seconds - 10 * temp + '0')); - buffer[p++] = ((char) '.'); - - // Millisecond - temp = ms / 100; - buffer[p++] = ((char) (temp + '0')); - - ms -= 100 * temp; - temp = ms / 10; - buffer[p++] = ((char) (temp + '0')); - - ms -= 10 * temp; - buffer[p++] = ((char) (ms + '0')); - return p; - } -} diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternDynamicFormatterSequencingBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternDynamicFormatterSequencingBenchmark.java new file mode 100644 index 00000000000..d46c431ea0b --- /dev/null +++ b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternDynamicFormatterSequencingBenchmark.java @@ -0,0 +1,96 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.perf.jmh.instant; + +import java.time.Instant; +import java.time.format.DateTimeFormatter; +import java.time.temporal.TemporalAccessor; +import java.util.Locale; +import java.util.TimeZone; +import java.util.stream.IntStream; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.infra.Blackhole; + +/** + * Compares {@link DateTimeFormatter} efficiency for formatting the {@code ss.SSS} singleton versus formatting the {@code ss}, {@code .}, and {@code SSS} sequence. + * This comparison is influential on the sequence merging strategies of {@code InstantPatternDynamicFormatter}. + */ +@State(Scope.Thread) +public class InstantPatternDynamicFormatterSequencingBenchmark { + + static final Locale LOCALE = Locale.US; + + static final TimeZone TIME_ZONE = TimeZone.getTimeZone("UTC"); + + private static final Instant[] INSTANTS = createInstants(); + + private static Instant[] createInstants() { + final Instant initInstant = Instant.parse("2020-05-14T10:44:23.901Z"); + return IntStream.range(0, 1_000) + .mapToObj((final int index) -> Instant.ofEpochSecond( + Math.addExact(initInstant.getEpochSecond(), index), + Math.addExact(initInstant.getNano(), index))) + .toArray(Instant[]::new); + } + + @FunctionalInterface + private interface Formatter { + + void formatTo(TemporalAccessor instantAccessor, StringBuilder buffer); + } + + private static final Formatter SINGLETON_FORMATTER = + DateTimeFormatter.ofPattern("ss.SSS").withLocale(LOCALE).withZone(TIME_ZONE.toZoneId())::formatTo; + + private static final Formatter SEQUENCED_FORMATTER = new Formatter() { + + private final Formatter[] formatters = { + DateTimeFormatter.ofPattern("ss").withLocale(LOCALE).withZone(TIME_ZONE.toZoneId())::formatTo, + (temporal, appendable) -> appendable.append("."), + DateTimeFormatter.ofPattern("SSS").withLocale(LOCALE).withZone(TIME_ZONE.toZoneId())::formatTo + }; + + @Override + public void formatTo(final TemporalAccessor instantAccessor, final StringBuilder buffer) { + for (Formatter formatter : formatters) { + formatter.formatTo(instantAccessor, buffer); + } + } + }; + + private final StringBuilder buffer = new StringBuilder(); + + @Benchmark + public void singleton(final Blackhole blackhole) { + benchmark(blackhole, SINGLETON_FORMATTER); + } + + @Benchmark + public void sequenced(final Blackhole blackhole) { + benchmark(blackhole, SEQUENCED_FORMATTER); + } + + private void benchmark(final Blackhole blackhole, final Formatter formatter) { + for (final Instant instant : INSTANTS) { + formatter.formatTo(instant, buffer); + blackhole.consume(buffer); + buffer.setLength(0); + } + } +} diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterBenchmark.java new file mode 100644 index 00000000000..18ed205b621 --- /dev/null +++ b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterBenchmark.java @@ -0,0 +1,215 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.perf.jmh.instant; + +import java.time.Instant; +import java.time.format.DateTimeFormatter; +import java.util.Arrays; +import java.util.Calendar; +import java.util.Locale; +import java.util.TimeZone; +import java.util.concurrent.TimeUnit; +import java.util.function.Supplier; +import java.util.stream.IntStream; +import java.util.stream.LongStream; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.apache.logging.log4j.core.util.datetime.FastDatePrinter; +import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternFormatter; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.infra.Blackhole; + +/** + * Compares {@link MutableInstant} formatting efficiency of {@link InstantPatternFormatter}, {@link FastDatePrinter}, {@link FixedDateFormat}, and {@link DateTimeFormatter}. + *

+ * The major formatting efficiency is mostly provided by caching, i.e., reusing the earlier formatter output if timestamps match. + * We deliberately exclude this optimization (by means of always distinct instants), since it is applicable to all formatters. + * This benchmark rather focuses on only and only the formatting efficiency. + *

+ * + * @see InstantPatternFormatterImpactBenchmark for the performance impact of different date & time formatters on a typical layout + */ +@State(Scope.Thread) +@SuppressWarnings("deprecation") +public class InstantPatternFormatterBenchmark { + + static final Locale LOCALE = Locale.US; + + static final TimeZone TIME_ZONE = TimeZone.getTimeZone("UTC"); + + private static final MutableInstant[] INSTANTS = createInstants(); + + private static MutableInstant[] createInstants() { + final Instant initInstant = Instant.parse("2020-05-14T10:44:23.901Z"); + MutableInstant[] instants = IntStream.range(0, 1_000) + .mapToObj((final int index) -> { + final Instant instant = initInstant.plusMillis(index).plusNanos(1); + final MutableInstant mutableInstant = new MutableInstant(); + mutableInstant.initFromEpochSecond(instant.getEpochSecond(), instant.getNano()); + return mutableInstant; + }) + .toArray(MutableInstant[]::new); + validateInstants(instants); + return instants; + } + + @SuppressWarnings("OptionalGetWithoutIsPresent") + static void validateInstants(final I[] instants) { + + // Find the instant offset + final Supplier millisStreamSupplier = () -> + Arrays.stream(instants).mapToLong(org.apache.logging.log4j.core.time.Instant::getEpochMillisecond); + final long minMillis = millisStreamSupplier.get().min().getAsLong(); + final long maxMillis = millisStreamSupplier.get().max().getAsLong(); + final long offMillis = maxMillis - minMillis; + + // Validate for `FixedDateFormat` + if (TimeUnit.DAYS.toMillis(1) <= offMillis) { + final String message = String.format( + "instant samples must be of the same day to exploit the `%s` caching", + FixedDateFormat.class.getSimpleName()); + throw new IllegalStateException(message); + } + + // Validate for `InstantPatternDynamicFormatter` + if (TimeUnit.MINUTES.toMillis(1) <= offMillis) { + final String message = String.format( + "instant samples must be of the same week to exploit the `%s` caching", + InstantPatternFormatter.class.getSimpleName()); + throw new IllegalStateException(message); + } + } + + private static final Formatters DATE_TIME_FORMATTERS = new Formatters("yyyy-MM-dd'T'HH:mm:ss.SSS"); + + private static final Formatters TIME_FORMATTERS = new Formatters("HH:mm:ss.SSS"); + + static final class Formatters { + + private final String pattern; + + final FastDatePrinter fastFormatter; + + final FixedDateFormat fixedFormatter; + + final InstantPatternFormatter instantFormatter; + + final DateTimeFormatter javaFormatter; + + Formatters(final String pattern) { + this.pattern = pattern; + this.fastFormatter = new FastDatePrinter(pattern, TIME_ZONE, LOCALE) {}; + this.fixedFormatter = FixedDateFormat.createIfSupported(pattern, TIME_ZONE.getID()); + if (fixedFormatter == null) { + final String message = String.format( + "couldn't create `%s` for pattern `%s` and time zone `%s`", + FixedDateFormat.class.getSimpleName(), pattern, TIME_ZONE.getID()); + throw new IllegalStateException(message); + } + this.instantFormatter = InstantPatternFormatter.newBuilder() + .setPattern(pattern) + .setLocale(LOCALE) + .setTimeZone(TIME_ZONE) + .setCachingEnabled(false) + .build(); + this.javaFormatter = DateTimeFormatter.ofPattern(pattern) + .withZone(TIME_ZONE.toZoneId()) + .withLocale(LOCALE); + } + } + + private final StringBuilder stringBuilder = + new StringBuilder(Math.max(DATE_TIME_FORMATTERS.pattern.length(), TIME_FORMATTERS.pattern.length()) * 2); + + private final char[] charBuffer = new char[stringBuilder.capacity()]; + + private final Calendar calendar = Calendar.getInstance(TIME_ZONE, LOCALE); + + @Benchmark + public void instantFormatter_dateTime(final Blackhole blackhole) { + instantFormatter(blackhole, DATE_TIME_FORMATTERS.instantFormatter); + } + + @Benchmark + public void instantFormatter_time(final Blackhole blackhole) { + instantFormatter(blackhole, TIME_FORMATTERS.instantFormatter); + } + + private void instantFormatter(final Blackhole blackhole, final InstantPatternFormatter formatter) { + for (final MutableInstant instant : INSTANTS) { + stringBuilder.setLength(0); + formatter.formatTo(stringBuilder, instant); + blackhole.consume(stringBuilder.length()); + } + } + + @Benchmark + public void fastFormatter_dateTime(final Blackhole blackhole) { + fastFormatter(blackhole, DATE_TIME_FORMATTERS.fastFormatter); + } + + @Benchmark + public void fastFormatter_time(final Blackhole blackhole) { + fastFormatter(blackhole, TIME_FORMATTERS.fastFormatter); + } + + private void fastFormatter(final Blackhole blackhole, final FastDatePrinter formatter) { + for (final MutableInstant instant : INSTANTS) { + stringBuilder.setLength(0); + calendar.setTimeInMillis(instant.getEpochMillisecond()); + formatter.format(calendar, stringBuilder); + blackhole.consume(stringBuilder.length()); + } + } + + @Benchmark + public void fixedFormatter_dateTime(final Blackhole blackhole) { + fixedFormatter(blackhole, DATE_TIME_FORMATTERS.fixedFormatter); + } + + @Benchmark + public void fixedFormatter_time(final Blackhole blackhole) { + fixedFormatter(blackhole, DATE_TIME_FORMATTERS.fixedFormatter); + } + + private void fixedFormatter(final Blackhole blackhole, final FixedDateFormat formatter) { + for (final MutableInstant instant : INSTANTS) { + final int length = formatter.formatInstant(instant, charBuffer, 0); + blackhole.consume(length); + } + } + + @Benchmark + public void javaFormatter_dateTime(final Blackhole blackhole) { + javaFormatter(blackhole, DATE_TIME_FORMATTERS.javaFormatter); + } + + @Benchmark + public void javaFormatter_time(final Blackhole blackhole) { + javaFormatter(blackhole, TIME_FORMATTERS.javaFormatter); + } + + private void javaFormatter(final Blackhole blackhole, final DateTimeFormatter formatter) { + for (final MutableInstant instant : INSTANTS) { + stringBuilder.setLength(0); + formatter.formatTo(instant, stringBuilder); + blackhole.consume(stringBuilder.length()); + } + } +} diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterImpactBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterImpactBenchmark.java new file mode 100644 index 00000000000..292d1f041a9 --- /dev/null +++ b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/instant/InstantPatternFormatterImpactBenchmark.java @@ -0,0 +1,187 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.perf.jmh.instant; + +import static org.apache.logging.log4j.perf.jmh.instant.InstantPatternFormatterBenchmark.validateInstants; + +import java.time.format.DateTimeFormatter; +import java.util.Calendar; +import java.util.List; +import java.util.function.BiFunction; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.config.NullConfiguration; +import org.apache.logging.log4j.core.layout.PatternLayout; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.time.MutableInstant; +import org.apache.logging.log4j.core.util.datetime.FastDatePrinter; +import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; +import org.apache.logging.log4j.core.util.internal.instant.InstantPatternFormatter; +import org.apache.logging.log4j.layout.template.json.LogEventFixture; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.infra.Blackhole; + +/** + * Benchmarks the impact of different date & time formatters on a typical layout. + * + * @see InstantPatternFormatterBenchmark for isolated benchmarks of date & time formatters + */ +@State(Scope.Thread) +@SuppressWarnings("deprecation") +public class InstantPatternFormatterImpactBenchmark { + + private static final List LITE_LOG_EVENTS = createLogEvents(LogEventFixture::createLiteLogEvents); + + private static final List FULL_LOG_EVENTS = createLogEvents(LogEventFixture::createFullLogEvents); + + private static List createLogEvents(final BiFunction> supplier) { + final int logEventCount = 1_000; + final List logEvents = supplier.apply( + logEventCount, + // Avoid overlapping instants to ensure the impact of date & time formatting at event encoding: + 1); + final Instant[] instants = logEvents.stream().map(LogEvent::getInstant).toArray(Instant[]::new); + validateInstants(instants); + return logEvents; + } + + private static final PatternLayout LAYOUT = PatternLayout.newBuilder() + .withConfiguration(new NullConfiguration()) + // Use a typical pattern *without* a date & time converter! + .withPattern("[%t] %p %-40.40c{1.} %notEmpty{%x }- %m%n") + .withAlwaysWriteExceptions(true) + .build(); + + private static final InstantPatternFormatterBenchmark.Formatters FORMATTERS = + new InstantPatternFormatterBenchmark.Formatters("yyyy-MM-dd'T'HH:mm:ss.SSS"); + + private final StringBuilder stringBuilder = new StringBuilder(1_1024 * 16); + + private final char[] charBuffer = new char[stringBuilder.capacity()]; + + private final Calendar calendar = + Calendar.getInstance(InstantPatternFormatterBenchmark.TIME_ZONE, InstantPatternFormatterBenchmark.LOCALE); + + @Benchmark + public void fastFormatter_lite(final Blackhole blackhole) { + fastFormatter(blackhole, LITE_LOG_EVENTS, FORMATTERS.fastFormatter); + } + + @Benchmark + public void fastFormatter_full(final Blackhole blackhole) { + fastFormatter(blackhole, FULL_LOG_EVENTS, FORMATTERS.fastFormatter); + } + + private void fastFormatter( + final Blackhole blackhole, final List logEvents, final FastDatePrinter formatter) { + // noinspection ForLoopReplaceableByForEach (avoid iterator allocation) + for (int logEventIndex = 0; logEventIndex < logEvents.size(); logEventIndex++) { + + // 1. Encode event + final LogEvent logEvent = logEvents.get(logEventIndex); + stringBuilder.setLength(0); + LAYOUT.serialize(logEvent, stringBuilder); + + // 2. Encode date & time + calendar.setTimeInMillis(logEvent.getInstant().getEpochMillisecond()); + formatter.format(calendar, stringBuilder); + blackhole.consume(stringBuilder.length()); + } + } + + @Benchmark + public void fixedFormatter_lite(final Blackhole blackhole) { + fixedFormatter(blackhole, LITE_LOG_EVENTS, FORMATTERS.fixedFormatter); + } + + @Benchmark + public void fixedFormatter_full(final Blackhole blackhole) { + fixedFormatter(blackhole, FULL_LOG_EVENTS, FORMATTERS.fixedFormatter); + } + + private void fixedFormatter( + final Blackhole blackhole, final List logEvents, final FixedDateFormat formatter) { + // noinspection ForLoopReplaceableByForEach (avoid iterator allocation) + for (int logEventIndex = 0; logEventIndex < logEvents.size(); logEventIndex++) { + + // 1. Encode event + final LogEvent logEvent = logEvents.get(logEventIndex); + stringBuilder.setLength(0); + LAYOUT.serialize(logEvent, stringBuilder); + + // 2. Encode date & time + final MutableInstant instant = (MutableInstant) logEvent.getInstant(); + final int length = formatter.formatInstant(instant, charBuffer, 0); + blackhole.consume(length); + } + } + + @Benchmark + public void instantFormatter_lite(final Blackhole blackhole) { + instantFormatter(blackhole, LITE_LOG_EVENTS, FORMATTERS.instantFormatter); + } + + @Benchmark + public void instantFormatter_full(final Blackhole blackhole) { + instantFormatter(blackhole, FULL_LOG_EVENTS, FORMATTERS.instantFormatter); + } + + private void instantFormatter( + final Blackhole blackhole, final List logEvents, final InstantPatternFormatter formatter) { + // noinspection ForLoopReplaceableByForEach (avoid iterator allocation) + for (int logEventIndex = 0; logEventIndex < logEvents.size(); logEventIndex++) { + + // 1. Encode event + final LogEvent logEvent = logEvents.get(logEventIndex); + stringBuilder.setLength(0); + LAYOUT.serialize(logEvent, stringBuilder); + + // 2. Encode date & time + final MutableInstant instant = (MutableInstant) logEvent.getInstant(); + formatter.formatTo(stringBuilder, instant); + blackhole.consume(stringBuilder.length()); + } + } + + @Benchmark + public void javaFormatter_lite(final Blackhole blackhole) { + javaFormatter(blackhole, LITE_LOG_EVENTS, FORMATTERS.javaFormatter); + } + + @Benchmark + public void javaFormatter_full(final Blackhole blackhole) { + javaFormatter(blackhole, FULL_LOG_EVENTS, FORMATTERS.javaFormatter); + } + + private void javaFormatter( + final Blackhole blackhole, final List logEvents, final DateTimeFormatter formatter) { + // noinspection ForLoopReplaceableByForEach (avoid iterator allocation) + for (int logEventIndex = 0; logEventIndex < logEvents.size(); logEventIndex++) { + + // 1. Encode event + final LogEvent logEvent = logEvents.get(logEventIndex); + stringBuilder.setLength(0); + LAYOUT.serialize(logEvent, stringBuilder); + + // 2. Encode date & time + final MutableInstant instant = (MutableInstant) logEvent.getInstant(); + formatter.formatTo(instant, stringBuilder); + blackhole.consume(stringBuilder.length()); + } + } +} diff --git a/src/changelog/.2.x.x/.release-notes.adoc.ftl b/src/changelog/.2.x.x/.release-notes.adoc.ftl index 47b4447337a..ce8c2df4033 100644 --- a/src/changelog/.2.x.x/.release-notes.adoc.ftl +++ b/src/changelog/.2.x.x/.release-notes.adoc.ftl @@ -38,6 +38,13 @@ This effectively helped with fixing some bugs by matching the feature parity of Additionally, rendered stack traces are ensured to be prefixed with a newline, which used to be a whitespace in earlier versions. The support for the `\{ansi}` option in exception converters is removed too. +[#release-notes-2-25-0-instant-format] +=== Date & time formatting + +Historically, Log4j contains custom date & time formatting utilities for performance reasons, i.e., link:javadoc/log4j-core/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.html[`FixedDateFormat`] and link:javadoc/log4j-core/org/apache/logging/log4j/core/util/datetime/FastDateFormat.html[`FastDateFormat`]. +These have been deprecated for removal in favor of Java's https://docs.oracle.com/javase/{java-target-version}/docs/api/java/time/format/DateTimeFormatter.html[`DateTimeFormatter`]. +After upgrading, if you experience any date & time formatting problems (in particular, related with the usage of `n` and `x` directives), please {logging-services-url}/support.html#issues[submit an issue ticket] – as a temporary workaround, you can set xref:manual/systemproperties.adoc#log4j2.instant.formatter[the `log4j2.instant.formatter` property] to `legacy` to switch to the old behaviour. + === ANSI support on Windows Since 2017, Windows 10 and newer have offered native support for ANSI escapes. diff --git a/src/changelog/.2.x.x/2936_deprecate_AbstractLogger_checkMessageFactory.xml b/src/changelog/.2.x.x/2936_deprecate_AbstractLogger_checkMessageFactory.xml index e72a33566a4..d57d4d14282 100644 --- a/src/changelog/.2.x.x/2936_deprecate_AbstractLogger_checkMessageFactory.xml +++ b/src/changelog/.2.x.x/2936_deprecate_AbstractLogger_checkMessageFactory.xml @@ -4,5 +4,5 @@ xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" type="deprecated"> - Deprecate `AbstractLogger.checkMessageFactory()`, since all created `Logger`s are already `MessageFactory`-namespaced + Deprecate `AbstractLogger.checkMessageFactory()`, since all created ``Logger``s are already `MessageFactory`-namespaced diff --git a/src/changelog/.2.x.x/3121_deprecate_FixedDateFormat.xml b/src/changelog/.2.x.x/3121_deprecate_FixedDateFormat.xml new file mode 100644 index 00000000000..f6c318a25f4 --- /dev/null +++ b/src/changelog/.2.x.x/3121_deprecate_FixedDateFormat.xml @@ -0,0 +1,8 @@ + + + + Deprecated `FixedDateTime`, `FastDateTime`, and supporting classes + diff --git a/src/changelog/.2.x.x/3121_instant_format.xml b/src/changelog/.2.x.x/3121_instant_format.xml new file mode 100644 index 00000000000..271c3c3dd7a --- /dev/null +++ b/src/changelog/.2.x.x/3121_instant_format.xml @@ -0,0 +1,9 @@ + + + + + Switch to using Java's `DateTimeFormatter` for date & time formatting of log event instants + diff --git a/src/changelog/.index.adoc.ftl b/src/changelog/.index.adoc.ftl index b71f9905f31..24c1ef38957 100644 --- a/src/changelog/.index.adoc.ftl +++ b/src/changelog/.index.adoc.ftl @@ -37,7 +37,7 @@ :page-toclevels: 1 [#release-notes] -= Release Notes += Release notes <#list releases as release><#if release.changelogEntryCount gt 0> include::_release-notes/${release.version}.adoc[] diff --git a/src/changelog/2.23.1/fix_StatusLogger_instant_formatting.xml b/src/changelog/2.23.1/fix_StatusLogger_instant_formatting.xml index 4b965ca3c09..39d948505ac 100644 --- a/src/changelog/2.23.1/fix_StatusLogger_instant_formatting.xml +++ b/src/changelog/2.23.1/fix_StatusLogger_instant_formatting.xml @@ -5,9 +5,7 @@ type="fixed"> - Add - xref:manual/statusLogger.adoc#log4j2.statusLoggerDateFormatZone[`log4j2.statusLoggerDateFormatZone`] - system property to set the time-zone `StatusLogger` uses to format `java.time.Instant`. + Add xref:manual/status-logger.adoc#log4j2.statusLoggerDateFormatZone[`log4j2.statusLoggerDateFormatZone`] system property to set the time-zone `StatusLogger` uses to format `java.time.Instant`. Without this, formatting patterns accessing to time-zone-specific fields (e.g., year-of-era) cause failures. diff --git a/src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc b/src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc index 49723986482..b2067b95cba 100644 --- a/src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/pattern-layout.adoc @@ -385,7 +385,7 @@ See xref:manual/layouts.adoc#LocationInformation[this section of the layouts pag [#converter-date] ==== Date -Outputs the date of the log event +Outputs the instant of the log event .link:../javadoc/log4j-core/org/apache/logging/log4j/core/pattern/DatePatternConverter.html[`DatePatternConverter`] specifier grammar [source,text] @@ -394,7 +394,7 @@ d{pattern}[{timezone}] date{pattern}[{timezone}] ---- -The date conversion specifier may be followed by a set of braces containing a date and time pattern string per https://docs.oracle.com/javase/{java-target-version}/docs/api/java/text/SimpleDateFormat.html[`SimpleDateFormat`]. +The date conversion specifier may be followed by a set of braces containing a date and time formatting pattern per https://docs.oracle.com/javase/{java-target-version}/docs/api/java/time/format/DateTimeFormatter.html[`DateTimeFormatter`]. The predefined _named_ formats are: [%header,cols="2m,3m"] @@ -448,8 +448,8 @@ The predefined _named_ formats are: |1351866842781 |=== -You can also use a set of braces containing a time zone id per https://docs.oracle.com/javase/{java-target-version}/docs/api/java/util/TimeZone.html#getTimeZone(java.lang.String)[`java.util.TimeZone#getTimeZone(String)`]. -If no date format specifier is given then the `DEFAULT` format is used. +You can also use a set of braces containing a time zone id per https://docs.oracle.com/javase/{java-target-version}/docs/api/java/util/TimeZone.html#getTimeZone(java.lang.String)[`TimeZone#getTimeZone(String)`]. +If no date format specifier is given, then the `DEFAULT` format is used. You can also define custom date formats, see following examples: @@ -461,36 +461,19 @@ You can also define custom date formats, see following examples: |%d{HH:mm:ss,SSS} |14:34:02,123 -|%d{HH:mm:ss,nnnn} to %d{HH:mm:ss,nnnnnnnnn} -|14:34:02,1234 to 14:34:02,123456789 - -|%d{dd MMM yyyy HH:mm:ss,SSS} -|02 Nov 2012 14:34:02,123 - -|%d{dd MMM yyyy HH:mm:ss,nnnn} to %d{dd MMM yyyy HH:mm:ss,nnnnnnnnn} -|02 Nov 2012 14:34:02,1234 to 02 Nov 2012 14:34:02,123456789 - -|%d{HH:mm:ss}{GMT+0} -|18:34:02 +|%d{yyyy-mm-dd'T'HH:mm:ss.SSS'Z'}\{UTC} +|2012-11-02T14:34:02.123Z |=== -`%d\{UNIX}` outputs the UNIX time in seconds. -`%d\{UNIX_MILLIS}` outputs the UNIX time in milliseconds. -The `UNIX` time is the difference – in seconds for `UNIX` and in milliseconds for `UNIX_MILLIS` – between the current time and 1970-01-01 00:00:00 (UTC). -While the time unit is milliseconds, the granularity depends on the platform. -This is an efficient way to output the event time because only a conversion from `long` to `String` takes place, there is no `Date` formatting involved. - -There is also limited support for timestamps more precise than milliseconds when running on Java 9 or later. -Note that not all -https://docs.oracle.com/javase/{java-target-version}/docs/api/java/time/format/DateTimeFormatter.html[`DateTimeFormatter`] -formats are supported. -Only timestamps in the formats mentioned in the table above may use the _nano-of-second_ pattern letter `n` instead of the _fraction-of-second_ pattern letter `S`. +`%d\{UNIX}` outputs the epoch time in seconds, i.e., the difference in seconds between the current time and 1970-01-01 00:00:00 (UTC). +`%d\{UNIX_MILLIS}` outputs the epoch time in milliseconds. +Note that the granularity of the sub-second formatters depends on the platform. Users may revert to a millisecond-precision clock when running on Java 9 by setting xref:manual/systemproperties.adoc#log4j2.clock[the `log4j2.clock` system property] to `SystemMillisClock`. [WARNING] ==== -Only named date formats (`DEFAULT`, `ISO8601`, `UNIX`, `UNIX_MILLIS`, etc.) are garbage-free. +Except `UNIX` and `UNIX_MILLIS` named patterns, the rest of the date & time formatters are not garbage-free. ==== [#converter-encode] diff --git a/src/site/antora/modules/ROOT/partials/manual/systemproperties/properties-log4j-core-misc.adoc b/src/site/antora/modules/ROOT/partials/manual/systemproperties/properties-log4j-core-misc.adoc index 8ac34f1101d..beae1c22810 100644 --- a/src/site/antora/modules/ROOT/partials/manual/systemproperties/properties-log4j-core-misc.adoc +++ b/src/site/antora/modules/ROOT/partials/manual/systemproperties/properties-log4j-core-misc.adoc @@ -251,6 +251,20 @@ link:../javadoc/log4j-api/org/apache/logging/log4j/message/FlowMessageFactory.ht implementation to be used by all loggers. // end::flow-tracing[] +[id=log4j2.instant.formatter] +== `log4j2.instant.formatter` + +[cols="1h,5"] +|=== +| Env. variable | `LOG4J_INSTANT_FORMATTER` +| Type | `String` +|=== + +Configures the date & time formatter used for log event instants. +The following values are accepted: + +`legacy`:: Enables the usage of legacy formatters (i.e., link:javadoc/log4j-core/org/apache/logging/log4j/core/util/datetime/FixedDateFormat.html[`FixedDateFormat`] and link:javadoc/log4j-core/org/apache/logging/log4j/core/util/datetime/FastDateFormat.html[`FastDateFormat`]) + [id=log4j2.loggerContextStacktraceOnStart] == `log4j2.loggerContextStacktraceOnStart`