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 observability and debugging experience #3901

Merged
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)
chemicL marked this conversation as resolved.
Show resolved Hide resolved
.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 {
chemicL marked this conversation as resolved.
Show resolved Hide resolved
@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");
chemicL marked this conversation as resolved.
Show resolved Hide resolved
}

/**
Expand All @@ -129,48 +128,88 @@ static boolean isUserCode(String line) {
* from the assembly stack trace.
*/
static String[] extractOperatorAssemblyInformationParts(String source) {
chemicL marked this conversation as resolved.
Show resolved Hide resolved
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.", "");
chemicL marked this conversation as resolved.
Show resolved Hide resolved
}
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