Neither of {@link TransactionSampler}'s two modes measures that. With "include timers" on it + * leaves the sample stretching from the moment the transaction opened - before the timers and + * pre-processors of the first request ran - to the last response, so a think time lands inside + * the transaction time (issue #155). With it off, {@code setTransactionDone} reports the sum of + * the children instead, which double counts requests that ran at the same time. So the span is + * measured here, out of the children's own stamps, exactly as this controller did up to v3.0.1. + * + *
Also stamps an end time on a transaction that is still open. A transaction that never gets + * one reports {@code 0 - startTime}: {@code setTransactionDone} only stamps it in the + * "include timers" off branch, and {@code JMeterThread} does not call it at all when the run is + * cut short - the scheduler expiring, a manual Stop - it just ends the open transaction where it + * stands. An enclosing Transaction Controller then folds that result in through + * {@code SampleResult.addSubResult}, whose {@code Math.max} keeps the zero, and the enclosing + * sample comes out as a negative epoch that wrecks the Average and the Min of every aggregate + * over the run. + */ + private void measureParentSample(Sampler next) { + if (!(next instanceof TransactionSampler)) { + return; + } + TransactionSampler transactionSampler = (TransactionSampler) next; + if (transactionSampler.isTransactionDone()) { + openParentTransaction = null; + applyRequestSpan(transactionSampler); + return; + } + openParentTransaction = transactionSampler; + SampleResult parent = transactionSampler.getTransactionResult(); + if (parent != null && parent.getEndTime() == 0) { + // Floor: a transaction ended from the outside now reports 0 ms instead of -startTime. Every + // child that arrives afterwards pushes it forward again through addSubResult's Math.max. + parent.setEndTime(parent.getStartTime()); + } + } + + /** + * Rewrites the finished parent sample as {@code lastResponse - firstRequestSent}, leaving what + * came before the first request (timers, pre-processors) in {@code idleTime}, which is the field + * JMeter itself uses for it. Keeps the wall clock reading when the user asked for the timers to + * be included. + * + * @see #isIncludeTimers() + */ + private void applyRequestSpan(TransactionSampler transactionSampler) { + if (isIncludeTimers()) { + return; + } + SampleResult parent = transactionSampler.getTransactionResult(); + if (parent == null) { + return; + } + long firstStart = Long.MAX_VALUE; + long lastEnd = 0; + for (SampleResult child : parent.getSubResults()) { + // Each child's stamps are on its own clock, put on the transaction's the same way + // SampleResult.addSubResult does when it extends a parent's end time (Bug 51855). + if (child.getStartTime() > 0) { + firstStart = Math.min(firstStart, + SampleClock.fromResultClock(parent, child, child.getStartTime())); + } + if (child.getEndTime() > 0) { + lastEnd = Math.max(lastEnd, + SampleClock.fromResultClock(parent, child, child.getEndTime())); + } + } + if (firstStart == Long.MAX_VALUE || lastEnd < firstStart) { + // Nothing was measured: an iteration that was cut short, or children that never got stamps. + parent.setIdleTime(0); + parent.setEndTime(parent.getStartTime()); + return; + } + // elapsed = endTime - startTime - idleTime, so this reads exactly lastEnd - firstStart. Going + // through idleTime rather than a synthetic end time leaves the sample ending when its last + // request did, and holding what came before the first one in the field JMeter's own Transaction + // Controller keeps a pause in (Bug 50080). + parent.setIdleTime(firstStart - parent.getStartTime()); + parent.setEndTime(lastEnd); + } + + /** + * The children of an aborted iteration - Start Next Loop, Stop Thread - are attached by + * {@code super.triggerEndOfLoop()}, which also closes the transaction, so the span can only be + * measured after it. + */ + @Override + public void triggerEndOfLoop() { + TransactionSampler ending = openParentTransaction; + openParentTransaction = null; + super.triggerEndOfLoop(); + if (ending != null) { + applyRequestSpan(ending); + } + } + + /** + * Same question a stock Transaction Controller asks, with the opposite default: a think time is a + * pause, not request time, and this controller has never counted it. Answering {@code true} by + * inheritance - which is what JMeter's own default does, for compatibility with test plans older + * than its checkbox - is what put the think time inside the transaction time in v3.1.0. An + * explicit value, from this element's GUI or from a JMX written against a stock Transaction + * Controller, is honoured. + */ + @Override + public boolean isIncludeTimers() { + return containsElementPropertyNamed(INCLUDE_TIMERS) + && getPropertyAsBoolean(INCLUDE_TIMERS, false); + } + + /** + * Always writes the property. {@code TransactionController.setIncludeTimers} drops it when it + * matches JMeter's default of {@code true}, which would leave this controller reading its own + * default of {@code false} and silently discard the user's choice. + */ + @Override + public void setIncludeTimers(boolean includeTimers) { + setProperty(INCLUDE_TIMERS, includeTimers); + } + /** * Same workaround as JMeter PR #6386: when the parent transaction has finished, replace the * completed {@link TransactionSampler} in this controller's {@link SamplePackage} with a fresh diff --git a/src/main/java/com/blazemeter/jmeter/http2/control/gui/HTTP2ControllerGUI.java b/src/main/java/com/blazemeter/jmeter/http2/control/gui/HTTP2ControllerGUI.java index fe8e4471..a5981f4b 100644 --- a/src/main/java/com/blazemeter/jmeter/http2/control/gui/HTTP2ControllerGUI.java +++ b/src/main/java/com/blazemeter/jmeter/http2/control/gui/HTTP2ControllerGUI.java @@ -18,12 +18,15 @@ public class HTTP2ControllerGUI extends AbstractControllerGui implements Scrollable { private static final long serialVersionUID = 240L; private final JCheckBox generateControllerSample; + private final JCheckBox includeTimers; private final JCheckBox limitMaxParallel; private final JTextField maxParallelField; private int defaultMaxParallel; public HTTP2ControllerGUI() { generateControllerSample = new JCheckBox("Generate Parent Sample"); + includeTimers = new JCheckBox( + "Include duration of timer and pre-post processors in generated sample"); limitMaxParallel = new JCheckBox("Limit max number of parallel executions"); maxParallelField = new JTextField(8); init(); @@ -47,6 +50,7 @@ public void modifyTestElement(TestElement el) { if (el instanceof HTTP2Controller) { HTTP2Controller controller = (HTTP2Controller) el; controller.setGenerateControllerSample(generateControllerSample.isSelected()); + controller.setIncludeTimers(includeTimers.isSelected()); controller.setLimitMaxParallel(limitMaxParallel.isSelected()); if (limitMaxParallel.isSelected()) { controller.setMaxConcurrentAsyncInController(parseMaxParallelValue()); @@ -60,6 +64,8 @@ public void configure(TestElement element) { if (element instanceof HTTP2Controller) { HTTP2Controller controller = (HTTP2Controller) element; generateControllerSample.setSelected(controller.isGenerateControllerSample()); + includeTimers.setSelected(controller.isIncludeTimers()); + updateIncludeTimersState(controller.isGenerateControllerSample()); limitMaxParallel.setSelected(controller.isLimitMaxParallel()); maxParallelField.setText(String.valueOf(controller.getMaxConcurrentAsyncInController())); updateMaxParallelFieldState(controller); @@ -78,6 +84,11 @@ private void init() { add(makeTitlePanel(), BorderLayout.NORTH); add(buildOptionsPanel(), BorderLayout.CENTER); + // The timer question only exists for the sample this controller generates itself: with no + // parent sample there is nothing whose duration could include them. + generateControllerSample.addItemListener( + event -> updateIncludeTimersState(event.getStateChange() == ItemEvent.SELECTED)); + limitMaxParallel.addItemListener(event -> { boolean enabled = event.getStateChange() == ItemEvent.SELECTED; updateMaxParallelFieldState(enabled); @@ -99,6 +110,9 @@ private JPanel buildOptionsPanel() { generateControllerSample.setAlignmentX(JCheckBox.LEFT_ALIGNMENT); panel.add(generateControllerSample); + includeTimers.setAlignmentX(JCheckBox.LEFT_ALIGNMENT); + panel.add(includeTimers); + limitMaxParallel.setAlignmentX(JCheckBox.LEFT_ALIGNMENT); panel.add(limitMaxParallel); @@ -110,6 +124,10 @@ private JPanel buildOptionsPanel() { return panel; } + private void updateIncludeTimersState(boolean generatesParentSample) { + includeTimers.setEnabled(generatesParentSample); + } + private void updateMaxParallelFieldState(HTTP2Controller controller) { defaultMaxParallel = controller.getDefaultMaxConcurrentAsyncInController(); updateMaxParallelFieldState(controller.isLimitMaxParallel()); diff --git a/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2FutureResponseListener.java b/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2FutureResponseListener.java index e24ee71d..f2aba2e3 100644 --- a/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2FutureResponseListener.java +++ b/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2FutureResponseListener.java @@ -8,6 +8,7 @@ import java.nio.charset.IllegalCharsetNameException; import java.nio.charset.StandardCharsets; import java.nio.charset.UnsupportedCharsetException; +import java.util.OptionalLong; import java.util.concurrent.CancellationException; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutionException; @@ -15,6 +16,7 @@ import java.util.concurrent.TimeUnit; import java.util.concurrent.TimeoutException; import java.util.concurrent.atomic.AtomicBoolean; +import org.apache.jmeter.samplers.SampleResult; import org.eclipse.jetty.client.AbstractResponseListener; import org.eclipse.jetty.client.BufferingResponseListener; import org.eclipse.jetty.client.ContentResponse; @@ -48,8 +50,14 @@ public class HTTP2FutureResponseListener extends BufferingResponseListener * origin, while the competing attempt still serves the request. See {@link #onComplete}. */ private volatile String raceProtocol; - private long responseStart; - private long responseEnd; + /** + * When the request went out and when it completed. Written on a Jetty thread and read on the + * JMeter one, so each end is a single immutable value published through one volatile write: + * whoever reads a {@link Stamp} sees all of it, and never a wall-clock reading paired with a + * monotonic one that has not been taken yet. + */ + private volatile Stamp responseStartStamp; + private volatile Stamp responseEndStamp; /** * {@link #releaseTransportBuffers()} is invoked from several completion paths (wrapper build, * sealed HE abort {@code onFailure}/{@code onComplete}, {@code cancel}, sample materialisation). @@ -91,21 +99,62 @@ public String getRaceProtocol() { } protected void setStart() { - if (this.responseStart == 0) { - this.responseStart = System.currentTimeMillis(); + if (this.responseStartStamp == null) { + this.responseStartStamp = Stamp.now(); } } protected void setEnd() { - this.responseEnd = System.currentTimeMillis(); + this.responseEndStamp = Stamp.now(); } + /** + * When the request went out as a {@link System#currentTimeMillis()} time, or 0. An absolute time + * to report or to log; to stamp it on a sample use {@link #getResponseStartOn}, and to measure a + * wait from it use {@link #getResponseStartNanos}. + */ public long getResponseStart() { - return this.responseStart; + return Stamp.wallClockOf(this.responseStartStamp); } + /** + * When the exchange completed as a {@link System#currentTimeMillis()} time, or 0. See + * {@link #getResponseStart()} for which of these three readings to use. + */ public long getResponseEnd() { - return this.responseEnd; + return Stamp.wallClockOf(this.responseEndStamp); + } + + /** + * The {@link System#nanoTime()} reading of when the request went out, empty only when the request + * never went out at all. + * + *
For measuring how long something has been waiting, which must not be thrown off by the + * machine clock moving under it. + */ + public OptionalLong getResponseStartNanos() { + Stamp stamp = this.responseStartStamp; + return stamp == null ? OptionalLong.empty() : OptionalLong.of(stamp.nanoTime); + } + + /** + * When the request went out, on {@code result}'s own clock, or 0 when that was never recorded. + * + *
This, and never {@link #getResponseStart()}, is what a {@link SampleResult} must be stamped + * from: a sample whose start comes from {@code sampleStart()} and whose end comes from the wall + * clock reports the distance between those two clocks as part of its duration. See + * {@link SampleClock}. + */ + public long getResponseStartOn(SampleResult result) { + return Stamp.on(result, this.responseStartStamp); + } + + /** + * When the exchange completed, on {@code result}'s own clock, or 0 when that was never recorded. + * See {@link #getResponseStartOn}. + */ + public long getResponseEndOn(SampleResult result) { + return Stamp.on(result, this.responseEndStamp); } /** @@ -120,13 +169,36 @@ public long getResponseEnd() { * synchronous caller never noticed because it returns the winner directly instead of reading back * from here; a consumer that polls {@link #isDone()} and then calls {@link #get()} does. */ + public void completeWith(ContentResponse response, HTTP2FutureResponseListener source) { + if (source.responseStartStamp != null) { + this.responseStartStamp = source.responseStartStamp; + } + this.responseEndStamp = + source.responseEndStamp != null ? source.responseEndStamp : Stamp.now(); + seal(response); + } + + /** + * Adopts a result timed only on the wall clock. Prefer + * {@link #completeWith(ContentResponse, HTTP2FutureResponseListener)}, which is what the protocol + * race uses: it carries the winner's monotonic readings over as well, so the sample stamped from + * this listener is translated from the exchange it actually reports. + */ public void completeWith(ContentResponse response, long responseStart, long responseEnd) { - this.response = response; - this.failure = null; if (responseStart > 0) { - this.responseStart = responseStart; + // These stamps describe another exchange, so this listener's own monotonic readings do not + // match them and must not be used to translate them. + this.responseStartStamp = Stamp.ofWallClock(responseStart); } - this.responseEnd = responseEnd > 0 ? responseEnd : System.currentTimeMillis(); + this.responseEndStamp = + responseEnd > 0 ? Stamp.ofWallClock(responseEnd) : Stamp.now(); + seal(response); + } + + /** Stores the adopted response and seals this listener: common tail of {@code completeWith}. */ + private void seal(ContentResponse response) { + this.response = response; + this.failure = null; this.onCompleteCalled = true; this.sealed = true; // Drop any partial body this listener may have buffered for its own (losing) attempt — the @@ -585,5 +657,59 @@ private ContentResponse getResult() throws ExecutionException, ProtocolErrorExce return response; } + /** + * One instant of the exchange, read on both clocks at once so a consumer can pick the one it + * needs: the wall clock to report an absolute time, the monotonic reading to measure a duration + * or to translate the instant onto a {@link SampleResult}'s clock. + * + *
Immutable, so publishing it through a single volatile field is enough for a JMeter thread to + * see a whole instant rather than half of one written by a Jetty thread. + */ + private static final class Stamp { + + private final long wallClockMillis; + private final long nanoTime; + /** Whether {@link #nanoTime} belongs to this instant, rather than never having been taken. */ + private final boolean monotonic; + + private Stamp(long wallClockMillis, long nanoTime, boolean monotonic) { + this.wallClockMillis = wallClockMillis; + this.nanoTime = nanoTime; + this.monotonic = monotonic; + } + + private static Stamp now() { + // The monotonic reading first: it is the one this instant gets translated with, the wall + // clock one is only ever reported as it is. + long nanoTime = System.nanoTime(); + return new Stamp(System.currentTimeMillis(), nanoTime, true); + } + + /** + * An instant known only as a wall-clock time, adopted from another exchange. Its monotonic + * counterpart is derived from how long ago it was, so measuring a wait from it still works; + * {@code monotonic} stays false because the derivation already went through the wall clock and + * translating it again would compound the two conversions. + */ + private static Stamp ofWallClock(long wallClockMillis) { + long nanoTime = System.nanoTime() + - TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis() - wallClockMillis); + return new Stamp(wallClockMillis, nanoTime, false); + } + + private static long wallClockOf(Stamp stamp) { + return stamp == null ? 0 : stamp.wallClockMillis; + } + + /** This instant on {@code result}'s own clock, or 0 when there is no instant. */ + private static long on(SampleResult result, Stamp stamp) { + if (stamp == null) { + return 0; + } + return stamp.monotonic + ? SampleClock.fromNanoTime(result, stamp.nanoTime) + : SampleClock.fromWallClock(result, stamp.wallClockMillis); + } + } } diff --git a/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2JettyClient.java b/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2JettyClient.java index d0c466f6..a35d292e 100644 --- a/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2JettyClient.java +++ b/src/main/java/com/blazemeter/jmeter/http2/core/HTTP2JettyClient.java @@ -1913,7 +1913,7 @@ public HTTPSampleResult sample(HTTP2Sampler sampler, HTTPSampleResult result, lowLevelDebug("=== send() returned successfully ==="); postContentResponse(sampler, request, result, contentResponse, cacheManager); - result.setEndTime(listener.getResponseEnd()); + stampSampleEnd(result, listener); resetSamplerDataBeforeResultProcessing(result); return sampler.resultProcessing(areFollowingRedirect, depth, result); @@ -1968,6 +1968,27 @@ private HTTPSampleResult sampleLocalFile(HTTP2Sampler sampler, HTTPSampleResult return sampler.resultProcessing(areFollowingRedirect, depth, result); } + /** + * Ends the sample when the exchange ended, translated onto this result's own clock: the start + * came from {@code sampleStart()}, and a {@link org.apache.jmeter.samplers.SampleResult} keeps a + * nano-derived clock of its own by default, so reading the end straight off the listener's + * wall-clock stamp reported the distance between the two clocks as part of the sample's duration. + * See {@link SampleClock}. + * + *
Falls back to {@code sampleEnd()} when the exchange never recorded a completion. Stamping + * what the listener held in that case wrote a 0, and {@code setEndTime} turns a zero end into an + * elapsed time of minus the start of the epoch. + */ + private static void stampSampleEnd(HTTPSampleResult result, + HTTP2FutureResponseListener listener) { + long endTime = listener.getResponseEndOn(result); + if (endTime > 0) { + result.setEndTime(endTime); + } else if (result.getEndTime() == 0) { + result.sampleEnd(); + } + } + public HTTPSampleResult sampleFromListener(HTTP2Sampler sampler, HTTPSampleResult result, boolean areFollowingRedirect, int depth, HTTP2FutureResponseListener listener @@ -1981,7 +2002,7 @@ public HTTPSampleResult sampleFromListener(HTTP2Sampler sampler, HTTPSampleResul JettyCacheManager cacheManager = JettyCacheManager.fromCacheManager(sampler.getCacheManager()); postContentResponse(sampler, request, result, contentResponse, cacheManager); - result.setEndTime(listener.getResponseEnd()); + stampSampleEnd(result, listener); resetSamplerDataBeforeResultProcessing(result); return sampler.resultProcessing(areFollowingRedirect, depth, result); @@ -2008,7 +2029,11 @@ public HTTPSampleResult sampleFromListener(HTTP2Sampler sampler, HTTPSampleResul JettyCacheManager cacheManager = JettyCacheManager.fromCacheManager(sampler.getCacheManager()); postContentResponse(sampler, request, result, retryResponse, cacheManager); - result.setEndTime(listener.getResponseEnd()); + // Not from the listener: the only completion it ever recorded is the GOAWAY that killed + // the first attempt. retryAfterGoAway sends a clone of its own and returns the response + // it got, so the sample ends now - stamping the listener's end reported a sample that + // finished before the response it carries, missing the whole retry. + result.setEndTime(result.currentTimeInMillis()); resetSamplerDataBeforeResultProcessing(result); return sampler.resultProcessing(areFollowingRedirect, depth, result); } catch (Exception retryException) { @@ -2334,8 +2359,7 @@ private ProtocolRace startProtocolRace(Request h3Request, h2Request.abort(new java.util.concurrent.CancellationException( "Happy Eyeballs H3 won")); } else { - h3Listener.completeWith(response, - h2Listener.getResponseStart(), h2Listener.getResponseEnd()); + h3Listener.completeWith(response, h2Listener); h3Request.abort(new java.util.concurrent.CancellationException( "Happy Eyeballs H2 won")); } diff --git a/src/main/java/com/blazemeter/jmeter/http2/core/SampleClock.java b/src/main/java/com/blazemeter/jmeter/http2/core/SampleClock.java new file mode 100644 index 00000000..1ebadff5 --- /dev/null +++ b/src/main/java/com/blazemeter/jmeter/http2/core/SampleClock.java @@ -0,0 +1,105 @@ +package com.blazemeter.jmeter.http2.core; + +import org.apache.jmeter.samplers.SampleResult; + +/** + * Puts a time taken by the Jetty transport on the clock the {@link SampleResult} it is about to be + * stamped on keeps its own times in, and stamps an interval that was measured elsewhere. + * + *
A {@code SampleResult} does not read {@link System#currentTimeMillis()} when + * {@code sampleresult.useNanoTime} is on, which is JMeter's shipped default: every stamp of its own + * comes from {@code System.nanoTime() / 1_000_000} plus an offset the instance captures once, at + * construction, from a value a daemon refreshes every {@code sampleresult.nanoThreadSleep} ms (5 s + * by default). A wall-clock reading and a {@code SampleResult}-clock reading of the same instant + * therefore differ by however stale that offset is, and {@link SampleResult#setEndTime} turns the + * difference straight into reported sample time, since it computes + * {@code elapsed = end - start - idle}. Taking a sample's start from {@code sampleStart()} and its + * end from the wall clock is not a rounding error, it is a measurement across two clocks - which is + * why JMeter's own HTTP samplers only ever stamp through {@code sampleEnd()}, + * {@code latencyEnd()} and {@code connectEnd()}. + * + *
Every conversion here is expressed as "how far is that clock from this result's clock right + * now", which is exact when {@code useNanoTime} is off - both clocks are then the same one - and + * within the 1 ms resolution of the offset when it is on. + */ +public final class SampleClock { + + /** + * Whether {@link SampleResult#setStampAndTime(long, long)} reads its first argument as the start + * of the sample. It reads it as the end when {@code sampleresult.timestamp.start} is off, and + * JMeter's shipped {@code jmeter.properties} turns it on while the property's built-in default is + * off - so which one a run uses cannot be assumed either way. Measured from the behaviour itself + * rather than read from the property, so this agrees with whatever {@code SampleResult} settled + * on when its own class was initialised. + */ + private static final boolean STAMP_IS_START = probeStampIsStart(); + + private SampleClock() { + } + + /** + * Converts a {@link System#nanoTime()} reading into {@code result}'s clock. + * + *
Preferred over {@link #fromWallClock}: a monotonic reading cannot be displaced by an NTP + * step, or by an operator moving the machine clock, between the moment it was taken and the + * moment the sample is stamped. + */ + public static long fromNanoTime(SampleResult result, long nanoTime) { + return nanoClockMillis(nanoTime) + + (result.currentTimeInMillis() - nanoClockMillis(System.nanoTime())); + } + + /** + * Converts a {@link System#currentTimeMillis()} reading into {@code result}'s clock. For instants + * no monotonic reading was taken for. + */ + public static long fromWallClock(SampleResult result, long wallClockMillis) { + return wallClockMillis + (result.currentTimeInMillis() - System.currentTimeMillis()); + } + + /** + * Converts a time on {@code result}'s clock back to {@link System#currentTimeMillis()}, for + * comparing a sample's own stamps against times recorded on the wall clock. + */ + public static long toWallClock(SampleResult result, long resultClockMillis) { + return resultClockMillis + (System.currentTimeMillis() - result.currentTimeInMillis()); + } + + /** + * Converts a time held by {@code source} into {@code target}'s clock. Two results capture their + * offset from the refreshing one at whatever moment each was constructed, so a sample and a + * sub-sample of it are on the same clock only as long as no refresh happened in between - which + * for a transaction holding a think time is not a given. + * + *
The same correction {@code SampleResult.addSubResult} applies for JMeter's Bug 51855 when it + * extends a parent's end time with a sub-result's, expressed through the public clock rather than + * the private offset field the class reads there. + */ + public static long fromResultClock(SampleResult target, SampleResult source, long time) { + return time + (target.currentTimeInMillis() - source.currentTimeInMillis()); + } + + /** + * Stamps a sample that was timed outside of it: {@code start} on the result's own clock (see + * {@link #fromNanoTime}) and how long it took. Both come out of the sample as given, whichever + * end of the interval {@code sampleresult.timestamp.start} makes + * {@link SampleResult#setStampAndTime(long, long)} take as its stamp. + * + * @throws IllegalStateException if {@code result} is already stamped, as + * {@code setStampAndTime} does + */ + public static void stampInterval(SampleResult result, long start, long elapsedMillis) { + result.setStampAndTime(STAMP_IS_START ? start : start + elapsedMillis, elapsedMillis); + } + + /** Mirrors {@code SampleResult.sampleNsClockInMs()}, truncation to whole millis included. */ + private static long nanoClockMillis(long nanoTime) { + return nanoTime / 1_000_000L; + } + + private static boolean probeStampIsStart() { + SampleResult probe = new SampleResult(); + probe.setStampAndTime(1_000L, 100L); + return probe.getStartTime() == 1_000L; + } +} diff --git a/src/main/java/com/blazemeter/jmeter/http2/sampler/HTTP2Sampler.java b/src/main/java/com/blazemeter/jmeter/http2/sampler/HTTP2Sampler.java index 8961ab8c..f6c64d2e 100644 --- a/src/main/java/com/blazemeter/jmeter/http2/sampler/HTTP2Sampler.java +++ b/src/main/java/com/blazemeter/jmeter/http2/sampler/HTTP2Sampler.java @@ -9,6 +9,7 @@ import com.blazemeter.jmeter.http2.core.JMeterSourceAddressResolver; import com.blazemeter.jmeter.http2.core.JmeterHttpClientExceptionMapper; import com.blazemeter.jmeter.http2.core.ProtocolErrorException; +import com.blazemeter.jmeter.http2.core.SampleClock; import com.blazemeter.jmeter.http2.util.BzmHttpPluginProperties; import com.blazemeter.jmeter.http2.util.Rfc9110Redirects; import com.github.benmanes.caffeine.cache.Caffeine; @@ -30,6 +31,7 @@ import java.util.Objects; import java.util.concurrent.Callable; import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.TimeUnit; import java.util.concurrent.TimeoutException; import java.util.function.Predicate; import java.util.regex.PatternSyntaxException; @@ -572,8 +574,13 @@ private HTTPSampleResult buildErrorResult(Exception e, HTTPSampleResult result) result.sampleStart(); } if (result.getEndTime() == 0) { - if (!Objects.isNull(this.asyncListener) && this.asyncListener.getResponseEnd() != 0) { - result.setEndTime(this.asyncListener.getResponseEnd()); + // On this result's own clock: its start came from sampleStart(), and the listener records the + // exchange on the wall clock. See SampleClock. + long responseEnd = Objects.isNull(this.asyncListener) + ? 0 + : this.asyncListener.getResponseEndOn(result); + if (responseEnd > 0) { + result.setEndTime(responseEnd); } else { result.sampleEnd(); } @@ -591,6 +598,11 @@ private HTTPSampleResult buildErrorResult(Exception e, HTTPSampleResult result) *
Reads the client already cached for this thread instead of asking the factory: building one * here would be a side effect on the error path, and a sample that never got that far has * nothing recorded anyway. + * + *
The recorder keeps its attempts on the wall clock, so the sample's own start is converted
+ * before being used to select them: comparing the two clocks directly dropped attempts of this
+ * very sample, or picked up attempts of the previous one, by however far apart the clocks were.
+ * See {@link SampleClock}.
*/
private void attachConnectAttempts(Throwable failure, HTTPSampleResult result) {
if (failure == null || result.getURL() == null) {
@@ -599,7 +611,11 @@ private void attachConnectAttempts(Throwable failure, HTTPSampleResult result) {
try {
HTTP2JettyClient client = CONNECTIONS.get().get(buildConnectionKey());
if (client != null) {
- client.attachConnectAttempts(failure, result.getURL(), result.getStartTime());
+ long sampleStart = result.getStartTime();
+ client.attachConnectAttempts(failure, result.getURL(),
+ // 0 is the recorder's "everything held", and must stay a 0 rather than become the
+ // distance between the clocks.
+ sampleStart == 0 ? 0 : SampleClock.toWallClock(result, sampleStart));
}
} catch (Exception ignored) {
// Diagnostics must never replace the failure the sample is actually reporting.
@@ -650,11 +666,12 @@ HTTPSampleResult detachedErrorResult(Throwable cause, HTTPSampleResult parent) {
* {@code sampleStart}/{@code sampleEnd} back-to-back left elapsed at ~0 and made the page look
* like it finished when the last fast image landed.
*
- * @param startedAtMs when this resource's attempt began (dispatch / listener start), used as the
- * sample start so the reported duration matches the timeout wait
+ * @param startedAtNanos {@link System#nanoTime()} when this resource's attempt began (dispatch /
+ * listener start). Monotonic, so the reported duration is the wait itself
+ * and not the wait plus whatever the machine clock did meanwhile
*/
private HTTPSampleResult embeddedTimeoutErrorResult(HTTP2Sampler embeddedSampler,
- long startedAtMs) {
+ long startedAtNanos) {
HTTPSampleResult err = new HTTPSampleResult();
URL url = resolveEmbeddedResourceUrl(embeddedSampler);
if (url != null) {
@@ -666,21 +683,25 @@ private HTTPSampleResult embeddedTimeoutErrorResult(HTTP2Sampler embeddedSampler
err.setSampleLabel(embeddedSampler.getName());
}
err.setHTTPMethod(HTTPConstants.GET);
- long endedAtMs = System.currentTimeMillis();
- long elapsedMs = Math.max(0L, endedAtMs - startedAtMs);
- // SampleResult.setStampAndTime(stamp, elapsed) treats stamp as start (end = stamp + elapsed).
- err.setStampAndTime(startedAtMs, elapsedMs);
+ long elapsedMs =
+ Math.max(0L, TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startedAtNanos));
+ // Start on this result's own clock and the wait measured monotonically, so both the timestamps
+ // and the duration hold whichever end of the interval setStampAndTime takes as its stamp.
+ SampleClock.stampInterval(err, SampleClock.fromNanoTime(err, startedAtNanos), elapsedMs);
err.setConnectTime(0L);
err.setLatency(0L);
return errorResult(new SocketTimeoutException("Read timed out"), err);
}
- private long embeddedAttemptStartMillis(HTTP2Sampler embeddedSampler) {
+ /**
+ * When this resource's attempt went out, as a {@link System#nanoTime()} reading, falling back to
+ * now for a sampler whose request never reached the transport.
+ */
+ private long embeddedAttemptStartNanos(HTTP2Sampler embeddedSampler) {
HTTP2FutureResponseListener listener = embeddedSampler.getFutureResponseListener();
- if (listener != null && listener.getResponseStart() > 0) {
- return listener.getResponseStart();
- }
- return System.currentTimeMillis();
+ return listener == null
+ ? System.nanoTime()
+ : listener.getResponseStartNanos().orElseGet(System::nanoTime);
}
private URL resolveEmbeddedResourceUrl(HTTP2Sampler embeddedSampler) {
@@ -710,12 +731,12 @@ private void failPendingEmbeddedRequestsWithTimeout(List What the parent sample of this controller must measure is the wall clock the controller spent
+ * on its requests: for a sequential controller that is the sum of the child times, and for a
+ * parallel one it is the span from the first dispatch to the last response. Timers and pre/post
+ * processors are pauses, not request time, so they are excluded — which is what v3.0.1 did by
+ * building the parent sample from {@code min(child start)} to {@code max(child end)}.
+ *
+ * The stock Transaction Controller is deliberately NOT the baseline for the times here, unlike
+ * the rest of this suite: it runs its children sequentially, so span and sum coincide for it, and
+ * its own {@code includeTimers} defaults to {@code true}, so its parent sample counts the think
+ * time on purpose. Only {@link #t4ATransactionCutShortMustNotReportANegativeSampleTime()} compares
+ * against it, because there stock defines what "not broken" looks like.
+ */
+public class AsyncControllerTransactionTimingTest extends HTTP2TestBase {
+
+ private static final long LATENCY = 120L;
+ private static final long THINK_TIME = 800L;
+
+ @Test
+ public void t1ThinkTimeMustNotBeCountedInTheParentSampleTime() {
+ TreeShape shape = fixture -> new AsyncScenarioRunner.Node[]{
+ node(fixture.controller("controller"),
+ node(fixture.http("S1", LATENCY), node(fixture.timer("think-time", THINK_TIME))),
+ node(fixture.http("S2", LATENCY)))
+ };
+ Result actual = execute(ControllerKind.ASYNC_PARENT, 1, shape);
+ SampleResult parent = actual.topLevelResult("controller");
+ report("T1 controller[S1[think time " + THINK_TIME + "ms], S2]", actual, parent);
+
+ SoftAssertions softly = new SoftAssertions();
+ softly.assertThat(parent).as("a parent sample must be reported").isNotNull();
+ if (parent != null) {
+ softly.assertThat(parent.getTime())
+ .as("the %s ms think time of S1 is a pause, not request time, so it must stay out of the "
+ + "controller's own sample time", THINK_TIME)
+ .isLessThan(THINK_TIME);
+ softly.assertThat(parent.getTime())
+ .as("the parent sample must measure the span of its requests")
+ .isEqualTo(requestSpan(parent));
+ softly.assertThat(parent.getTime())
+ .as("a sample time can never be negative")
+ .isNotNegative();
+ }
+ softly.assertAll();
+ }
+
+ @Test
+ public void t2ParentSampleTimeMustBeTheSpanOfTheOverlappedRequestsNotTheirSum() {
+ TreeShape shape = fixture -> new AsyncScenarioRunner.Node[]{
+ node(fixture.controller("controller"),
+ node(fixture.http("S1", 300)),
+ node(fixture.http("S2", 300)),
+ node(fixture.http("S3", 300)))
+ };
+ Result actual = execute(ControllerKind.ASYNC_PARENT, 1, shape);
+ SampleResult parent = actual.topLevelResult("controller");
+ report("T2 controller[S1, S2, S3] all 300ms", actual, parent);
+
+ SoftAssertions softly = new SoftAssertions();
+ softly.assertThat(actual.maxConcurrentInFlight())
+ .as("precondition: the requests really overlapped")
+ .isGreaterThan(1);
+ softly.assertThat(parent).as("a parent sample must be reported").isNotNull();
+ if (parent != null) {
+ softly.assertThat(parent.getTime())
+ .as("three requests that ran at the same time took as long as the slowest of them, not "
+ + "as long as all of them one after another (%s ms)", sumOfChildTimes(parent))
+ .isLessThan(sumOfChildTimes(parent));
+ softly.assertThat(parent.getTime())
+ .as("the parent sample must measure the span of its requests")
+ .isEqualTo(requestSpan(parent));
+ }
+ softly.assertAll();
+ }
+
+ @Test
+ public void t3ThinkTimeMustNotBubbleUpToAnEnclosingTransactionController() {
+ TreeShape shape = fixture -> new AsyncScenarioRunner.Node[]{
+ node(enclosingTransaction(fixture),
+ node(fixture.controller("controller"),
+ node(fixture.http("S1", LATENCY), node(fixture.timer("think-time", THINK_TIME))),
+ node(fixture.http("S2", LATENCY))))
+ };
+ Result actual = execute(ControllerKind.ASYNC_PARENT, 1, shape);
+ SampleResult outer = actual.topLevelResult("tx");
+ SampleResult inner = outer == null ? null : firstChild(outer);
+ report("T3 tx(parent, includeTimers=false)[controller[S1[think time], S2]]", actual, outer);
+
+ SoftAssertions softly = new SoftAssertions();
+ softly.assertThat(outer).as("the enclosing transaction must be reported").isNotNull();
+ softly.assertThat(inner).as("the controller sample must be nested in it").isNotNull();
+ if (outer != null && inner != null) {
+ softly.assertThat(inner.getTime())
+ .as("the controller's own sample time must exclude the think time")
+ .isLessThan(THINK_TIME);
+ softly.assertThat(outer.getTime())
+ .as("an enclosing transaction sums the times of its children, so a think time counted by "
+ + "the controller bubbles straight up into it")
+ .isLessThan(THINK_TIME);
+ softly.assertThat(outer.getTime())
+ .as("the enclosing transaction has a single child, so it must report that child's time")
+ .isEqualTo(inner.getTime());
+ }
+ softly.assertAll();
+ }
+
+ @Test
+ public void t4ATransactionCutShortMustNotReportANegativeSampleTime() {
+ TreeShape shape = fixture -> new AsyncScenarioRunner.Node[]{
+ node(enclosingTransaction(fixture),
+ node(fixture.controller("controller"),
+ node(fixture.http("S1", LATENCY)),
+ node(fixture.http("S2", LATENCY))))
+ };
+ Result baseline = execute(ControllerKind.STOCK_TX_PARENT, 1, shape,
+ AsyncScenarioRunner.expiredScheduler());
+ Result actual = execute(ControllerKind.ASYNC_PARENT, 1, shape,
+ AsyncScenarioRunner.expiredScheduler());
+ System.out.println("\n=== T4 scheduler already expired, transaction cut short ==="
+ + "\n stock: " + describeAll(baseline)
+ + "\n async: " + describeAll(actual));
+
+ SoftAssertions softly = new SoftAssertions();
+ assertReportsDurationsNotEpochs(softly, "stock", baseline);
+ assertReportsDurationsNotEpochs(softly, "async", actual);
+ softly.assertAll();
+ }
+
+ /**
+ * The defect is a transaction that was never given an end time: {@code elapsed = end - start} then
+ * reports {@code 0 - startTime}, an epoch, and that single row wrecks the Average and the Min of
+ * every aggregate over the run. Both halves are asserted, since the missing end time is the cause
+ * and the negative duration is what a report shows.
+ */
+ private static void assertReportsDurationsNotEpochs(SoftAssertions softly, String kind,
+ Result result) {
+ for (SampleResult sample : allResults(result)) {
+ softly.assertThat(sample.getEndTime())
+ .as("%s: '%s' was ended without an end time being stamped, which is what turns into "
+ + "0 - startTime", kind, sample.getSampleLabel())
+ .isPositive();
+ softly.assertThat(sample.getTime())
+ .as("%s: '%s' was reported with %s ms", kind, sample.getSampleLabel(), sample.getTime())
+ .isNotNegative();
+ }
+ }
+
+ /** Mirrors issue #155's test plan: parent sample on, think time excluded. */
+ private static TransactionController enclosingTransaction(ScenarioFixture fixture) {
+ TransactionController transaction = fixture.stockTransaction("tx", true);
+ transaction.setIncludeTimers(false);
+ return transaction;
+ }
+
+ /** From the first dispatch to the last response, i.e. what a parallel block really took. */
+ private static long requestSpan(SampleResult parent) {
+ long firstStart = Long.MAX_VALUE;
+ long lastEnd = 0;
+ for (SampleResult child : children(parent)) {
+ if (child.getStartTime() > 0) {
+ firstStart = Math.min(firstStart, child.getStartTime());
+ }
+ lastEnd = Math.max(lastEnd, child.getEndTime());
+ }
+ return firstStart == Long.MAX_VALUE ? 0 : lastEnd - firstStart;
+ }
+
+ private static long sumOfChildTimes(SampleResult parent) {
+ long total = 0;
+ for (SampleResult child : children(parent)) {
+ total += child.getTime();
+ }
+ return total;
+ }
+
+ private static SampleResult firstChild(SampleResult parent) {
+ List The delay is applied on every call, not only when the timer is created: a scenario that asks
+ * for the same name twice used to keep whichever delay came first, so a test asserting on a think
+ * time could silently run with none and pass without measuring anything.
+ */
+ public CountingTimer timer(String name, long delayMillis) {
+ CountingTimer timer = timers.computeIfAbsent(name, CountingTimer::new);
+ timer.setDelay(delayMillis);
+ return timer;
}
public CountingPreProcessor pre(String name) {
@@ -358,6 +373,14 @@ public Result run(ThreadGroup group, long timeoutMillis,
return new Result(this, AsyncScenarioRunner.run(group, timeoutMillis, children));
}
+ /** @see AsyncScenarioRunner#run(ThreadGroup, long, Consumer, AsyncScenarioRunner.Node...) */
+ public Result run(ThreadGroup group, long timeoutMillis,
+ Consumer A {@link SampleResult} derives every stamp of its own from {@code System.nanoTime()} plus an
+ * offset it captures at construction, while {@link HTTP2FutureResponseListener} records the exchange
+ * on the wall clock as well. Taking a sample's start from {@code sampleStart()} and its end from the
+ * listener's wall-clock reading therefore reported the distance between those two clocks as part of
+ * the duration: single-digit milliseconds in a healthy run, but bounded only by how stale that
+ * offset is. See {@link SampleClock}.
+ *
+ * The distance is made deterministic here by moving the result's own offset - the same thing a
+ * stale refresh does at runtime, only by an amount worth asserting on.
+ */
+public class SampleClockTest extends HTTP2TestBase {
+
+ private static final long SKEW_MILLIS = 250L;
+ private static final long EXCHANGE_MILLIS = 60L;
+ /** The exchange is simulated with a sleep, so its duration is a lower bound, not an equality. */
+ private static final long SCHEDULING_SLACK_MILLIS = 400L;
+ /** Two truncations to whole milliseconds, plus the gap between reading the two clocks. */
+ private static final long TRANSLATION_SLACK_MILLIS = 5L;
+
+ @Test
+ public void endTakenFromTheListenerMustNotAbsorbTheDistanceBetweenTheClocks() throws Exception {
+ HTTPSampleResult result = new HTTPSampleResult();
+ assumeSampleClockMovedBy(result, SKEW_MILLIS);
+ result.sampleStart();
+
+ HTTP2FutureResponseListener listener = new HTTP2FutureResponseListener(-1);
+ Thread.sleep(EXCHANGE_MILLIS);
+ listener.setEnd();
+
+ assertThat(listener.getResponseEnd() - result.getStartTime())
+ .as("the raw wall-clock reading the sample used to be stamped with sits before its own "
+ + "start here, which is what corrupted the duration")
+ .isNegative();
+
+ result.setEndTime(listener.getResponseEndOn(result));
+
+ assertThat(result.getTime())
+ .as("the duration must be the exchange, not the exchange shifted by %d ms of clock "
+ + "distance", SKEW_MILLIS)
+ .isBetween(EXCHANGE_MILLIS, EXCHANGE_MILLIS + SCHEDULING_SLACK_MILLIS);
+ }
+
+ @Test
+ public void endTakenFromTheListenerMustNotBeInflatedByTheDistanceBetweenTheClocks()
+ throws Exception {
+ HTTPSampleResult result = new HTTPSampleResult();
+ assumeSampleClockMovedBy(result, -SKEW_MILLIS);
+ result.sampleStart();
+
+ HTTP2FutureResponseListener listener = new HTTP2FutureResponseListener(-1);
+ Thread.sleep(EXCHANGE_MILLIS);
+ listener.setEnd();
+
+ assertThat(listener.getResponseEnd() - result.getStartTime())
+ .as("the raw wall-clock reading is %d ms ahead of this result's clock, so it used to "
+ + "inflate the sample by that much", SKEW_MILLIS)
+ .isGreaterThan(SKEW_MILLIS);
+
+ result.setEndTime(listener.getResponseEndOn(result));
+
+ assertThat(result.getTime())
+ .isBetween(EXCHANGE_MILLIS, EXCHANGE_MILLIS + SCHEDULING_SLACK_MILLIS);
+ }
+
+ @Test
+ public void anExchangeThatNeverCompletedStaysUnstampedInsteadOfBecomingAClockReading() {
+ HTTP2FutureResponseListener listener = new HTTP2FutureResponseListener(-1);
+
+ assertThat(listener.getResponseEnd()).as("no completion yet").isZero();
+ assertThat(listener.getResponseEndOn(new HTTPSampleResult()))
+ .as("an absent stamp must stay absent, so callers can tell it apart from a real end and "
+ + "fall back to sampleEnd() rather than stamping a zero")
+ .isZero();
+ }
+
+ /**
+ * The winner of a protocol race is reported through the listener of the attempt that lost, so the
+ * stamps and the monotonic readings they are translated with have to travel together: translating
+ * the winner's interval with the loser's readings would put the sample wherever the two attempts
+ * happened to be apart.
+ */
+ @Test
+ public void adoptingARaceWinnerKeepsItsIntervalOnOneClock() throws Exception {
+ HTTP2FutureResponseListener winner = new HTTP2FutureResponseListener(-1);
+ Thread.sleep(EXCHANGE_MILLIS);
+ winner.setEnd();
+ HTTP2FutureResponseListener reporter = new HTTP2FutureResponseListener(-1);
+
+ reporter.completeWith(null, winner);
+
+ HTTPSampleResult result = new HTTPSampleResult();
+ assumeSampleClockMovedBy(result, SKEW_MILLIS);
+ assertThat(reporter.getResponseEndOn(result) - reporter.getResponseStartOn(result))
+ .as("the reported interval must be the winner's exchange")
+ .isBetween(EXCHANGE_MILLIS - TRANSLATION_SLACK_MILLIS,
+ EXCHANGE_MILLIS + SCHEDULING_SLACK_MILLIS);
+ assertThat(reporter.getResponseEndOn(result) - winner.getResponseEndOn(result))
+ .as("both listeners must translate the same instant to the same time")
+ .isBetween(-TRANSLATION_SLACK_MILLIS, TRANSLATION_SLACK_MILLIS);
+ assertThat(reporter.isDone()).isTrue();
+ }
+
+ /** Stamps adopted from elsewhere as plain wall-clock times still land on the result's clock. */
+ @Test
+ public void adoptedWallClockStampsAreTranslatedIntoTheResultsClock() throws Exception {
+ HTTPSampleResult result = new HTTPSampleResult();
+ assumeSampleClockMovedBy(result, -SKEW_MILLIS);
+
+ long start = System.currentTimeMillis();
+ HTTP2FutureResponseListener listener = new HTTP2FutureResponseListener(-1);
+ listener.completeWith(null, start, start + EXCHANGE_MILLIS);
+
+ assertThat(listener.getResponseEndOn(result) - listener.getResponseStartOn(result))
+ .as("translating both ends of the same interval must preserve it")
+ .isEqualTo(EXCHANGE_MILLIS);
+ assertThat(listener.getResponseStartOn(result) - start)
+ .as("both stamps must land on the result's clock, %d ms from the wall clock here",
+ -SKEW_MILLIS)
+ .isBetween(-SKEW_MILLIS - TRANSLATION_SLACK_MILLIS,
+ -SKEW_MILLIS + TRANSLATION_SLACK_MILLIS);
+ }
+
+ /**
+ * {@code SampleResult.setStampAndTime} reads its first argument as the start of the sample or as
+ * its end depending on {@code sampleresult.timestamp.start} - JMeter's shipped
+ * {@code jmeter.properties} turns that on, the property's own default is off. A caller that
+ * assumes either one gets the timestamps of the other backwards by the whole duration, which for
+ * a sub-sample also drags the container's end with it. So the choice belongs in one place.
+ */
+ @Test
+ public void stampIntervalReportsTheStartAndTheDurationItWasGiven() {
+ SampleResult result = new SampleResult();
+
+ SampleClock.stampInterval(result, 1_000_000L, 250L);
+
+ assertThat(result.getStartTime()).as("start").isEqualTo(1_000_000L);
+ assertThat(result.getEndTime()).as("end").isEqualTo(1_000_250L);
+ assertThat(result.getTime()).as("duration").isEqualTo(250L);
+ }
+
+ /**
+ * A sub-sample's times are on its own clock, and JMeter corrects for that when it folds one into
+ * its parent - {@code SampleResult.addSubResult} extends the parent's end time by
+ * {@code childEnd + parentOffset - childOffset}, its Bug 51855. Reading a child's stamps to
+ * measure the parent has to make the same correction, so both must land on the same time.
+ */
+ @Test
+ public void aChildsTimesLandWhereAddSubResultPutsThem() throws Exception {
+ SampleResult parent = new SampleResult();
+ parent.sampleStart();
+ HTTPSampleResult child = new HTTPSampleResult();
+ assumeSampleClockMovedBy(child, SKEW_MILLIS);
+ child.sampleStart();
+ child.sampleEnd();
+
+ parent.addSubResult(child, false);
+
+ assertThat(SampleClock.fromResultClock(parent, child, child.getEndTime()))
+ .as("the child's end on the parent's clock must be the end addSubResult stamped")
+ .isCloseTo(parent.getEndTime(), within(TRANSLATION_SLACK_MILLIS));
+ assertThat(parent.getEndTime() - child.getEndTime())
+ .as("and the raw stamp is %d ms away from it, which is what reading it uncorrected costs",
+ SKEW_MILLIS)
+ .isCloseTo(-SKEW_MILLIS, within(TRANSLATION_SLACK_MILLIS));
+ }
+
+ /**
+ * Moves {@code result}'s own nano offset by {@code deltaMillis}, so its clock sits a known
+ * distance from the wall clock. Skips the test when {@code sampleresult.useNanoTime} is off, since
+ * both clocks are then the wall clock and there is no distance to leak.
+ */
+ private static void assumeSampleClockMovedBy(SampleResult result, long deltaMillis)
+ throws ReflectiveOperationException {
+ Field nanoTimeOffset = SampleResult.class.getDeclaredField("nanoTimeOffset");
+ nanoTimeOffset.setAccessible(true);
+ long current = nanoTimeOffset.getLong(result);
+ assumeTrue("sampleresult.useNanoTime must be on for the two clocks to differ at all",
+ current != Long.MIN_VALUE);
+ nanoTimeOffset.setLong(result, current + deltaMillis);
+ }
+}