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

Reduce overhead of creating / parsing / serializing trace IDs. #212

Merged
merged 2 commits into from
Sep 10, 2020

Conversation

anuraaga
Copy link
Contributor

@anuraaga anuraaga commented Sep 9, 2020

Description of changes:

TraceID currently stores its components as a long for epoch and BigInteger for random number. However, these numeric representations provide mostly no value as in almost all usage a trace ID is just an opaque string (propagation, emitting). So we can reduce the overhead of parsing the ID by storing fields as hex strings themselves, the same format we use in propagating. We also reduce overhead in serialization by only generating the String once, instead of multiple times (2 times without log propagation, potentially hundreds of times with log propagation in a reactive server, ignoring any other debug logging that may happen).

As a result, creation is a tiny bit slower due to the extra work of converting long to string, and biginteger also converts byte array to int array which is a big faster than byte array to hex string. But this is near 0 while we get 3-4x savings in the other operations.

Most conversion code is adapted from OTel.

After

IdsBenchmark.traceId_create                                      sample  1996604     14.918 ±    0.241   us/op
IdsBenchmark.traceId_create:traceId_create·p0.00                 sample               0.176              us/op
IdsBenchmark.traceId_create:traceId_create·p0.50                 sample               1.230              us/op
IdsBenchmark.traceId_create:traceId_create·p0.90                 sample               4.480              us/op
IdsBenchmark.traceId_create:traceId_create·p0.95                 sample              51.584              us/op
IdsBenchmark.traceId_create:traceId_create·p0.99                 sample             335.872              us/op
IdsBenchmark.traceId_create:traceId_create·p0.999                sample             972.800              us/op
IdsBenchmark.traceId_create:traceId_create·p0.9999               sample            2252.800              us/op
IdsBenchmark.traceId_create:traceId_create·p1.00                 sample           16809.984              us/op
IdsBenchmark.traceId_create:·gc.alloc.rate                       sample        5    197.285 ±   14.875  MB/sec
IdsBenchmark.traceId_create:·gc.alloc.rate.norm                  sample        5    197.461 ±    0.524    B/op
IdsBenchmark.traceId_create:·gc.churn.G1_Eden_Space              sample        5    216.618 ±  280.080  MB/sec
IdsBenchmark.traceId_create:·gc.churn.G1_Eden_Space.norm         sample        5    217.107 ±  283.852    B/op
IdsBenchmark.traceId_create:·gc.churn.G1_Survivor_Space          sample        5      1.282 ±    6.406  MB/sec
IdsBenchmark.traceId_create:·gc.churn.G1_Survivor_Space.norm     sample        5      1.299 ±    6.493    B/op
IdsBenchmark.traceId_create:·gc.count                            sample        5      8.000             counts
IdsBenchmark.traceId_create:·gc.time                             sample        5     97.000                 ms
IdsBenchmark.traceId_parse                                       sample  2221831      1.736 ±    0.347   us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.00                   sample               0.001              us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.50                   sample               0.218              us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.90                   sample               0.240              us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.95                   sample               0.256              us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.99                   sample               0.927              us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.999                  sample              12.531              us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.9999                 sample            3304.191              us/op
IdsBenchmark.traceId_parse:traceId_parse·p1.00                   sample           62193.664              us/op
IdsBenchmark.traceId_parse:·gc.alloc.rate                        sample        5   3647.943 ±  495.556  MB/sec
IdsBenchmark.traceId_parse:·gc.alloc.rate.norm                   sample        5    136.147 ±    0.017    B/op
IdsBenchmark.traceId_parse:·gc.churn.G1_Eden_Space               sample        5   3683.291 ±  762.591  MB/sec
IdsBenchmark.traceId_parse:·gc.churn.G1_Eden_Space.norm          sample        5    137.446 ±   19.224    B/op
IdsBenchmark.traceId_parse:·gc.churn.G1_Old_Gen                  sample        5      0.121 ±    1.045  MB/sec
IdsBenchmark.traceId_parse:·gc.churn.G1_Old_Gen.norm             sample        5      0.004 ±    0.038    B/op
IdsBenchmark.traceId_parse:·gc.churn.G1_Survivor_Space           sample        5      1.141 ±    0.305  MB/sec
IdsBenchmark.traceId_parse:·gc.churn.G1_Survivor_Space.norm      sample        5      0.043 ±    0.015    B/op
IdsBenchmark.traceId_parse:·gc.count                             sample        5     58.000             counts
IdsBenchmark.traceId_parse:·gc.time                              sample        5    156.000                 ms
IdsBenchmark.traceId_serialize                                   sample  1905681      1.480 ±    0.324   us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.00           sample               0.001              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.50           sample               0.135              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.90           sample               0.157              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.95           sample               0.176              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.99           sample               0.766              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.999          sample               8.496              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.9999         sample            2454.714              us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p1.00           sample           45416.448              us/op
IdsBenchmark.traceId_serialize:·gc.alloc.rate                    sample        5   5071.941 ± 1745.898  MB/sec
IdsBenchmark.traceId_serialize:·gc.alloc.rate.norm               sample        5     80.060 ±    0.026    B/op
IdsBenchmark.traceId_serialize:·gc.churn.G1_Eden_Space           sample        5   5157.374 ± 1824.165  MB/sec
IdsBenchmark.traceId_serialize:·gc.churn.G1_Eden_Space.norm      sample        5     81.434 ±   10.136    B/op
IdsBenchmark.traceId_serialize:·gc.churn.G1_Old_Gen              sample        5      0.125 ±    1.078  MB/sec
IdsBenchmark.traceId_serialize:·gc.churn.G1_Old_Gen.norm         sample        5      0.002 ±    0.017    B/op
IdsBenchmark.traceId_serialize:·gc.churn.G1_Survivor_Space       sample        5      0.856 ±    0.954  MB/sec
IdsBenchmark.traceId_serialize:·gc.churn.G1_Survivor_Space.norm  sample        5      0.014 ±    0.015    B/op
IdsBenchmark.traceId_serialize:·gc.count                         sample        5     69.000             counts
IdsBenchmark.traceId_serialize:·gc.time                          sample        5    160.000                 ms

Before

IdsBenchmark.traceId_create                                      sample  1987176     14.021 ±   0.199   us/op
IdsBenchmark.traceId_create:traceId_create·p0.00                 sample               0.160             us/op
IdsBenchmark.traceId_create:traceId_create·p0.50                 sample               1.202             us/op
IdsBenchmark.traceId_create:traceId_create·p0.90                 sample               5.272             us/op
IdsBenchmark.traceId_create:traceId_create·p0.95                 sample              74.112             us/op
IdsBenchmark.traceId_create:traceId_create·p0.99                 sample             302.198             us/op
IdsBenchmark.traceId_create:traceId_create·p0.999                sample             637.952             us/op
IdsBenchmark.traceId_create:traceId_create·p0.9999               sample            1548.866             us/op
IdsBenchmark.traceId_create:traceId_create·p1.00                 sample           16678.912             us/op
IdsBenchmark.traceId_create:·gc.alloc.rate                       sample        5    188.753 ±  13.639  MB/sec
IdsBenchmark.traceId_create:·gc.alloc.rate.norm                  sample        5    189.367 ±   0.449    B/op
IdsBenchmark.traceId_create:·gc.churn.G1_Eden_Space              sample        5    191.933 ± 282.215  MB/sec
IdsBenchmark.traceId_create:·gc.churn.G1_Eden_Space.norm         sample        5    192.044 ± 275.624    B/op
IdsBenchmark.traceId_create:·gc.churn.G1_Old_Gen                 sample        5      0.371 ±   3.198  MB/sec
IdsBenchmark.traceId_create:·gc.churn.G1_Old_Gen.norm            sample        5      0.361 ±   3.110    B/op
IdsBenchmark.traceId_create:·gc.churn.G1_Survivor_Space          sample        5      1.630 ±   9.432  MB/sec
IdsBenchmark.traceId_create:·gc.churn.G1_Survivor_Space.norm     sample        5      1.607 ±   9.219    B/op
IdsBenchmark.traceId_create:·gc.count                            sample        5      7.000            counts
IdsBenchmark.traceId_create:·gc.time                             sample        5     77.000                ms
IdsBenchmark.traceId_parse                                       sample  1833488      4.304 ±   0.592   us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.00                   sample               0.001             us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.50                   sample               0.598             us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.90                   sample               0.632             us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.95                   sample               0.650             us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.99                   sample               1.998             us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.999                  sample              52.929             us/op
IdsBenchmark.traceId_parse:traceId_parse·p0.9999                 sample           13798.749             us/op
IdsBenchmark.traceId_parse:traceId_parse·p1.00                   sample           52559.872             us/op
IdsBenchmark.traceId_parse:·gc.alloc.rate                        sample        5   3062.220 ± 320.713  MB/sec
IdsBenchmark.traceId_parse:·gc.alloc.rate.norm                   sample        5    408.597 ±   0.090    B/op
IdsBenchmark.traceId_parse:·gc.churn.G1_Eden_Space               sample        5   3102.402 ± 543.926  MB/sec
IdsBenchmark.traceId_parse:·gc.churn.G1_Eden_Space.norm          sample        5    413.826 ±  36.274    B/op
IdsBenchmark.traceId_parse:·gc.churn.G1_Survivor_Space           sample        5      1.427 ±   0.224  MB/sec
IdsBenchmark.traceId_parse:·gc.churn.G1_Survivor_Space.norm      sample        5      0.190 ±   0.024    B/op
IdsBenchmark.traceId_parse:·gc.count                             sample        5     52.000            counts
IdsBenchmark.traceId_parse:·gc.time                              sample        5    171.000                ms
IdsBenchmark.traceId_serialize                                   sample  1940509      6.541 ±   0.700   us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.00           sample               0.015             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.50           sample               1.056             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.90           sample               1.114             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.95           sample               1.164             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.99           sample               3.344             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.999          sample             129.792             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p0.9999         sample           17134.322             us/op
IdsBenchmark.traceId_serialize:traceId_serialize·p1.00           sample           43712.512             us/op
IdsBenchmark.traceId_serialize:·gc.alloc.rate                    sample        5   4141.172 ± 603.543  MB/sec
IdsBenchmark.traceId_serialize:·gc.alloc.rate.norm               sample        5   1057.239 ±   0.248    B/op
IdsBenchmark.traceId_serialize:·gc.churn.G1_Eden_Space           sample        5   4213.699 ± 982.527  MB/sec
IdsBenchmark.traceId_serialize:·gc.churn.G1_Eden_Space.norm      sample        5   1075.361 ± 151.308    B/op
IdsBenchmark.traceId_serialize:·gc.churn.G1_Old_Gen              sample        5      0.253 ±   2.180  MB/sec
IdsBenchmark.traceId_serialize:·gc.churn.G1_Old_Gen.norm         sample        5      0.061 ±   0.522    B/op
IdsBenchmark.traceId_serialize:·gc.churn.G1_Survivor_Space       sample        5      1.632 ±   0.198  MB/sec
IdsBenchmark.traceId_serialize:·gc.churn.G1_Survivor_Space.norm  sample        5      0.417 ±   0.069    B/op
IdsBenchmark.traceId_serialize:·gc.count                         sample        5     60.000            counts
IdsBenchmark.traceId_serialize:·gc.time                          sample        5    199.000                ms

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

Copy link
Contributor

@willarmiros willarmiros left a comment

Choose a reason for hiding this comment

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

Cool optimization!

@@ -42,6 +48,32 @@ public static StringBuilder stringBuilder() {
return buffer;
}

/**
* A {@link ThreadLocal} {@code char[]} of length {@code length}. The array is not zeroed in any way - every character of
* a resulting {@link String} must be set explicitly. The array returned my be longer than {@code length} - always explicitly
Copy link
Contributor

Choose a reason for hiding this comment

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

typo: may be longer

import org.junit.jupiter.api.RepeatedTest;
import org.junit.jupiter.api.Test;

class TraceIDTest {
Copy link
Contributor

Choose a reason for hiding this comment

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

Thanks so much for adding these!! Probably should've been here from day 1 :/

@anuraaga anuraaga merged commit 5c01cb0 into aws:master Sep 10, 2020
@willarmiros willarmiros mentioned this pull request Nov 25, 2020
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.

None yet

2 participants