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

Optimize Scannable#name() and related logic #3901

Open
wants to merge 8 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 4 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2022 VMware Inc. or its affiliates, All Rights Reserved.
* Copyright (c) 2022-2024 VMware Inc. or its affiliates, All Rights Reserved.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -49,8 +49,8 @@ public static void main(String[] args) throws Exception {

@SuppressWarnings("unused")
@Benchmark
public void measureThroughput() {
Flux.range(0, rangeSize)
public Boolean measureThroughput() {
return Flux.range(0, rangeSize)
Comment on lines +52 to +53
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Here and in MonoCallableBenchmark: as stated, these are unrelated improvements. Can be pulled into a separate PR if desired.

.all(i -> i < Integer.MAX_VALUE)
.block();
}
Expand Down
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2022 VMware Inc. or its affiliates, All Rights Reserved.
* Copyright (c) 2022-2024 VMware Inc. or its affiliates, All Rights Reserved.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -49,8 +49,8 @@ public static void main(String[] args) throws Exception {

@SuppressWarnings("unused")
@Benchmark
public void measureThroughput() {
Flux.range(0, rangeSize)
public Boolean measureThroughput() {
return Flux.range(0, rangeSize)
.all(i -> i < Integer.MAX_VALUE)
.block();
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,70 @@
/*
* Copyright (c) 2024 VMware Inc. or its affiliates, All Rights Reserved.
*
* Licensed 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
*
* https://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 reactor.core.publisher;

import java.util.concurrent.TimeUnit;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Level;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Param;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Warmup;

@BenchmarkMode({Mode.AverageTime})
@Warmup(iterations = 5, time = 5, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 5, time = 5, timeUnit = TimeUnit.SECONDS)
@Fork(value = 1)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Benchmark)
public class TracesBenchmark {
Comment on lines +33 to +39
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 configuration and setup for this benchmark match those of the existing benchmarks, including explicit specification of default parameters. Can be cleaned up a bit more if desired.

As for the impact of this PR, the following shows the before- and after output of ./gradlew jmh --include="TracesBenchmark" --profilers="gc":

Before:

Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt       Score      Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5      93.082 ±    5.671   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5    8607.367 ±  515.275  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5     840.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5     117.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5     153.000                 ms
TracesBenchmark.measureThroughput                                         0               10  avgt    5     398.660 ±   16.663   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0               10  avgt    5    7081.158 ±  294.949  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0               10  avgt    5    2960.001 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0               10  avgt    5      96.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0               10  avgt    5     124.000                 ms
TracesBenchmark.measureThroughput                                         0              100  avgt    5    2999.075 ±   89.655   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0              100  avgt    5    7364.662 ±  220.010  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0              100  avgt    5   23160.019 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0              100  avgt    5     100.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0              100  avgt    5     131.000                 ms
TracesBenchmark.measureThroughput                                         0             1000  avgt    5   27916.269 ± 1601.038   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0             1000  avgt    5    7751.034 ±  442.501  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0             1000  avgt    5  226865.228 ±    0.070    B/op
TracesBenchmark.measureThroughput:gc.count                                0             1000  avgt    5     105.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0             1000  avgt    5     133.000                 ms
TracesBenchmark.measureThroughput                                        10                0  avgt    5     402.076 ±   11.693   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10                0  avgt    5    7476.144 ±  216.947  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10                0  avgt    5    3152.001 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10                0  avgt    5     102.000             counts
TracesBenchmark.measureThroughput:gc.time                                10                0  avgt    5     131.000                 ms
TracesBenchmark.measureThroughput                                        10               10  avgt    5     626.244 ±   31.574   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10               10  avgt    5    8053.582 ±  403.074  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10               10  avgt    5    5288.002 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10               10  avgt    5     109.000             counts
TracesBenchmark.measureThroughput:gc.time                                10               10  avgt    5     140.000                 ms
TracesBenchmark.measureThroughput                                        10              100  avgt    5    3331.927 ±  253.038   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10              100  avgt    5    7608.535 ±  564.012  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10              100  avgt    5   26576.019 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10              100  avgt    5     104.000             counts
TracesBenchmark.measureThroughput:gc.time                                10              100  avgt    5     137.000                 ms
TracesBenchmark.measureThroughput                                        10             1000  avgt    5   27321.302 ± 1180.729   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10             1000  avgt    5    7992.724 ±  345.188  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10             1000  avgt    5  228969.037 ±    0.044    B/op
TracesBenchmark.measureThroughput:gc.count                               10             1000  avgt    5     109.000             counts
TracesBenchmark.measureThroughput:gc.time                                10             1000  avgt    5     140.000                 ms
TracesBenchmark.measureThroughput                                       100                0  avgt    5    3119.034 ±   70.765   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100                0  avgt    5    7555.751 ±  170.859  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100                0  avgt    5   24712.018 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                              100                0  avgt    5     102.000             counts
TracesBenchmark.measureThroughput:gc.time                               100                0  avgt    5     131.000                 ms
TracesBenchmark.measureThroughput                                       100               10  avgt    5    3384.598 ±  134.383   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100               10  avgt    5    7894.374 ±  310.075  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100               10  avgt    5   28016.020 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                              100               10  avgt    5     107.000             counts
TracesBenchmark.measureThroughput:gc.time                               100               10  avgt    5     141.000                 ms
TracesBenchmark.measureThroughput                                       100              100  avgt    5    5920.906 ±  192.896   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100              100  avgt    5    7678.427 ±  250.022  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100              100  avgt    5   47672.060 ±    0.002    B/op
TracesBenchmark.measureThroughput:gc.count                              100              100  avgt    5     104.000             counts
TracesBenchmark.measureThroughput:gc.time                               100              100  avgt    5     141.000                 ms
TracesBenchmark.measureThroughput                                       100             1000  avgt    5   28805.156 ± 1329.846   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100             1000  avgt    5    8211.734 ±  378.784  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100             1000  avgt    5  248017.124 ±    0.052    B/op
TracesBenchmark.measureThroughput:gc.count                              100             1000  avgt    5     111.000             counts
TracesBenchmark.measureThroughput:gc.time                               100             1000  avgt    5     147.000                 ms
TracesBenchmark.measureThroughput                                      1000                0  avgt    5   27765.904 ± 1098.007   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000                0  avgt    5    8341.364 ±  333.465  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000                0  avgt    5  242849.078 ±    0.042    B/op
TracesBenchmark.measureThroughput:gc.count                             1000                0  avgt    5     113.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000                0  avgt    5     145.000                 ms
TracesBenchmark.measureThroughput                                      1000               10  avgt    5   28772.385 ± 1965.006   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000               10  avgt    5    8115.825 ±  550.707  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000               10  avgt    5  244809.121 ±    0.076    B/op
TracesBenchmark.measureThroughput:gc.count                             1000               10  avgt    5     111.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000               10  avgt    5     145.000                 ms
TracesBenchmark.measureThroughput                                      1000              100  avgt    5   31094.765 ± 1220.979   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000              100  avgt    5    8049.444 ±  315.635  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000              100  avgt    5  262450.032 ±    0.080    B/op
TracesBenchmark.measureThroughput:gc.count                             1000              100  avgt    5     109.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000              100  avgt    5     142.000                 ms
TracesBenchmark.measureThroughput                                      1000             1000  avgt    5   55008.078 ± 3723.012   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000             1000  avgt    5    8252.861 ±  557.526  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000             1000  avgt    5  475940.138 ±    0.280    B/op
TracesBenchmark.measureThroughput:gc.count                             1000             1000  avgt    5     112.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000             1000  avgt    5     148.000                 ms

After

Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt      Score      Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5     28.283 ±    2.319   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5  12142.383 ±  996.110  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5    360.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5    165.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5    218.000                 ms
TracesBenchmark.measureThroughput                                         0               10  avgt    5     48.606 ±    4.176   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0               10  avgt    5  11305.217 ±  943.994  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0               10  avgt    5    576.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0               10  avgt    5    154.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0               10  avgt    5    211.000                 ms
TracesBenchmark.measureThroughput                                         0              100  avgt    5     47.248 ±    2.156   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0              100  avgt    5  11626.888 ±  524.566  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0              100  avgt    5    576.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0              100  avgt    5    158.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0              100  avgt    5    204.000                 ms
TracesBenchmark.measureThroughput                                         0             1000  avgt    5     47.641 ±    4.503   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0             1000  avgt    5  11535.133 ± 1068.897  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0             1000  avgt    5    576.002 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0             1000  avgt    5    157.000             counts
TracesBenchmark.measureThroughput:gc.time                                 0             1000  avgt    5    199.000                 ms
TracesBenchmark.measureThroughput                                        10                0  avgt    5     47.941 ±    1.134   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10                0  avgt    5  10821.406 ±  255.277  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10                0  avgt    5    544.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10                0  avgt    5    147.000             counts
TracesBenchmark.measureThroughput:gc.time                                10                0  avgt    5    182.000                 ms
TracesBenchmark.measureThroughput                                        10               10  avgt    5     48.681 ±    3.065   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10               10  avgt    5  10658.850 ±  672.502  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10               10  avgt    5    544.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10               10  avgt    5    145.000             counts
TracesBenchmark.measureThroughput:gc.time                                10               10  avgt    5    189.000                 ms
TracesBenchmark.measureThroughput                                        10              100  avgt    5     48.309 ±    3.576   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10              100  avgt    5  10741.652 ±  778.802  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10              100  avgt    5    544.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10              100  avgt    5    147.000             counts
TracesBenchmark.measureThroughput:gc.time                                10              100  avgt    5    202.000                 ms
TracesBenchmark.measureThroughput                                        10             1000  avgt    5     46.582 ±    2.587   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                          10             1000  avgt    5  11138.595 ±  611.256  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                     10             1000  avgt    5    544.002 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                               10             1000  avgt    5    152.000             counts
TracesBenchmark.measureThroughput:gc.time                                10             1000  avgt    5    202.000                 ms
TracesBenchmark.measureThroughput                                       100                0  avgt    5     46.127 ±    2.642   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100                0  avgt    5  11248.700 ±  638.495  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100                0  avgt    5    544.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                              100                0  avgt    5    153.000             counts
TracesBenchmark.measureThroughput:gc.time                               100                0  avgt    5    201.000                 ms
TracesBenchmark.measureThroughput                                       100               10  avgt    5     46.186 ±    2.518   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100               10  avgt    5  11234.035 ±  610.123  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100               10  avgt    5    544.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                              100               10  avgt    5    153.000             counts
TracesBenchmark.measureThroughput:gc.time                               100               10  avgt    5    199.000                 ms
TracesBenchmark.measureThroughput                                       100              100  avgt    5     48.736 ±    1.891   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100              100  avgt    5  10645.285 ±  416.594  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100              100  avgt    5    544.000 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                              100              100  avgt    5    145.000             counts
TracesBenchmark.measureThroughput:gc.time                               100              100  avgt    5    185.000                 ms
TracesBenchmark.measureThroughput                                       100             1000  avgt    5     46.312 ±    2.365   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                         100             1000  avgt    5  11203.368 ±  573.569  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                    100             1000  avgt    5    544.002 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                              100             1000  avgt    5    152.000             counts
TracesBenchmark.measureThroughput:gc.time                               100             1000  avgt    5    198.000                 ms
TracesBenchmark.measureThroughput                                      1000                0  avgt    5     46.600 ±    2.220   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000                0  avgt    5  11133.818 ±  527.892  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000                0  avgt    5    544.002 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                             1000                0  avgt    5    152.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000                0  avgt    5    201.000                 ms
TracesBenchmark.measureThroughput                                      1000               10  avgt    5     45.805 ±    1.806   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000               10  avgt    5  11326.617 ±  446.037  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000               10  avgt    5    544.002 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                             1000               10  avgt    5    154.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000               10  avgt    5    206.000                 ms
TracesBenchmark.measureThroughput                                      1000              100  avgt    5     48.450 ±    2.778   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000              100  avgt    5  10709.195 ±  616.791  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000              100  avgt    5    544.003 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                             1000              100  avgt    5    145.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000              100  avgt    5    191.000                 ms
TracesBenchmark.measureThroughput                                      1000             1000  avgt    5     51.759 ±    2.299   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                        1000             1000  avgt    5  10023.884 ±  443.024  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                   1000             1000  avgt    5    544.004 ±    0.001    B/op
TracesBenchmark.measureThroughput:gc.count                             1000             1000  avgt    5    136.000             counts
TracesBenchmark.measureThroughput:gc.time                              1000             1000  avgt    5    174.000                 ms

Note how performance of the new implementation is almost independent of the input, while the old implementation scales fairly poorly.

@Param({"0", "1", "2"})
private int reactorLeadingLines;

@Param({"0", "1", "2"})
private int trailingLines;

private String stackTrace;

@Setup(Level.Iteration)
public void setup() {
stackTrace = createStackTrace(reactorLeadingLines, trailingLines);
}

@SuppressWarnings("unused")
@Benchmark
public String measureThroughput() {
return Traces.extractOperatorAssemblyInformation(stackTrace);
}

private static String createStackTrace(int reactorLeadingLines, int trailingLines) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < reactorLeadingLines; i++) {
sb.append("\tat reactor.core.publisher.Flux.someOperation(Flux.java:42)\n");
}
sb.append("\tat some.user.package.SomeUserClass.someOperation(SomeUserClass.java:1234)\n");
for (int i = 0; i < trailingLines; i++) {
sb.append("\tat any.package.AnyClass.anyOperation(AnyClass.java:1)\n");
}
return sb.toString();
}
}
2 changes: 1 addition & 1 deletion reactor-core/src/main/java/reactor/core/Scannable.java
Original file line number Diff line number Diff line change
Expand Up @@ -449,7 +449,7 @@ default String name() {
.map(s -> s.scan(Attr.NAME))
.filter(Objects::nonNull)
.findFirst()
.orElse(stepName());
.orElseGet(this::stepName);
}

/**
Expand Down
123 changes: 81 additions & 42 deletions reactor-core/src/main/java/reactor/core/publisher/Traces.java
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2018-2023 VMware Inc. or its affiliates, All Rights Reserved.
* Copyright (c) 2018-2024 VMware Inc. or its affiliates, All Rights Reserved.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand All @@ -16,11 +16,10 @@

package reactor.core.publisher;

import java.util.List;
import java.util.Iterator;
import java.util.NoSuchElementException;
import java.util.function.Supplier;
import java.util.stream.Collectors;
import java.util.stream.Stream;

import reactor.util.annotation.Nullable;

/**
* Utilities around manipulating stack traces and displaying assembly traces.
Expand All @@ -29,6 +28,7 @@
* @author Sergei Egorov
*/
final class Traces {
private static final String PUBLISHER_PACKAGE_PREFIX = "reactor.core.publisher.";
Copy link
Member

Choose a reason for hiding this comment

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

Let's move the private constant below the package-private ones.


/**
* If set to true, the creation of FluxOnAssembly will capture the raw stacktrace
Expand Down Expand Up @@ -57,9 +57,8 @@ final class Traces {
static boolean shouldSanitize(String stackTraceRow) {
return stackTraceRow.startsWith("java.util.function")
|| stackTraceRow.startsWith("reactor.core.publisher.Mono.onAssembly")
|| stackTraceRow.equals("reactor.core.publisher.Mono.onAssembly")
|| stackTraceRow.equals("reactor.core.publisher.Flux.onAssembly")
|| stackTraceRow.equals("reactor.core.publisher.ParallelFlux.onAssembly")
|| stackTraceRow.startsWith("reactor.core.publisher.Flux.onAssembly")
|| stackTraceRow.startsWith("reactor.core.publisher.ParallelFlux.onAssembly")
|| stackTraceRow.startsWith("reactor.core.publisher.SignalLogger")
|| stackTraceRow.startsWith("reactor.core.publisher.FluxOnAssembly")
|| stackTraceRow.startsWith("reactor.core.publisher.MonoOnAssembly.")
Expand Down Expand Up @@ -103,7 +102,7 @@ static String extractOperatorAssemblyInformation(String source) {
}

static boolean isUserCode(String line) {
return !line.startsWith("reactor.core.publisher") || line.contains("Test");
return !line.startsWith(PUBLISHER_PACKAGE_PREFIX) || line.contains("Test");
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 constant has a trailing dot. Afaik that doesn't matter, as each line should include a class name, too.

Copy link
Member

Choose a reason for hiding this comment

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

In case at any point future maintainers decide to add a package that begins with reactor.core.publisher but does not end with a dot I think we can remove the dot from the prefix. Unless it's needed?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Good question. So if I drop the dot from the constant, then the dropPublisherPackagePrefix method won't behave properly. I guess that shows that the current code (with a dot) is slightly more appropriate.

I can of course also just revert the change on this line, though given that currently there's no reactor.core.publisherX package, I suppose it's nicer to keep it like this.

Copy link
Member

Choose a reason for hiding this comment

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

No, that's ok, let's leave it as is.

}

/**
Expand All @@ -129,48 +128,88 @@ static boolean isUserCode(String line) {
* from the assembly stack trace.
*/
static String[] extractOperatorAssemblyInformationParts(String source) {
Copy link
Member

Choose a reason for hiding this comment

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

Since you're changing this mechanism a lot, can you also review the javadoc and update? E.g. skipFirst remained in the javadoc while there is no such argument here.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Check I hadn't reviewed it because the change should affect behavior, but pushed a proposal 👍

String[] uncleanTraces = source.split("\n");
final List<String> traces = Stream.of(uncleanTraces)
.map(String::trim)
.filter(s -> !s.isEmpty())
.collect(Collectors.toList());
Iterator<String> traces = trimmedNonemptyLines(source);
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 largest improvements in this PR come from these changes.

Key contributors to performance of the old implementation:

  • String#split accepts a regular expression. We're no longer performing the comparatively expensive operation of compiling regular expressions.
  • String#split allocates an array and substrings proportional to the provided input, covering a potentially large part of the input that does not at all influence the result of this method.
  • The Stream operation likewise processes irrelevant lines, and allocates a potentially large list.

The new implementation instead lazily iterates over the input, processing only relevant lines, and tracking only the two most-recently-seen lines.


if (traces.isEmpty()) {
if (!traces.hasNext()) {
return new String[0];
}

int i = 0;
while (i < traces.size() && !isUserCode(traces.get(i))) {
i++;
}
String prevLine = null;
String currentLine = traces.next();

String apiLine;
String userCodeLine;
if (i == 0) {
//no line was a reactor API line
apiLine = "";
userCodeLine = traces.get(0);
}
else if (i == traces.size()) {
//we skipped ALL lines, meaning they're all reactor API lines. We'll fully display the last one
apiLine = "";
userCodeLine = traces.get(i-1).replaceFirst("reactor.core.publisher.", "");
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Here and below: replaceFirst also accepts a regex. The new code instead performs a cheaper startsWith check.

}
else {
//currently on user code line, previous one is API
apiLine = traces.get(i - 1);
userCodeLine = traces.get(i);
if (isUserCode(currentLine)) {
// No line is a Reactor API line.
return new String[]{currentLine};
}
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Some logic was moved around, but existing comments were relocated with it. This should aid review. It's nice that there was already good test coverage.


//now we want something in the form "Flux.map ⇢ user.code.Class.method(Class.java:123)"
if (apiLine.isEmpty()) return new String[] { userCodeLine };
while (traces.hasNext()) {
prevLine = currentLine;
currentLine = traces.next();

if (isUserCode(currentLine)) {
// Currently on user code line, previous one is API. Attempt to create something in the form
// "Flux.map ⇢ user.code.Class.method(Class.java:123)".
int linePartIndex = prevLine.indexOf('(');
String apiLine = linePartIndex > 0 ?
prevLine.substring(0, linePartIndex) :
prevLine;

int linePartIndex = apiLine.indexOf('(');
if (linePartIndex > 0) {
apiLine = apiLine.substring(0, linePartIndex);
return new String[]{dropPublisherPackagePrefix(apiLine), "at " + currentLine};
}
}
apiLine = apiLine.replaceFirst("reactor.core.publisher.", "");

return new String[] { apiLine, "at " + userCodeLine };
// We skipped ALL lines, meaning they're all Reactor API lines. We'll fully display the last
// one.
return new String[]{dropPublisherPackagePrefix(currentLine)};
}

private static String dropPublisherPackagePrefix(String line) {
return line.startsWith(PUBLISHER_PACKAGE_PREFIX)
? line.substring(PUBLISHER_PACKAGE_PREFIX.length())
: line;
}

/**
* Returns an iterator over all trimmed non-empty lines in the given source string.
*
* @implNote This implementation attempts to minimize allocations.
*/
private static Iterator<String> trimmedNonemptyLines(String source) {
return new Iterator<String>() {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This manually-crafted iterator feels a bit like "coding like it's 1999", but I didn't find a less-verbose alternative that doesn't impact over-all code readability. (Had Guava been on the classpath, then I'd have opted to extend AbstractIterator.) Open to suggestions!

private int index = 0;
@Nullable
private String next = getNextLine();

@Override
public boolean hasNext() {
return next != null;
}

@Override
public String next() {
String current = next;
if (current == null) {
throw new NoSuchElementException();
}
next = getNextLine();
return current;
}

@Nullable
private String getNextLine() {
Copy link
Member

Choose a reason for hiding this comment

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

Here's an outline of an idea to avoid using String and get the next line:

// Assume the entire input (String source) is wrapped in CharBuffer

CharBuffer cb = CharBuffer.wrap(source);

private CharBuffer getNextLine() {
		int i = 0;
		while (i < cb.length()) {
			if (Character.isWhitespace(cb.charAt(i))) continue;

			int end = i + 1;
			while (end < cb.length() && cb.charAt(end) != '\n') {
				end++;
			}
			
			CharBuffer line = cb.subSequence(i, end);
			i = end + 1;
			return line;
		}
}

Copy link
Member

Choose a reason for hiding this comment

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

The match for the reactor package name can also be done in the same linear scanning manner. I wonder if it'd be 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.

I had a look at this, and went down the rabbit hole. The TL;DR is that I added three commits that further improve performance:

  1. One that avoids String#join, unrelated to your suggestion here.
  2. One that replaces String#trim, such that the original string's underlying char[] is always reused, thanks to the implementation of String#substring. This is IIUC an alternative to your suggestion to use CharBuffer; I couldn't use the latter, as it lacks operations such as .startsWith and indexOf.
  3. One that introduces a custom Substring class and is "somehow" even more performant.
Benchmark of the code on `main`
Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt     Score     Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5    91.389 ±   1.255   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5  8765.340 ± 120.723  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5   840.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5   119.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5   179.000                ms
TracesBenchmark.measureThroughput                                         0                1  avgt    5   122.102 ±   3.312   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                1  avgt    5  8060.272 ± 216.623  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                1  avgt    5  1032.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                1  avgt    5   109.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                1  avgt    5   158.000                ms
TracesBenchmark.measureThroughput                                         0                2  avgt    5   148.867 ±   2.750   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                2  avgt    5  7892.060 ± 145.950  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                2  avgt    5  1232.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                2  avgt    5   107.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                2  avgt    5   156.000                ms
TracesBenchmark.measureThroughput                                         1                0  avgt    5   122.145 ±   1.654   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                0  avgt    5  8057.222 ± 109.248  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                0  avgt    5  1032.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                0  avgt    5   109.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                0  avgt    5   165.000                ms
TracesBenchmark.measureThroughput                                         1                1  avgt    5   145.273 ±   0.361   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                1  avgt    5  8087.325 ±  20.159  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                1  avgt    5  1232.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                1  avgt    5   110.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                1  avgt    5   158.000                ms
TracesBenchmark.measureThroughput                                         1                2  avgt    5   177.756 ±   2.771   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                2  avgt    5  7639.569 ± 119.523  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                2  avgt    5  1424.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                2  avgt    5   104.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                2  avgt    5   152.000                ms
TracesBenchmark.measureThroughput                                         2                0  avgt    5   147.853 ±   2.101   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                0  avgt    5  8049.391 ± 114.613  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                0  avgt    5  1248.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                0  avgt    5   109.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                0  avgt    5   151.000                ms
TracesBenchmark.measureThroughput                                         2                1  avgt    5   176.972 ±   2.701   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                1  avgt    5  7759.568 ± 118.381  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                1  avgt    5  1440.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                1  avgt    5   106.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                1  avgt    5   154.000                ms
TracesBenchmark.measureThroughput                                         2                2  avgt    5   199.950 ±   0.792   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                2  avgt    5  8203.243 ±  32.542  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                2  avgt    5  1720.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                2  avgt    5   111.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                2  avgt    5   162.000                ms
Benchmark of the already-reviewed code
Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt      Score     Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5     27.709 ±   1.321   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5  12390.947 ± 590.685  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5    360.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5    168.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5    226.000                ms
TracesBenchmark.measureThroughput                                         0                1  avgt    5     47.622 ±   1.357   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                1  avgt    5  11534.798 ± 330.546  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                1  avgt    5    576.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                1  avgt    5    157.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                1  avgt    5    217.000                ms
TracesBenchmark.measureThroughput                                         0                2  avgt    5     46.575 ±   2.868   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                2  avgt    5  11796.026 ± 725.031  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                2  avgt    5    576.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                2  avgt    5    160.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                2  avgt    5    222.000                ms
TracesBenchmark.measureThroughput                                         1                0  avgt    5     48.489 ±   3.267   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                0  avgt    5  11330.727 ± 758.029  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                0  avgt    5    576.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                0  avgt    5    154.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                0  avgt    5    208.000                ms
TracesBenchmark.measureThroughput                                         1                1  avgt    5     46.214 ±   2.285   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                1  avgt    5  11887.215 ± 584.466  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                1  avgt    5    576.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                1  avgt    5    162.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                1  avgt    5    212.000                ms
TracesBenchmark.measureThroughput                                         1                2  avgt    5     46.943 ±   2.083   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                2  avgt    5  11702.329 ± 513.790  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                2  avgt    5    576.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                2  avgt    5    159.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                2  avgt    5    230.000                ms
TracesBenchmark.measureThroughput                                         2                0  avgt    5     48.431 ±   1.966   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                0  avgt    5  10712.378 ± 436.213  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                0  avgt    5    544.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                0  avgt    5    146.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                0  avgt    5    210.000                ms
TracesBenchmark.measureThroughput                                         2                1  avgt    5     46.974 ±   3.057   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                1  avgt    5  11046.458 ± 731.622  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                1  avgt    5    544.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                1  avgt    5    151.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                1  avgt    5    210.000                ms
TracesBenchmark.measureThroughput                                         2                2  avgt    5     50.708 ±   0.980   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                2  avgt    5  10230.724 ± 197.935  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                2  avgt    5    544.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                2  avgt    5    139.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                2  avgt    5    187.000                ms
Benchmark after the first improvement
Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt      Score     Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5     21.666 ±   0.360   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5  10563.716 ± 175.257  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5    240.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5    144.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5    212.000                ms
TracesBenchmark.measureThroughput                                         0                1  avgt    5     36.057 ±   1.438   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                1  avgt    5  10791.558 ± 429.161  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                1  avgt    5    408.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                1  avgt    5    146.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                1  avgt    5    206.000                ms
TracesBenchmark.measureThroughput                                         0                2  avgt    5     35.516 ±   1.274   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                2  avgt    5  10955.809 ± 391.095  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                2  avgt    5    408.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                2  avgt    5    149.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                2  avgt    5    209.000                ms
TracesBenchmark.measureThroughput                                         1                0  avgt    5     37.723 ±   1.266   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                0  avgt    5  10719.145 ± 360.313  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                0  avgt    5    424.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                0  avgt    5    145.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                0  avgt    5    201.000                ms
TracesBenchmark.measureThroughput                                         1                1  avgt    5     35.600 ±   2.316   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                1  avgt    5  11360.236 ± 738.477  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                1  avgt    5    424.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                1  avgt    5    154.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                1  avgt    5    221.000                ms
TracesBenchmark.measureThroughput                                         1                2  avgt    5     36.167 ±   1.605   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                2  avgt    5  11180.857 ± 492.758  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                2  avgt    5    424.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                2  avgt    5    152.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                2  avgt    5    213.000                ms
TracesBenchmark.measureThroughput                                         2                0  avgt    5     34.945 ±   0.914   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                0  avgt    5  10697.778 ± 280.941  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                0  avgt    5    392.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                0  avgt    5    145.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                0  avgt    5    210.000                ms
TracesBenchmark.measureThroughput                                         2                1  avgt    5     35.215 ±   1.076   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                1  avgt    5  10615.784 ± 325.177  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                1  avgt    5    392.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                1  avgt    5    144.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                1  avgt    5    198.000                ms
TracesBenchmark.measureThroughput                                         2                2  avgt    5     35.754 ±   1.788   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                2  avgt    5  10456.676 ± 524.036  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                2  avgt    5    392.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                2  avgt    5    142.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                2  avgt    5    200.000                ms
Benchmark after the second improvement
Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt     Score     Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5    16.695 ±   0.223   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5  6854.558 ±  91.285  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5   120.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5    94.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5   130.000                ms
TracesBenchmark.measureThroughput                                         0                1  avgt    5    27.538 ±   2.173   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                1  avgt    5  7482.351 ± 582.492  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                1  avgt    5   216.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                1  avgt    5   102.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                1  avgt    5   143.000                ms
TracesBenchmark.measureThroughput                                         0                2  avgt    5    26.589 ±   1.541   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                2  avgt    5  7748.273 ± 448.220  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                2  avgt    5   216.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                2  avgt    5   106.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                2  avgt    5   154.000                ms
TracesBenchmark.measureThroughput                                         1                0  avgt    5    28.482 ±   0.514   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                0  avgt    5  7500.140 ± 135.789  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                0  avgt    5   224.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                0  avgt    5   102.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                0  avgt    5   150.000                ms
TracesBenchmark.measureThroughput                                         1                1  avgt    5    26.180 ±   0.323   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                1  avgt    5  8159.420 ± 101.176  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                1  avgt    5   224.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                1  avgt    5   111.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                1  avgt    5   163.000                ms
TracesBenchmark.measureThroughput                                         1                2  avgt    5    26.194 ±   0.395   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                2  avgt    5  8155.085 ± 122.896  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                2  avgt    5   224.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                2  avgt    5   111.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                2  avgt    5   157.000                ms
TracesBenchmark.measureThroughput                                         2                0  avgt    5    26.485 ±   0.255   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                0  avgt    5  7489.392 ±  72.106  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                0  avgt    5   208.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                0  avgt    5   102.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                0  avgt    5   146.000                ms
TracesBenchmark.measureThroughput                                         2                1  avgt    5    26.530 ±   0.298   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                1  avgt    5  7476.572 ±  83.959  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                1  avgt    5   208.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                1  avgt    5   102.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                1  avgt    5   149.000                ms
TracesBenchmark.measureThroughput                                         2                2  avgt    5    26.710 ±   0.566   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                2  avgt    5  7426.339 ± 157.301  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                2  avgt    5   208.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                2  avgt    5   101.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                2  avgt    5   146.000                ms
Benchmark after the third improvement
Benchmark                                             (reactorLeadingLines)  (trailingLines)  Mode  Cnt     Score     Error   Units
TracesBenchmark.measureThroughput                                         0                0  avgt    5    18.096 ±   0.304   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                0  avgt    5  7588.502 ± 127.338  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                0  avgt    5   144.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                0  avgt    5   103.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                0  avgt    5   145.000                ms
TracesBenchmark.measureThroughput                                         0                1  avgt    5    22.850 ±   0.378   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                1  avgt    5  5008.182 ±  83.316  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                1  avgt    5   120.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                1  avgt    5    68.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                1  avgt    5    98.000                ms
TracesBenchmark.measureThroughput                                         0                2  avgt    5    20.251 ±   0.517   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           0                2  avgt    5  5651.105 ± 144.835  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      0                2  avgt    5   120.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                0                2  avgt    5    77.000            counts
TracesBenchmark.measureThroughput:gc.time                                 0                2  avgt    5   114.000                ms
TracesBenchmark.measureThroughput                                         1                0  avgt    5    23.276 ±   0.700   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                0  avgt    5  4261.171 ± 128.182  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                0  avgt    5   104.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                0  avgt    5    58.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                0  avgt    5    79.000                ms
TracesBenchmark.measureThroughput                                         1                1  avgt    5    19.319 ±   0.161   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                1  avgt    5  5133.773 ±  43.098  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                1  avgt    5   104.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                1  avgt    5    70.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                1  avgt    5    96.000                ms
TracesBenchmark.measureThroughput                                         1                2  avgt    5    19.673 ±   0.342   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           1                2  avgt    5  5041.454 ±  87.186  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      1                2  avgt    5   104.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                1                2  avgt    5    68.000            counts
TracesBenchmark.measureThroughput:gc.time                                 1                2  avgt    5    89.000                ms
TracesBenchmark.measureThroughput                                         2                0  avgt    5    18.855 ±   0.652   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                0  avgt    5  5260.401 ± 184.048  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                0  avgt    5   104.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                0  avgt    5    72.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                0  avgt    5    99.000                ms
TracesBenchmark.measureThroughput                                         2                1  avgt    5    18.931 ±   0.206   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                1  avgt    5  5238.827 ±  56.895  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                1  avgt    5   104.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                1  avgt    5    71.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                1  avgt    5   103.000                ms
TracesBenchmark.measureThroughput                                         2                2  avgt    5    18.723 ±   0.983   ns/op
TracesBenchmark.measureThroughput:gc.alloc.rate                           2                2  avgt    5  5297.753 ± 279.570  MB/sec
TracesBenchmark.measureThroughput:gc.alloc.rate.norm                      2                2  avgt    5   104.000 ±   0.001    B/op
TracesBenchmark.measureThroughput:gc.count                                2                2  avgt    5    72.000            counts
TracesBenchmark.measureThroughput:gc.time                                 2                2  avgt    5   100.000                ms

So for the common (1, 1) case, we see the following timing and memory usage differences:

Variant       Speed                           Normalized garbage
============= ============================    ==========================
Baseline      145.273 ± 0.361 ns/op           1232.000 ± 0.001 B/op
Reviewed code  46.214 ± 2.285 ns/op (-68%)     576.000 ± 0.001 B/op (-53%)
Speedup 1      35.600 ± 2.316 ns/op (-23%)     424.000 ± 0.001 B/op (-26%)
Speedup 2      26.180 ± 0.323 ns/op (-26%)     224.000 ± 0.001 B/op (-47%)
Speedup 3      19.319 ± 0.161 ns/op (-26%)     104.000 ± 0.001 B/op (-53%)

I can see how "Speedup 3" is controversial from a maintainability point of view. I guess the only way to justify it, is by realizing that we're dealing with a very hot codepath here (at least for Reactor Debug Agent users). Up to you :)

while (index < source.length()) {
Stephan202 marked this conversation as resolved.
Show resolved Hide resolved
int end = source.indexOf('\n', index);
if (end == -1) {
end = source.length();
}
String line = source.substring(index, end).trim();
index = end + 1;
if (!line.isEmpty()) {
return line;
}
}
return null;
}
};
}
}
Loading