You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "ASF subversion and git services (Jira)" <ji...@apache.org> on 2021/08/24 20:23:00 UTC
[jira] [Commented] (LOG4J2-1151) Performance improvement: backport
fast Java 8 ISO-8859-1 String to byte[] encoder to AbstractStringLayout
[ https://issues.apache.org/jira/browse/LOG4J2-1151?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17404039#comment-17404039 ]
ASF subversion and git services commented on LOG4J2-1151:
---------------------------------------------------------
Commit 1e611c2e191a3f05850aa4f3118eba50b2061976 in logging-log4j2's branch refs/heads/release-2.x from Carter Kozak
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=1e611c2 ]
LOG4J2-1151: Prefer `string.getBytes(Charset)` over `string.getBytes(String)`
Rerunning the benchmarks on modern java (in this case java 16,
however many optimizations are available in java 11 due to the
compact string optimizations) shows that the previous assumptions
no longer hold true:
```
Benchmark Mode Cnt Score Error Units
StringEncodingBenchmark.defaultStringGetBytes sample 299799 51.904 ± 1.399 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.00 sample 24.000 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.50 sample 46.000 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.90 sample 58.000 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.95 sample 61.000 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.99 sample 84.000 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.999 sample 406.200 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p0.9999 sample 15456.320 ns/op
StringEncodingBenchmark.defaultStringGetBytes:defaultStringGetBytes·p1.00 sample 27936.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet sample 308499 43.115 ± 1.269 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.00 sample 24.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.50 sample 37.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.90 sample 49.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.95 sample 56.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.99 sample 77.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.999 sample 411.500 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p0.9999 sample 15381.600 ns/op
StringEncodingBenchmark.defaultStringGetBytesCharSet:defaultStringGetBytesCharSet·p1.00 sample 19296.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesString sample 193869 63.425 ± 2.415 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.00 sample 33.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.50 sample 55.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.90 sample 66.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.95 sample 69.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.99 sample 89.000 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.999 sample 845.700 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p0.9999 sample 15817.808 ns/op
StringEncodingBenchmark.defaultStringGetBytesString:defaultStringGetBytesString·p1.00 sample 16320.000 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte sample 315863 55.002 ± 1.274 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.00 sample 35.000 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.50 sample 48.000 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.90 sample 62.000 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.95 sample 69.000 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.99 sample 78.000 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.999 sample 290.136 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p0.9999 sample 15629.235 ns/op
StringEncodingBenchmark.iso8859_1CustomCastToByte:iso8859_1CustomCastToByte·p1.00 sample 16272.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8 sample 203423 74.947 ± 2.029 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.00 sample 51.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.50 sample 66.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.90 sample 80.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.95 sample 82.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.99 sample 90.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.999 sample 425.880 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p0.9999 sample 15680.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8:iso8859_1CustomPortedJDK8·p1.00 sample 25312.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray sample 249565 98.996 ± 2.026 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.00 sample 75.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.50 sample 91.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.90 sample 100.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.95 sample 102.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.99 sample 130.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.999 sample 378.434 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p0.9999 sample 15968.000 ns/op
StringEncodingBenchmark.iso8859_1CustomPortedJDK8CopyArray:iso8859_1CustomPortedJDK8CopyArray·p1.00 sample 17056.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast sample 210096 68.452 ± 1.793 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.00 sample 43.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.50 sample 66.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.90 sample 71.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.95 sample 72.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.99 sample 82.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.999 sample 281.903 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p0.9999 sample 15632.000 ns/op
StringEncodingBenchmark.iso8859_1CustomVerifyAndCast:iso8859_1CustomVerifyAndCast·p1.00 sample 16176.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder sample 200539 404.110 ± 62.046 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.00 sample 334.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.50 sample 366.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.90 sample 387.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.95 sample 393.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.99 sample 449.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.999 sample 10432.000 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p0.9999 sample 16159.136 ns/op
StringEncodingBenchmark.iso8859_1Encoder:iso8859_1Encoder·p1.00 sample 3776512.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet sample 191618 37.300 ± 1.661 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.00 sample 21.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.50 sample 29.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.90 sample 42.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.95 sample 46.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.99 sample 56.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.999 sample 432.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p0.9999 sample 15443.048 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesCharSet:iso8859_1StringGetBytesCharSet·p1.00 sample 16160.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString sample 324805 44.331 ± 1.504 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.00 sample 25.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.50 sample 39.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.90 sample 48.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.95 sample 52.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.99 sample 84.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.999 sample 391.000 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p0.9999 sample 15609.552 ns/op
StringEncodingBenchmark.iso8859_1StringGetBytesString:iso8859_1StringGetBytesString·p1.00 sample 58368.000 ns/op
StringEncodingBenchmark.shiftJisEncoder sample 295798 519.145 ± 40.724 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.00 sample 455.000 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.50 sample 487.000 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.90 sample 513.000 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.95 sample 521.000 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.99 sample 590.000 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.999 sample 5011.256 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p0.9999 sample 16342.722 ns/op
StringEncodingBenchmark.shiftJisEncoder:shiftJisEncoder·p1.00 sample 3653632.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet sample 291714 86.313 ± 1.686 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.00 sample 60.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.50 sample 74.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.90 sample 84.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.95 sample 93.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.99 sample 368.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.999 sample 978.570 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p0.9999 sample 15904.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesCharSet:shiftJisStringGetBytesCharSet·p1.00 sample 16800.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString sample 296544 45.989 ± 1.286 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.00 sample 28.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.50 sample 42.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.90 sample 48.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.95 sample 50.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.99 sample 60.000 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.999 sample 378.455 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p0.9999 sample 15573.528 ns/op
StringEncodingBenchmark.shiftJisStringGetBytesString:shiftJisStringGetBytesString·p1.00 sample 16416.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet sample 211373 70.209 ± 2.050 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.00 sample 48.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.50 sample 61.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.90 sample 74.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.95 sample 75.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.99 sample 86.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.999 sample 271.626 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p0.9999 sample 15840.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesCharSet:usAsciiStringGetBytesCharSet·p1.00 sample 19584.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString sample 345053 79.109 ± 14.984 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.00 sample 60.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.50 sample 68.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.90 sample 83.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.95 sample 87.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.99 sample 91.000 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.999 sample 156.946 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p0.9999 sample 15527.395 ns/op
StringEncodingBenchmark.usAsciiStringGetBytesString:usAsciiStringGetBytesString·p1.00 sample 1566720.000 ns/op
```
> Performance improvement: backport fast Java 8 ISO-8859-1 String to byte[] encoder to AbstractStringLayout
> ---------------------------------------------------------------------------------------------------------
>
> Key: LOG4J2-1151
> URL: https://issues.apache.org/jira/browse/LOG4J2-1151
> Project: Log4j 2
> Issue Type: Improvement
> Components: Layouts
> Affects Versions: 2.4
> Reporter: Remko Popma
> Assignee: Remko Popma
> Priority: Major
> Fix For: 2.4.1
>
>
> Java 8 made large improvements to String encoding performance for all character sets. Especially for the ISO8859_1 encoding, Java 8 introduced logic that simply casts each char in the array to a byte, giving a huge performance increase.
> This ticket proposes to backport that logic into AbstractStringLayout to get the same performance in Java 7.
> Focussing on the results for ISO8859_1:
> {quote}
> Java 7 String.getBytes(): ~200-300 ns/op
> Java 8 String.getBytes(): ~70-80 ns/op
> Custom logic: ~90 ns/op (on both Java 7 and 8)
> {quote}
> Benchmarks below are with a representative message string of 100 characters, on 64 bit Windows 10, Dual Intel Core i5-3317U @1.70GHz with hyperthreading on (4 cores).
> *jdk 1.8.0_60 (64 bit Hotspot)*
> {noformat}
> Benchmark Mode Samples Score Error Units
> o.a.l.l.p.j.StringEncodingBenchmark.customIso8859_1 sample 156848 94.014 ± 2.362 ns/op <- custom
> o.a.l.l.p.j.StringEncodingBenchmark.encoderIso8859_1 sample 103773 859.529 ± 27.461 ns/op
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytes sample 125785 363.129 ± 17.674 ns/op
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesCharSet88591 sample 117191 72.606 ± 2.771 ns/op <- variation 1
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesCharSetShiftJIS sample 102914 452.721 ± 21.274 ns/op
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesString88591 sample 181547 79.653 ± 1.735 ns/op <- variation 2
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesStringShiftJIS sample 125817 354.961 ± 4.072 ns/op
> {noformat}
> *jdk 1.7.0_55 (64 bit Hotspot)*
> {noformat}
> Benchmark Mode Samples Score Error Units
> o.a.l.l.p.j.StringEncodingBenchmark.customIso8859_1 sample 148456 93.248 ± 2.193 ns/op <- custom
> o.a.l.l.p.j.StringEncodingBenchmark.encoderIso8859_1 sample 176198 516.731 ± 24.054 ns/op
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytes sample 121660 731.530 ± 27.116 ns/op
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesCharSet88591 sample 99636 234.709 ± 3.234 ns/op <- variation 1
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesCharSetShiftJIS sample 125754 1401.008 ± 25.385 ns/op
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesString88591 sample 147124 316.411 ± 21.454 ns/op <- variation 2
> o.a.l.l.p.j.StringEncodingBenchmark.stringGetBytesStringShiftJIS sample 114733 808.315 ± 27.177 ns/op
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)