Fix samplers timing

Author: 3dgiordano

README.md

@@ -374,6 +374,7 @@ Add it with **Add → Logic Controller → bzm - HTTP Async Controller**. **`bzm
 | **Field** | **Description** | **Default** |
 |---|---|---|
 | Generate Parent Sample | Wraps child BlazeMeter HTTP results in one parent sample (sub-results in listeners/reports). | Off (`false`) |
+| Include duration of timer and pre-post processors in generated sample | Only applies with **Generate Parent Sample** on. When **off**, the parent sample measures the requests only: from the first one sent to the last response received, so think times and pre/post-processor time are reported as idle time instead of transaction time. When **on**, the parent sample spans the whole controller, pauses included (JMeter's Transaction Controller behaviour). | Off (`false`) |
 | Limit max number of parallel executions | When **off**, the cap is **`blazemeter.http.maxConcurrentAsyncInController`**. When **on**, cap is **Max parallel** (saved in the `.jmx` only while this is on; runtime still uses the global cap when off). | Off (`false`) |
 | Max parallel | Highest number of overlapping BlazeMeter HTTP samplers when limiting is **on** (integer ≥ **1**). Read-only when limiting is **off** (shows the effective global cap). | **100** (matches **`blazemeter.http.maxConcurrentAsyncInController`** unless you override; with limiting **on**, use the value you enter) |
 

src/main/java/com/blazemeter/jmeter/http2/control/HTTP2Controller.java

@@ -1,6 +1,7 @@
 package com.blazemeter.jmeter.http2.control;
 
 import com.blazemeter.jmeter.http2.core.HTTP2FutureResponseListener;
+import com.blazemeter.jmeter.http2.core.SampleClock;
 import com.blazemeter.jmeter.http2.sampler.HTTP2Sampler;
 import com.blazemeter.jmeter.http2.util.BzmHttpPluginProperties;
 import java.io.Serializable;
@@ -13,6 +14,7 @@
 import org.apache.jmeter.control.NextIsNullException;
 import org.apache.jmeter.control.TransactionController;
 import org.apache.jmeter.control.TransactionSampler;
+import org.apache.jmeter.samplers.SampleResult;
 import org.apache.jmeter.samplers.Sampler;
 import org.apache.jmeter.testelement.TestElement;
 import org.apache.jmeter.testelement.property.JMeterProperty;
@@ -56,6 +58,8 @@ public class HTTP2Controller extends TransactionController implements Serializab
       BzmHttpPluginProperties.CONTROLLER_PREFERRED_PREFIX + "maxConcurrentAsyncInController";
   private static final String MAX_CONCURRENT_LEGACY =
       BzmHttpPluginProperties.CONTROLLER_LEGACY_PREFIX + "maxConcurrentAsyncInController";
+  /** JMeter's own property name, so a value set on a stock Transaction Controller still reads. */
+  private static final String INCLUDE_TIMERS = "TransactionController.includeTimers";
 
   private static final int DEFAULT_MAX_CONCURRENT_ASYNC_IN_CONTROLLER = 100;
   private static final long COMPLETION_POLL_INTERVAL_MILLIS = 10;
@@ -69,6 +73,12 @@ public class HTTP2Controller extends TransactionController implements Serializab
   private transient boolean handingOutPendingSampler;
   private transient boolean nestedSequentialRequestWarned;
   private boolean generateControllerSample;
+  /**
+   * The parent transaction currently open, so {@link #triggerEndOfLoop()} can still reach it: the
+   * field {@link TransactionController} keeps it in is private and is already null by the time
+   * {@code super.triggerEndOfLoop()} returns.
+   */
+  private transient TransactionSampler openParentTransaction;
 
   public HTTP2Controller() {
     super();
@@ -148,6 +158,7 @@ public void setGenerateParentSample(boolean generateParent) {
   public Sampler next() {
     if (isGenerateParentSample()) {
       Sampler next = super.next();
+      measureParentSample(next);
       // Only after the controller has finished the parent transaction (next == null). Releasing
       // while still returning the done TransactionSampler is pointless: JMeterThread calls
       // configureTransactionSampler(done) next and puts that same instance back on the package.
@@ -161,6 +172,128 @@ public Sampler next() {
     return nextWithoutTransactionBookkeeping();
   }
 
+  /**
+   * What the parent sample must report is the time this controller spent on requests, which for
+   * overlapped requests is the span from the first one leaving to the last one arriving.
+   *
+   * <p>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.
+   *
+   * <p>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

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());