Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Improve SimpleJsonEncoder.escapeString memory usage #61

Merged
merged 1 commit into from
May 19, 2021

Conversation

fabiojb
Copy link
Contributor

@fabiojb fabiojb commented May 7, 2021

write String slices instead of single chars to the Writer. Iterate over the string to be escaped and write a new slice every time a char needs to be escaped.

@fabiojb
Copy link
Contributor Author

fabiojb commented May 7, 2021

I also created and ran a Java microbenchmark:

Before:

Benchmark                                          Mode  Cnt       Score       Error   Units
Benchmak.testEncode                               thrpt   10  231654,956 ± 39245,086   ops/s
Benchmak.testEncode:·gc.alloc.rate                thrpt   10    2982,905 ±   484,834  MB/sec
Benchmak.testEncode:·gc.alloc.rate.norm           thrpt   10   14184,808 ±    98,620    B/op
Benchmak.testEncode:·gc.churn.G1_Eden_Space       thrpt   10    2878,642 ±   506,329  MB/sec
Benchmak.testEncode:·gc.churn.G1_Eden_Space.norm  thrpt   10   13678,036 ±   318,446    B/op
Benchmak.testEncode:·gc.churn.G1_Old_Gen          thrpt   10      49,120 ±     0,249  MB/sec
Benchmak.testEncode:·gc.churn.G1_Old_Gen.norm     thrpt   10     236,215 ±    41,114    B/op
Benchmak.testEncode:·gc.count                     thrpt   10     334,000              counts
Benchmak.testEncode:·gc.time                      thrpt   10     451,000                  ms

After:

Benchmark                                          Mode  Cnt       Score       Error   Units
Benchmak.testEncode                               thrpt   10  645469,842 ± 12113,391   ops/s
Benchmak.testEncode:·gc.alloc.rate                thrpt   10    2716,148 ±    43,627  MB/sec
Benchmak.testEncode:·gc.alloc.rate.norm           thrpt   10    4633,482 ±    12,607    B/op
Benchmak.testEncode:·gc.churn.G1_Eden_Space       thrpt   10    2356,656 ±   253,340  MB/sec
Benchmak.testEncode:·gc.churn.G1_Eden_Space.norm  thrpt   10    4019,902 ±   416,759    B/op
Benchmak.testEncode:·gc.churn.G1_Old_Gen          thrpt   10     401,142 ±    83,690  MB/sec
Benchmak.testEncode:·gc.churn.G1_Old_Gen.norm     thrpt   10     684,139 ±   139,178    B/op
Benchmak.testEncode:·gc.count                     thrpt   10      71,000              counts
Benchmak.testEncode:·gc.time                      thrpt   10     217,000                  ms

Is notable the reduced GC count and time, and increased throughput, almost 3x

Copy link
Owner

@osiegmar osiegmar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for your contribution! Please see my comments.

}
if (ch < ' ') {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why don't you keep this if in the switch (default) block?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The code looked simpler that way, but I didn't realize that it would add an unnecessary if condition check when the current char is an escaped char. Moved the if back to the default block

escaped = escapeCharacter(ch);
}
if (escaped != null) {
writer.append(str.substring(lastCopyIndex, currentIndex));
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As this method already gets the char array representation of str (via str.toCharArray()), I assume that using java.io.Writer#write(char[], int, int) would be a lot faster than slicing the string. Could you check this?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changed to Writer.write instead of append, and it performed way better than the first changes. Also performed better than the upstream version of this code, I will put the reports on the comments bellow

currentIndex++;
}
if (lastCopyIndex != currentIndex) {
writer.append(str.substring(lastCopyIndex));
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

...same here java.io.Writer#write(char[], int, int) is probably way faster.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated the code

@fabiojb
Copy link
Contributor Author

fabiojb commented May 10, 2021

See the summary of the benchmark results between the upstream version and before this changes:

Upstream:

Benchmark                                                    Mode  Cnt     Score     Error   Units
Benchmak.testEncode                                         thrpt   25  3784,752 ± 164,448  ops/ms
Benchmak.testEncode:·gc.alloc.rate                          thrpt   25  1842,399 ±  80,049  MB/sec
Benchmak.testEncode:·gc.alloc.rate.norm                     thrpt   25   536,000 ±   0,001    B/op
Benchmak.testEncode:·gc.churn.G1_Eden_Space                 thrpt   25  1842,582 ±  80,854  MB/sec
Benchmak.testEncode:·gc.churn.G1_Eden_Space.norm            thrpt   25   536,069 ±   4,638    B/op
Benchmak.testEncode:·gc.churn.G1_Old_Gen                    thrpt   25     0,005 ±   0,002  MB/sec
Benchmak.testEncode:·gc.churn.G1_Old_Gen.norm               thrpt   25     0,002 ±   0,001    B/op
Benchmak.testEncode:·gc.count                               thrpt   25   987,000            counts
Benchmak.testEncode:·gc.time                                thrpt   25  1170,000                ms
Benchmak.testEncodeEscapeMany                               thrpt   25  1693,864 ±  29,154  ops/ms
Benchmak.testEncodeEscapeMany:·gc.alloc.rate                thrpt   25  1747,594 ±  30,077  MB/sec
Benchmak.testEncodeEscapeMany:·gc.alloc.rate.norm           thrpt   25  1136,000 ±   0,001    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space       thrpt   25  1748,404 ±  31,715  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space.norm  thrpt   25  1136,548 ±   8,479    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen          thrpt   25     0,005 ±   0,002  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen.norm     thrpt   25     0,003 ±   0,001    B/op
Benchmak.testEncodeEscapeMany:·gc.count                     thrpt   25   917,000            counts
Benchmak.testEncodeEscapeMany:·gc.time                      thrpt   25  1123,000                ms
Benchmak.testEncodeEscapeOne                                thrpt   25  3937,699 ± 183,182  ops/ms
Benchmak.testEncodeEscapeOne:·gc.alloc.rate                 thrpt   25  1945,470 ±  90,518  MB/sec
Benchmak.testEncodeEscapeOne:·gc.alloc.rate.norm            thrpt   25   544,000 ±   0,001    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space        thrpt   25  1949,189 ±  91,494  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space.norm   thrpt   25   545,053 ±   4,754    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen           thrpt   25     0,005 ±   0,002  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen.norm      thrpt   25     0,001 ±   0,001    B/op
Benchmak.testEncodeEscapeOne:·gc.count                      thrpt   25   891,000            counts
Benchmak.testEncodeEscapeOne:·gc.time                       thrpt   25  1176,000                ms

After:

Benchmark                                                    Mode  Cnt     Score     Error   Units
Benchmak.testEncode                                         thrpt   25  4756,126 ± 155,129  ops/ms
Benchmak.testEncode:·gc.alloc.rate                          thrpt   25  2315,276 ±  75,518  MB/sec
Benchmak.testEncode:·gc.alloc.rate.norm                     thrpt   25   536,000 ±   0,001    B/op
Benchmak.testEncode:·gc.churn.G1_Eden_Space                 thrpt   25  2314,528 ±  75,804  MB/sec
Benchmak.testEncode:·gc.churn.G1_Eden_Space.norm            thrpt   25   535,847 ±   3,901    B/op
Benchmak.testEncode:·gc.churn.G1_Old_Gen                    thrpt   25     0,005 ±   0,002  MB/sec
Benchmak.testEncode:·gc.churn.G1_Old_Gen.norm               thrpt   25     0,001 ±   0,001    B/op
Benchmak.testEncode:·gc.count                               thrpt   25  1162,000            counts
Benchmak.testEncode:·gc.time                                thrpt   25  1152,000                ms
Benchmak.testEncodeEscapeMany                               thrpt   25  1074,152 ±  19,542  ops/ms
Benchmak.testEncodeEscapeMany:·gc.alloc.rate                thrpt   25  3533,775 ±  62,810  MB/sec
Benchmak.testEncodeEscapeMany:·gc.alloc.rate.norm           thrpt   25  3622,400 ±   8,989    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space       thrpt   25  3536,156 ±  62,944  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space.norm  thrpt   25  3624,896 ±  18,209    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen          thrpt   25     0,006 ±   0,002  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen.norm     thrpt   25     0,006 ±   0,002    B/op
Benchmak.testEncodeEscapeMany:·gc.count                     thrpt   25  1538,000            counts
Benchmak.testEncodeEscapeMany:·gc.time                      thrpt   25  1226,000                ms
Benchmak.testEncodeEscapeOne                                thrpt   25  4397,764 ±  67,443  ops/ms
Benchmak.testEncodeEscapeOne:·gc.alloc.rate                 thrpt   25  2172,764 ±  33,323  MB/sec
Benchmak.testEncodeEscapeOne:·gc.alloc.rate.norm            thrpt   25   544,000 ±   0,001    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space        thrpt   25  2173,916 ±  38,387  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space.norm   thrpt   25   544,288 ±   4,714    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen           thrpt   25     0,008 ±   0,002  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen.norm      thrpt   25     0,002 ±   0,001    B/op
Benchmak.testEncodeEscapeOne:·gc.count                      thrpt   25  1101,000            counts
Benchmak.testEncodeEscapeOne:·gc.time                       thrpt   25  1177,000                ms

testEncode -> 25% throughtput gain
testEncodeEscapeOne -> 11% throughtput gain
testEncodeEscapeMany -> 36 % throghtput lost

My understanding is that with the current changes, there are gains when there are few characters to escape, but there are losses when encoding strings with more characters to escape.

I'm going to think how to re-work those changes.

I also uploaded the benchmark code on a new git repo: https://github.com/fabiojb/logbook-gelf-benchmark

@fabiojb fabiojb changed the title Improve SimpleJsonEncoder.escapeString performance WIP: Improve SimpleJsonEncoder.escapeString performance May 10, 2021
int lastCopyIndex = 0;
char[] chars = str.toCharArray();
for (final char ch : chars) {
String escaped = null;
switch (ch) {
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It might be beneficial to refactor the switch block to a private static method and call it via final String escaped = escapeIfNeeded(ch);. Another possible optimization would be to have private static final char attributes for all the escape sequences to test for.

Copy link
Contributor Author

@fabiojb fabiojb May 12, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm going to work on a way to escape the string only if is needed.

I did some tests putting some values on static final variables, but it didn't show a significant difference in the performance tests

@fabiojb
Copy link
Contributor Author

fabiojb commented May 17, 2021

@osiegmar I have submitted two new changes, and finished the improvements I had in mind.

First 90fb46a, reduced memory allocation:

Benchmark                                                    Mode  Cnt     Score    Error   Units
Benchmak.testEncode                                         thrpt   25  5379,559 ± 27,294  ops/ms
Benchmak.testEncode:·gc.alloc.rate                          thrpt   25   117,257 ±  0,595  MB/sec
Benchmak.testEncode:·gc.alloc.rate.norm                     thrpt   25    24,000 ±  0,001    B/op
Benchmak.testEncode:·gc.churn.G1_Eden_Space                 thrpt   25   117,826 ±  5,172  MB/sec
Benchmak.testEncode:·gc.churn.G1_Eden_Space.norm            thrpt   25    24,116 ±  1,048    B/op
Benchmak.testEncode:·gc.churn.G1_Old_Gen                    thrpt   25     0,001 ±  0,001  MB/sec
Benchmak.testEncode:·gc.churn.G1_Old_Gen.norm               thrpt   25    ≈ 10⁻⁴             B/op
Benchmak.testEncode:·gc.count                               thrpt   25   209,000           counts
Benchmak.testEncode:·gc.time                                thrpt   25    87,000               ms
Benchmak.testEncodeEscapeMany                               thrpt   25  1200,371 ± 10,728  ops/ms
Benchmak.testEncodeEscapeMany:·gc.alloc.rate                thrpt   25    52,329 ±  0,468  MB/sec
Benchmak.testEncodeEscapeMany:·gc.alloc.rate.norm           thrpt   25    48,000 ±  0,001    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space       thrpt   25    53,557 ±  4,310  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space.norm  thrpt   25    49,107 ±  3,806    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen          thrpt   25    ≈ 10⁻³           MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen.norm     thrpt   25    ≈ 10⁻³             B/op
Benchmak.testEncodeEscapeMany:·gc.count                     thrpt   25    95,000           counts
Benchmak.testEncodeEscapeMany:·gc.time                      thrpt   25    45,000               ms
Benchmak.testEncodeEscapeOne                                thrpt   25  3276,976 ± 82,336  ops/ms
Benchmak.testEncodeEscapeOne:·gc.alloc.rate                 thrpt   25   127,854 ± 20,334  MB/sec
Benchmak.testEncodeEscapeOne:·gc.alloc.rate.norm            thrpt   25    43,200 ±  7,339    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space        thrpt   25   128,537 ± 20,742  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space.norm   thrpt   25    43,428 ±  7,464    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen           thrpt   25     0,001 ±  0,001  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen.norm      thrpt   25    ≈ 10⁻³             B/op
Benchmak.testEncodeEscapeOne:·gc.count                      thrpt   25   228,000           counts
Benchmak.testEncodeEscapeOne:·gc.time                       thrpt   25    91,000               ms

Second, 53ca94b is a more verbose change, that escapes characters only when it's needed. It did improve the throughput:

Benchmark                                                      Mode  Cnt      Score     Error   Units
Benchmak.testEncode                                           thrpt   25   9806,568 ± 175,136  ops/ms
Benchmak.testEncode:·gc.alloc.rate                            thrpt   25    213,749 ±   3,817  MB/sec
Benchmak.testEncode:·gc.alloc.rate.norm                       thrpt   25     24,000 ±   0,001    B/op
Benchmak.testEncode:·gc.churn.G1_Eden_Space                   thrpt   25    214,263 ±   6,178  MB/sec
Benchmak.testEncode:·gc.churn.G1_Eden_Space.norm              thrpt   25     24,057 ±   0,512    B/op
Benchmak.testEncode:·gc.churn.G1_Old_Gen                      thrpt   25      0,002 ±   0,001  MB/sec
Benchmak.testEncode:·gc.churn.G1_Old_Gen.norm                 thrpt   25     ≈ 10⁻⁴              B/op
Benchmak.testEncode:·gc.count                                 thrpt   25    375,000            counts
Benchmak.testEncode:·gc.time                                  thrpt   25    170,000                ms
Benchmak.testEncodeEscapeMany                                 thrpt   25   2127,439 ±  34,801  ops/ms
Benchmak.testEncodeEscapeMany:·gc.alloc.rate                  thrpt   25     46,371 ±   0,758  MB/sec
Benchmak.testEncodeEscapeMany:·gc.alloc.rate.norm             thrpt   25     24,000 ±   0,001    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space         thrpt   25     47,424 ±   5,094  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Eden_Space.norm    thrpt   25     24,551 ±   2,638    B/op
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen            thrpt   25      0,001 ±   0,002  MB/sec
Benchmak.testEncodeEscapeMany:·gc.churn.G1_Old_Gen.norm       thrpt   25      0,001 ±   0,001    B/op
Benchmak.testEncodeEscapeMany:·gc.count                       thrpt   25     83,000            counts
Benchmak.testEncodeEscapeMany:·gc.time                        thrpt   25     43,000                ms
Benchmak.testEncodeEscapeOne                                  thrpt   25   8168,387 ±  98,073  ops/ms
Benchmak.testEncodeEscapeOne:·gc.alloc.rate                   thrpt   25    178,044 ±   2,138  MB/sec
Benchmak.testEncodeEscapeOne:·gc.alloc.rate.norm              thrpt   25     24,000 ±   0,001    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space          thrpt   25    178,840 ±   5,456  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Eden_Space.norm     thrpt   25     24,106 ±   0,643    B/op
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen             thrpt   25      0,001 ±   0,001  MB/sec
Benchmak.testEncodeEscapeOne:·gc.churn.G1_Old_Gen.norm        thrpt   25     ≈ 10⁻⁴              B/op
Benchmak.testEncodeEscapeOne:·gc.count                        thrpt   25    313,000            counts
Benchmak.testEncodeEscapeOne:·gc.time                         thrpt   25    147,000                ms

To better understand the improvements, you can compare this results against the Upstream results in the previous comment.

@fabiojb fabiojb changed the title WIP: Improve SimpleJsonEncoder.escapeString performance Improve SimpleJsonEncoder.escapeString performance May 17, 2021
Copy link
Owner

@osiegmar osiegmar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry but this commit went way too far. While it might/does improve the performance it hurts the simplicity/maintainability due to its API changes and +150 lines of code. I don't want to sacrifice this for the sake of performance.

@fabiojb fabiojb force-pushed the json-encoder-performance branch 2 times, most recently from d1cc3a0 to 5d512cd Compare May 17, 2021 16:39
@fabiojb
Copy link
Contributor Author

fabiojb commented May 17, 2021

No problem, I understand your point. I removed the last commit, but can you still review the commit ca7259f that improves memory usage?

@@ -107,7 +107,8 @@ private void appendKey(final String key) throws IOException {
*/
@SuppressWarnings("checkstyle:cyclomaticcomplexity")
private void escapeString(final String str) throws IOException {
for (final char ch : str.toCharArray()) {
for (int i = 0; i < str.length(); i++) {
char ch = str.charAt(i);
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add a final in front of char ch and I can approve it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Iterate over the current String internal values instead of making a copy of its content with String.toCharArray
@fabiojb fabiojb changed the title Improve SimpleJsonEncoder.escapeString performance Improve SimpleJsonEncoder.escapeString memory usage May 18, 2021
Copy link
Owner

@osiegmar osiegmar left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks!

@osiegmar osiegmar merged commit 89482d7 into osiegmar:master May 19, 2021
@jbye
Copy link

jbye commented May 20, 2021

Are you planning to release a new version that includes this patch relatively soon?

Also, thank you @osiegmar for maintaining this library and to @fabiojb for providing this performance improvement.

@osiegmar
Copy link
Owner

I'll be part of https://github.com/osiegmar/logback-gelf/milestone/1 which is to be released when the test coverage is (greatly) improved. Unfortunately I hadn't had enough time for that and cannot promise a specific date.

@osiegmar osiegmar added this to the 3.0.0 milestone May 21, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants