Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce profiling overhead. #25772

Merged
merged 3 commits into from Jul 19, 2017

Conversation

Projects
None yet
3 participants
@jpountz
Copy link
Contributor

commented Jul 18, 2017

Calling System.nanoTime() for each method call may have a significant
performance impact.

Closes #24799

Reduce profiling overhead.
Calling `System.nanoTime()` for each method call may have a significant
performance impact.

Closes #24799
@danielmitterdorfer
Copy link
Member

left a comment

I left a couple of comments but I think nothing critical. LGTM.

// a maximum interval of 1024, which is reached for 1024*2^8 ~= 262000
// This allows to not slow down things too much because of calls
// to System.nanoTime() when methods are called millions of time
// in tight loops, while still providing useful timings for methods

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

we will have to be careful though. If a very short-running method with < 256 calls is timed using this approach, we will have significant overhead from System.nanoTime() calls.

This comment has been minimized.

Copy link
@jpountz

jpountz Jul 18, 2017

Author Contributor

256 nanoTime calls should still take much less than 1ms so I don't worry about it

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 19, 2017

Member

I was not aware of the relative times. What I meant was that calling System.nanoTime() takes on typical systems 30ns (see nanotrusting nanotime). If the code you want to measure takes a similarly long time then you will have a significant measurement error. However, if you measure code that takes e.g. 500µs to execute, the overhead is much lower.

This comment has been minimized.

Copy link
@jpountz

jpountz Jul 19, 2017

Author Contributor

Agreed.

start = 0;
public final void stop() {
if (doTiming) {
timing += (count - lastCount) * Math.max(nanoTime() - start, 1L);

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

If we call start() and stop() in a time frame that is below the resolution of System.nanoTime() (at best ~ 30 ns) then we will have also significant skew here (assuming 1 ns between consecutive calls).

This comment has been minimized.

Copy link
@jpountz

jpountz Jul 18, 2017

Author Contributor

True. This is a pre-existing issue that I don't know how to fix without changing the approach entirely.

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 19, 2017

Member

This was more of a comment than a call-to-action for you. I also do not think that this can be overcome without changing the approach completely. This is the eternal dilemma of tracing vs. sampling. You have to pick one poison. :)

/** Return an approximation of the total time spend between consecutive calls of #start and #stop. */
public long getTiming() {
/** Return an approximation of the total time spent between consecutive calls of #start and #stop. */
public final long getTiming() {

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

We could call this method getApproximateTiming() maybe to indicate that this value is not accurate?

This comment has been minimized.

Copy link
@jpountz

jpountz Jul 18, 2017

Author Contributor

ok

if (start != 0) {
throw new IllegalStateException("#start call misses a matching #stop call");
}
return timing;
// We don't have timings for the last `count-lastCount` method calls
// se we assume that they had the same timing as the lastCount first

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

nit: "so we assume"...

public class TimerTests extends ESTestCase {

public void testTimingInterval() {
final AtomicLong counter = new AtomicLong();

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

Can't you avoid counter and just call #getCount() in the test when you need it?

This comment has been minimized.

Copy link
@jpountz

jpountz Jul 18, 2017

Author Contributor

this counter counts how many times nanoTime is called. I should rename it.

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

Ah, I see. I totally missed that. Renaming is a good idea. :)

return time += 1;
}
};
for (int i = 0; i < 100000; ++i) {

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

nit: unrelated but maybe we should use a separator here and write it as 100_000?

This comment has been minimized.

Copy link
@jpountz

jpountz Jul 18, 2017

Author Contributor

ok

// se we assume that they had the same timing as the lastCount first
// calls. This approximation is ok since at most 1/256th of method
// calls have not been timed.
return timing + (count - lastCount) * timing / lastCount;

This comment has been minimized.

Copy link
@danielmitterdorfer

danielmitterdorfer Jul 18, 2017

Member

Makes sense to me.

jpountz added some commits Jul 18, 2017

@jpountz jpountz merged commit 01f083c into elastic:master Jul 19, 2017

2 checks passed

CLA Commit author is a member of Elasticsearch
Details
elasticsearch-ci Build finished.
Details

@jpountz jpountz deleted the jpountz:fix/reduce_profiling_overhead branch Jul 19, 2017

@jpountz jpountz added >enhancement and removed >bug labels Jul 19, 2017

jpountz added a commit that referenced this pull request Jul 21, 2017

Reduce profiling overhead. (#25772)
Calling `System.nanoTime()` for each method call may have a significant
performance impact.

Closes #24799

@clintongormley clintongormley added v6.0.0-beta1 and removed v6.0.0 labels Jul 25, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.