Skip to content

Conversation

@aalsanie
Copy link

ContextPairs builds nested pairs by splitting each name on ".". The current implementation uses String.split("\\."), which is regex-based and allocates an array and list per name.

Here I replaced the regex split with a manual dot delimited scan that reduces allocations and avoids regex overhead while preserving existing behavior.

A test has been added.

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jan 28, 2026
ContextPairs currently uses String.split("\\.") to expand nested names.
String.split is regex-based and allocates per call. Replace it with a
manual dot-delimited scan to reduce allocations and CPU overhead while
preserving existing behavior.

Signed-off-by: Ahmad Al-Sanie [email protected]
Signed-off-by: aalsanie <[email protected]>
@wilkinsona
Copy link
Member

Thanks for the PR. Unfortunately, I'm not sure that we should merge it as it adds a significant amount of complexity. To consider merging it, I think we'd need to see evidence that the change makes a notable difference to real-world performance.

@wilkinsona wilkinsona added the status: waiting-for-feedback We need additional information before we can continue label Jan 28, 2026
@aalsanie
Copy link
Author

@wilkinsona Thanks for the feedback, I went and isolated both implementations into the same class and executed them under identical JVM conditions.

java SplitPerf

regex:  664 ms   (66.42357 ns/op)
manual: 478 ms   (47.80414 ns/op)
blackhole=0

java -XX:StartFlightRecording=filename=split.jfr,settings=profile -cp . SplitPerf

regex:  706 ms   (70.6994 ns/op)
manual: 487 ms   (48.79678 ns/op)
blackhole=0

Running 10M iterations shows a consistent ~30% reduction in execution time,, the reduced allocation rate also lowers GC pressure.

allocation method profiling

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jan 28, 2026
@wilkinsona
Copy link
Member

Thanks. That's not quite what I meant by real-world and is more of a micro benchmark. To justify the extra complexity, I think we'd need to see an improvement in the performance of structured logging.

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Jan 28, 2026
@aalsanie
Copy link
Author

Fair enough, I’ll put together a small boot app with structured logging end-to-end and compare baseline.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jan 28, 2026
@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Jan 28, 2026
@aalsanie
Copy link
Author

Structured logging benchmark: https://github.com/aalsanie/logging-sample.


baseline:

round=1 elapsedMs=44628
round=2 elapsedMs=44553
round=3 elapsedMs=44552
round=4 elapsedMs=45230
round=5 elapsedMs=45527

Median baseline = 44,628 ms


patched:

round=1 elapsedMs=43137
round=2 elapsedMs=43115
round=3 elapsedMs=43141
round=4 elapsedMs=43103
round=5 elapsedMs=43084

Median patched = 43,115 ms


summary

3.39% faster

1.5s faster per 3M events

total allocation samples drop (~4% fewer)

run duration drops (~3–4%)

Please see attached zip: baseline Vs. patched JFR
baselineVsPatched.zip


Impl Notes:

  • single JVM process with internal warmup before measurements (avoids startup/classloading noise)
  • no per-event mdc put/clear (keeps the benchmark focused on structured formatting/encoding rather than mdc overhead)
  • jvm flags to reduce gc variance: -Xms1g -Xmx1g -XX:+AlwaysPreTouch
  • output is a no-op stream to avoid io cost influencing results

patched snapshot used:

gradlew --refresh-dependencies -q dependencyInsight --dependency org.springframework.boot:spring-boot-starter --configuration runtimeClasspath
org.springframework.boot:spring-boot-starter:4.1.0-SNAPSHOT (by constraint)

......

org.springframework.boot:spring-boot-starter-logging:4.1.0-SNAPSHOT
+--- org.springframework.boot:spring-boot-dependencies:4.1.0-SNAPSHOT
|    \--- runtimeClasspath
\--- org.springframework.boot:spring-boot-starter:4.1.0-SNAPSHOT
     +--- runtimeClasspath (requested org.springframework.boot:spring-boot-starter)
     \--- org.springframework.boot:spring-boot-dependencies:4.1.0-SNAPSHOT (*)

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jan 29, 2026
@aalsanie
Copy link
Author

aalsanie commented Jan 29, 2026

I’ll be honest; I’m not entirely happy with the results. I expected the gain to be higher than this. That said, a 3-4% improvement in a hot structured logging path can benefit a lot of users.

On the other hand, I agree with you that the current change adds too much complexity, and your hesitation is reasonable.
What bugs me the most in the current version is the end == 0 special-case branch. I think we can do better while keeping all existing, tested behavior intact

@SuppressWarnings("unchecked")
void nested(T item, BiConsumer<String, Object> pairs) {
    LinkedHashMap<String, Object> result = new LinkedHashMap<>();
    this.addedPairs.forEach((addedPair) -> {
        addedPair.accept(item, joining((name, value) -> {
            Map<String, Object> destination = result;

            int end = trimTrailingDelimiters(name);
            if (end == 0) {
                return;
            }

            int start = 0;
            while (true) {
                int dot = name.indexOf('.', start);
                if (dot == -1 || dot >= end) {
                    break;
                }

                String part = name.substring(start, dot);

                Object existing = destination.computeIfAbsent(part, (key) -> new LinkedHashMap<>());
                if (!(existing instanceof Map)) {
                    String common = name.substring(0, dot);
                    throw new IllegalStateException(
                            "Duplicate nested pairs added under '%s'".formatted(common));
                }

                destination = (Map<String, Object>) existing;
                start = dot + 1;
            }

            String leaf = name.substring(start, end);
            Object previous = destination.put(leaf, value);
            Assert.state(previous == null,
                    () -> "Duplicate nested pairs added under '%s'".formatted(name));
        }));
    });
    result.forEach(pairs);
}

private int trimTrailingDelimiters(String name) {
    int end = name.length();
    while (end > 0 && name.charAt(end - 1) == '.') {
        end--;
    }
    return end;
}

@philwebb
Copy link
Member

What benchmarks do you get if you keep the original code but replace name.split("\\.") with org.springframework.util.StringUtils.delimitedListToStringArray(String, String, String)? That would at least get rid of the regex complexity.

@philwebb philwebb added the status: waiting-for-feedback We need additional information before we can continue label Jan 29, 2026
@aalsanie
Copy link
Author

Unfortunately I couldn't do that, the delimitedListToStringArray keeps trailing empty
"a1.b1." → ["a1","b1",""] where split would have dropped them.

I had to normalize the input to match what split("\\.") produces which brought back extra logic and complexity. The simplest option is the nonregex indexOf('.') loop with trimTrailingDelimiters the one I shared above.

@spring-projects-issues spring-projects-issues removed the status: waiting-for-feedback We need additional information before we can continue label Jan 30, 2026
@philwebb philwebb added the for: team-meeting An issue we'd like to discuss as a team to make progress label Jan 30, 2026
@philwebb philwebb changed the title Optimize ContextPairs nested name splitting Optimize 'ContextPairs' nested name splitting Feb 2, 2026
@philwebb
Copy link
Member

philwebb commented Feb 2, 2026

@aalsanie Would you be willing to force push an update to your PR with the code from your comment above?

@wilkinsona wilkinsona removed status: feedback-provided Feedback has been provided for: team-meeting An issue we'd like to discuss as a team to make progress labels Feb 2, 2026
@wilkinsona wilkinsona added the status: waiting-for-feedback We need additional information before we can continue label Feb 2, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

status: waiting-for-feedback We need additional information before we can continue status: waiting-for-triage An issue we've not yet triaged

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants