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

TimeWindowMax#record causes allocation #3193

Closed
agusevas opened this issue May 24, 2022 · 5 comments
Closed

TimeWindowMax#record causes allocation #3193

agusevas opened this issue May 24, 2022 · 5 comments
Labels
bug A general bug module: micrometer-core An issue that is related to our core module performance Issues related to general performance
Milestone

Comments

@agusevas
Copy link

Some methods in TimeWindowMax class produce garbage because of usage of capturing lambdas. For example:

    public void record(double sample, TimeUnit timeUnit) {
        record(() -> (long) TimeUtils.convert(sample, timeUnit, TimeUnit.NANOSECONDS));
    }

    private void record(LongSupplier sampleSupplier) {
        rotate();
        long sample = sampleSupplier.getAsLong();
        for (AtomicLong max : ringBuffer) {
            updateMax(max, sample);
        }
    }

Every time the record(double sample, TimeUnit timeUnit) is called, a new lambda instance will be created. See example memory allocation profiler stack trace:
CleanShot 2022-05-24 at 09 08 01@2x

Environment

  • Micrometer version: 1.8.5
  • Micrometer registry: prometheus
  • OS: macOS
  • Java version: 17

To Reproduce
How to reproduce the bug:

import java.util.concurrent.TimeUnit;

import org.junit.jupiter.api.Test;

import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.simple.SimpleMeterRegistry;

public class TimeWindowMaxMemoryAllocation {

	@Test
	void timeWindowMax() {
		SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry();
		Timer timer = Timer.builder("timer").register(meterRegistry);
		for (int i = 0; i < 1_000_000; i++) {
			timer.record(1, TimeUnit.MILLISECONDS);
		}
	}
}

Run the test using memory allocation profiler. Sample result:
CleanShot 2022-05-24 at 09 28 49@2x

Expected behavior
Garbage creation is reduced in TimeWindowMax class.

Additional context
See https://www.infoq.com/articles/Java-8-Lambdas-A-Peek-Under-the-Hood/ for more information about the capturing lambdas.

@shakuzen shakuzen added performance Issues related to general performance module: micrometer-core An issue that is related to our core module labels May 24, 2022
@shakuzen shakuzen added this to the 1.8.x milestone May 24, 2022
@shakuzen
Copy link
Member

Looks like this was introduced with #1641. I'm wondering why we used a supplier at all instead of directly taking a long parameter. @izeye do you remember?

@izeye
Copy link
Contributor

izeye commented May 24, 2022

@shakuzen I can't remember exactly, but it seems to have been done that way as part of refactoring to reduce duplication. It'd be better to be reverted if it causes any performance downsides.

@shakuzen shakuzen changed the title TimeWindowMax produces garbage TimeWindowMax#record causes allocation Jun 3, 2022
@shakuzen
Copy link
Member

shakuzen commented Jun 3, 2022

I did quite a bit of investigation for this. It's a bit difficult to be certain about things because behavior can vary depending on the compiler and other factors. I do not see any garbage from the lambda in a heapdump, but I do see the same allocation you are seeing with the profiler. I think it's likely the allocation is happening on the stack due to escape analysis. If I add a breakpoint on the lambda and pause execution in it, then I can see garbage in a heapdump for the lambda instance. Since we don't need to use a capturing lambda here, and this is the hot path for recording, we should avoid the allocation.
As a separate issue, it would be nice if we can add tests and assertions about allocations to avoid this kind of problem.

@shakuzen shakuzen added the bug A general bug label Jun 3, 2022
@shakuzen shakuzen modified the milestones: 1.8.x, 1.8.7 Jun 3, 2022
shakuzen added a commit to shakuzen/micrometer that referenced this issue Jun 3, 2022
The capturing lambda that was used resulted in allocation on each invocation of the record method, which is on the hot path for metrics recording. To reduce the overhead of metrics, avoid the capturing lambda that results in allocation.

Resolves micrometer-metricsgh-3193
@shakuzen
Copy link
Member

shakuzen commented Jun 3, 2022

@agusevas Thank you for reporting the issue. The fix is available in snapshots now (1.8.7-SNAPSHOT, 1.9.1-SNAPSHOT). I did not see the allocation in the memory profiler with these changes. Let us know if you still see allocation happening.

@agusevas
Copy link
Author

agusevas commented Jun 7, 2022

@shakuzen Thank you for the fix. I have tested the 1.8.7-SNAPSHOT version locally. The allocation issue is fixed now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug A general bug module: micrometer-core An issue that is related to our core module performance Issues related to general performance
Projects
None yet
Development

No branches or pull requests

3 participants