From cfb87d1f70d0fe3b2ed9edf0064a2ddf15ebb336 Mon Sep 17 00:00:00 2001 From: ruthes00 Date: Tue, 22 Sep 2026 14:46:42 -0400 Subject: [PATCH] Exclude timer delays from elapsed time of a transaction interrupted by thread stop When a thread is stopped mid-transaction (e.g. during scheduler ramp-down) while sleeping through a timer delay, the TransactionSampler's elapsed time was inflated by the full timer delay rather than reflecting only the time spent executing child samplers. Root cause (parent mode): JMeterThread called setTransactionDone() after notifyListeners() had already fired, so the idle-time correction was applied to a result that had already been reported to listeners. Fix: call setTransactionDone() before doEndTransactionSampler() so the result is fully populated before it is broadcast. Root cause (non-parent mode / triggerEndOfLoop): the time elapsed since the last child sample ended was not added to pauseTime before sampleEnd(), so the timer delay was counted as active sampling time. Fix: accumulate the gap into pauseTime in triggerEndOfLoop() when includeTimers is false. Side-effect: interrupted transactions now receive the standard response message 'Number of samples in transaction : N, number of failing samples : M' and response code 200, so TransactionController.isFromTransactionController() returns true for them. This changes how Summariser, ResultSaver, and the Backend Listener's SamplerMetric handle these samples (see changes.xml). Fixes: #6496 --- .../control/TestTransactionController.java | 335 +++++++++++++++++- .../jmeter/control/TransactionController.java | 8 + .../jmeter/control/TransactionSampler.java | 2 +- .../apache/jmeter/threads/JMeterThread.java | 6 + xdocs/changes.xml | 1 + 5 files changed, 337 insertions(+), 15 deletions(-) diff --git a/src/components/src/test/java/org/apache/jmeter/control/TestTransactionController.java b/src/components/src/test/java/org/apache/jmeter/control/TestTransactionController.java index 3da05383418..06ce29d6b7b 100644 --- a/src/components/src/test/java/org/apache/jmeter/control/TestTransactionController.java +++ b/src/components/src/test/java/org/apache/jmeter/control/TestTransactionController.java @@ -18,28 +18,328 @@ package org.apache.jmeter.control; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import java.util.ArrayList; +import java.util.List; import org.apache.jmeter.assertions.ResponseAssertion; import org.apache.jmeter.junit.JMeterTestCase; import org.apache.jmeter.sampler.DebugSampler; -import org.apache.jmeter.test.samplers.CollectSamplesListener; +import org.apache.jmeter.samplers.AbstractSampler; +import org.apache.jmeter.samplers.Entry; +import org.apache.jmeter.samplers.SampleEvent; +import org.apache.jmeter.samplers.SampleListener; +import org.apache.jmeter.samplers.SampleResult; +import org.apache.jmeter.testelement.AbstractTestElement; import org.apache.jmeter.threads.JMeterContextService; import org.apache.jmeter.threads.JMeterThread; import org.apache.jmeter.threads.JMeterVariables; import org.apache.jmeter.threads.ListenerNotifier; import org.apache.jmeter.threads.TestCompiler; import org.apache.jmeter.threads.ThreadGroup; +import org.apache.jmeter.timers.Timer; import org.apache.jorphan.collections.ListedHashTree; import org.junit.jupiter.api.Test; public class TestTransactionController extends JMeterTestCase { + /** + * A snapshot of a sample result captured at notification time. + * Because {@link SampleResult} is mutated after listeners are notified + * (e.g. {@code setTransactionDone()} is called later), we must record + * the values we care about inside {@code sampleOccurred} rather than + * reading them from the result object after the test has finished. + */ + private static class SampleSnapshot { + final long time; + final long idleTime; + final String responseMessage; + final boolean isTransactionSample; + + SampleSnapshot(SampleEvent e) { + SampleResult r = e.getResult(); + this.time = r.getTime(); + this.idleTime = r.getIdleTime(); + this.responseMessage = r.getResponseMessage(); + this.isTransactionSample = e.isTransactionSampleEvent(); + } + } + + /** + * A {@link SampleListener} that records a {@link SampleSnapshot} for every + * {@code sampleOccurred} call. Values are captured immediately inside the + * callback so that later mutations of the {@link SampleResult} do not affect + * the recorded data. + */ + private static class SnapshotListener extends AbstractTestElement implements SampleListener { + private static final long serialVersionUID = 1L; + private final List snapshots = new ArrayList<>(); + + @Override + public void sampleOccurred(SampleEvent e) { + snapshots.add(new SampleSnapshot(e)); + } + + @Override + public void sampleStarted(SampleEvent e) { + } + + @Override + public void sampleStopped(SampleEvent e) { + } + + List getSnapshots() { + return snapshots; + } + } + + /** + * A simple sampler that returns a successful result with a fixed elapsed time. + */ + private static class FixedElapsedTimeSampler extends AbstractSampler { + private static final long serialVersionUID = 1L; + private final long elapsedTimeMs; + + FixedElapsedTimeSampler(long elapsedTimeMs) { + this.elapsedTimeMs = elapsedTimeMs; + } + + @Override + public SampleResult sample(Entry e) { + SampleResult result = new SampleResult(); + result.setSampleLabel(getName()); + result.sampleStart(); + result.setSuccessful(true); + result.setResponseCodeOK(); + long start = result.getStartTime(); + result.setEndTime(start + elapsedTimeMs); + return result; + } + } + + /** + * A timer that returns a fixed delay without actually sleeping. + */ + private static class FixedDelayTimer extends AbstractTestElement implements Timer { + private static final long serialVersionUID = 1L; + private final long delayMs; + + FixedDelayTimer(long delayMs) { + this.delayMs = delayMs; + } + + @Override + public long delay() { + return delayMs; + } + } + + /** + * Test for GitHub issue #6496: when a thread is stopped mid-transaction by the + * scheduler (parent mode, {@code includeTimers=false}), the transaction elapsed + * time reported to listeners must not include the timer delay that was in + * progress when the thread was stopped. + * + *

Setup: a Transaction Controller in parent mode with two child samplers. + * A 500 ms timer sits before the first sampler and a 5000 ms timer sits before + * the second sampler. The scheduler end time is set 1500 ms ahead, so the + * thread is stopped while sleeping through the 5000 ms timer. + * + *

On the base commit (without the fix) the snapshot captured inside + * {@code sampleOccurred} shows {@code t≈520, it=0, rm=""} because + * {@code setTransactionDone()} is called after the event is fired and + * the idle-time correction is never applied to the already-reported result. + * With the fix the snapshot shows {@code t≈10, it≈508} (child elapsed time only, + * timer delay moved to idle time). + */ + @Test + public void testIssue6496ParentMode() throws Exception { + JMeterContextService.getContext().setVariables(new JMeterVariables()); + + SnapshotListener listener = new SnapshotListener(); + + TransactionController transactionController = new TransactionController(); + transactionController.setGenerateParentSample(true); + transactionController.setIncludeTimers(false); + + // Child sampler with a very short simulated elapsed time + long childElapsedMs = 10L; + FixedElapsedTimeSampler firstSampler = new FixedElapsedTimeSampler(childElapsedMs); + firstSampler.setName("First Sampler"); + + // Short timer before the first sampler (will complete before scheduler fires) + long firstTimerDelayMs = 500L; + FixedDelayTimer firstTimer = new FixedDelayTimer(firstTimerDelayMs); + firstTimer.setName("First Timer"); + firstTimer.setEnabled(true); + + FixedElapsedTimeSampler secondSampler = new FixedElapsedTimeSampler(childElapsedMs); + secondSampler.setName("Second Sampler"); + + // Long timer before the second sampler; the scheduler will fire while sleeping here + long secondTimerDelayMs = 5000L; + FixedDelayTimer secondTimer = new FixedDelayTimer(secondTimerDelayMs); + secondTimer.setName("Second Timer"); + secondTimer.setEnabled(true); + + LoopController loop = new LoopController(); + loop.setLoops(LoopController.INFINITE_LOOP_COUNT); + loop.setContinueForever(true); + loop.setEnabled(true); + + // Build the tree correctly using the subtrees returned by add() + ListedHashTree tree = new ListedHashTree(); + ListedHashTree tcTree = (ListedHashTree) tree.add(loop).add(transactionController); + tcTree.add(listener); + ListedHashTree firstSamplerTree = (ListedHashTree) tcTree.add(firstSampler); + firstSamplerTree.add(firstTimer); + ListedHashTree secondSamplerTree = (ListedHashTree) tcTree.add(secondSampler); + secondSamplerTree.add(secondTimer); + + TestCompiler compiler = new TestCompiler(tree); + tree.traverse(compiler); + + ThreadGroup threadGroup = new ThreadGroup(); + threadGroup.setNumThreads(1); + + ListenerNotifier notifier = new ListenerNotifier(); + + // Scheduler end time: 1500 ms from now. + // The first timer (500 ms) + first sampler (~10 ms) will complete (~510 ms total). + // The second timer (5000 ms) will be cut short by the scheduler at ~1500 ms. + long maxDuration = 1500L; + JMeterThread thread = new JMeterThread(tree, threadGroup, notifier); + thread.setScheduled(true); + thread.setEndTime(System.currentTimeMillis() + maxDuration); + thread.setThreadGroup(threadGroup); + thread.run(); + + assertFalse(listener.getSnapshots().isEmpty(), + "At least one transaction sample should have been collected"); + + // The last snapshot is the transaction interrupted during ramp-down. + // Its elapsed time must equal the child sample time, not be inflated by + // the timer delay that was in progress when the thread was stopped. + SampleSnapshot lastSnapshot = listener.getSnapshots().get(listener.getSnapshots().size() - 1); + + // The response message must be set (isFromTransactionController() must return true) + assertNotNull(lastSnapshot.responseMessage, + "Response message must not be null for an interrupted transaction"); + assertTrue(lastSnapshot.responseMessage.startsWith( + TransactionController.NUMBER_OF_SAMPLES_IN_TRANSACTION_PREFIX), + "Response message should start with the transaction prefix; got: " + lastSnapshot.responseMessage); + + // The elapsed time must be close to the child sample time, not inflated by the + // 5000 ms timer that was in progress when the thread was stopped. + assertTrue(lastSnapshot.time < secondTimerDelayMs, + "Transaction elapsed time (" + lastSnapshot.time + " ms) must not include " + + "the timer delay (" + secondTimerDelayMs + " ms) when thread is stopped mid-transaction"); + + // The idle time must account for the timer delays that were excluded + assertTrue(lastSnapshot.idleTime > 0, + "Idle time (" + lastSnapshot.idleTime + " ms) must be positive when timers are excluded"); + } + + /** + * Test for GitHub issue #6496: when a thread is stopped mid-transaction by the + * scheduler (non-parent / additional-sample mode, {@code includeTimers=false}), + * the transaction elapsed time reported to listeners must not include the timer + * delay that was in progress when the thread was stopped. + * + *

This exercises the {@code triggerEndOfLoop()} path in + * {@link TransactionController} (non-parent mode). A Flow Control Action + * "Start next thread loop" is not needed here because the scheduler stop + * already causes {@code triggerEndOfLoop()} to be called on the + * TransactionController. + */ + @Test + public void testIssue6496NonParentMode() throws Exception { + JMeterContextService.getContext().setVariables(new JMeterVariables()); + + SnapshotListener listener = new SnapshotListener(); + + TransactionController transactionController = new TransactionController(); + transactionController.setGenerateParentSample(false); + transactionController.setIncludeTimers(false); + + long childElapsedMs = 10L; + FixedElapsedTimeSampler firstSampler = new FixedElapsedTimeSampler(childElapsedMs); + firstSampler.setName("First Sampler"); + + long firstTimerDelayMs = 500L; + FixedDelayTimer firstTimer = new FixedDelayTimer(firstTimerDelayMs); + firstTimer.setName("First Timer"); + firstTimer.setEnabled(true); + + FixedElapsedTimeSampler secondSampler = new FixedElapsedTimeSampler(childElapsedMs); + secondSampler.setName("Second Sampler"); + + long secondTimerDelayMs = 5000L; + FixedDelayTimer secondTimer = new FixedDelayTimer(secondTimerDelayMs); + secondTimer.setName("Second Timer"); + secondTimer.setEnabled(true); + + LoopController loop = new LoopController(); + loop.setLoops(LoopController.INFINITE_LOOP_COUNT); + loop.setContinueForever(true); + loop.setEnabled(true); + + // Build the tree correctly using the subtrees returned by add() + ListedHashTree tree = new ListedHashTree(); + ListedHashTree tcTree = (ListedHashTree) tree.add(loop).add(transactionController); + // In non-parent mode the listener must be a child of the TransactionController + tcTree.add(listener); + ListedHashTree firstSamplerTree = (ListedHashTree) tcTree.add(firstSampler); + firstSamplerTree.add(firstTimer); + ListedHashTree secondSamplerTree = (ListedHashTree) tcTree.add(secondSampler); + secondSamplerTree.add(secondTimer); + + TestCompiler compiler = new TestCompiler(tree); + tree.traverse(compiler); + + ThreadGroup threadGroup = new ThreadGroup(); + threadGroup.setNumThreads(1); + + ListenerNotifier notifier = new ListenerNotifier(); + + long maxDuration = 1500L; + JMeterThread thread = new JMeterThread(tree, threadGroup, notifier); + thread.setScheduled(true); + thread.setEndTime(System.currentTimeMillis() + maxDuration); + thread.setThreadGroup(threadGroup); + thread.run(); + + // Filter for transaction snapshots (non-parent mode fires both child and transaction events) + List txSnapshots = new ArrayList<>(); + for (SampleSnapshot s : listener.getSnapshots()) { + if (s.responseMessage != null + && s.responseMessage.startsWith(TransactionController.NUMBER_OF_SAMPLES_IN_TRANSACTION_PREFIX)) { + txSnapshots.add(s); + } + } + + assertFalse(txSnapshots.isEmpty(), + "At least one transaction sample should have been collected"); + + SampleSnapshot lastSnapshot = txSnapshots.get(txSnapshots.size() - 1); + + assertTrue(lastSnapshot.time < secondTimerDelayMs, + "Transaction elapsed time (" + lastSnapshot.time + " ms) must not include " + + "the timer delay (" + secondTimerDelayMs + " ms) when thread is stopped mid-transaction"); + + assertTrue(lastSnapshot.idleTime > 0, + "Idle time (" + lastSnapshot.idleTime + " ms) must be positive when timers are excluded"); + } + @Test public void testIssue57958() throws Exception { JMeterContextService.getContext().setVariables(new JMeterVariables()); - CollectSamplesListener listener = new CollectSamplesListener(); + SnapshotListener listener = new SnapshotListener(); TransactionController transactionController = new TransactionController(); transactionController.setGenerateParentSample(true); @@ -56,29 +356,36 @@ public void testIssue57958() throws Exception { loop.setLoops(1); loop.setContinueForever(false); - ListedHashTree hashTree = new ListedHashTree(); - hashTree.add(loop); - hashTree.add(loop, transactionController); - hashTree.add(transactionController, debugSampler); - hashTree.add(transactionController, listener); - hashTree.add(debugSampler, assertion); + ListedHashTree tree = new ListedHashTree(); + ListedHashTree tcTree = (ListedHashTree) tree.add(loop).add(transactionController); + tcTree.add(listener); + ListedHashTree samplerTree = (ListedHashTree) tcTree.add(debugSampler); + samplerTree.add(assertion); - TestCompiler compiler = new TestCompiler(hashTree); - hashTree.traverse(compiler); + TestCompiler compiler = new TestCompiler(tree); + tree.traverse(compiler); ThreadGroup threadGroup = new ThreadGroup(); threadGroup.setNumThreads(1); ListenerNotifier notifier = new ListenerNotifier(); - JMeterThread thread = new JMeterThread(hashTree, threadGroup, notifier); + JMeterThread thread = new JMeterThread(tree, threadGroup, notifier); thread.setThreadGroup(threadGroup); thread.setOnErrorStopThread(true); thread.run(); - assertEquals(1, listener.getEvents().size(), - "Must one transaction samples with parent debug sample"); + List txSnapshots = new ArrayList<>(); + for (SampleSnapshot s : listener.getSnapshots()) { + if (s.responseMessage != null + && s.responseMessage.startsWith(TransactionController.NUMBER_OF_SAMPLES_IN_TRANSACTION_PREFIX)) { + txSnapshots.add(s); + } + } + + assertEquals(1, txSnapshots.size(), + "Must have one transaction sample with parent debug sample"); assertEquals("Number of samples in transaction : 1, number of failing samples : 1", - listener.getEvents().get(0).getResult().getResponseMessage()); + txSnapshots.get(0).responseMessage); } } diff --git a/src/core/src/main/java/org/apache/jmeter/control/TransactionController.java b/src/core/src/main/java/org/apache/jmeter/control/TransactionController.java index 1f651e2d880..ad0241e6a54 100644 --- a/src/core/src/main/java/org/apache/jmeter/control/TransactionController.java +++ b/src/core/src/main/java/org/apache/jmeter/control/TransactionController.java @@ -252,6 +252,14 @@ public static boolean isFromTransactionController(SampleResult res) { public void triggerEndOfLoop() { if(!isGenerateParentSample()) { if (res != null) { + // See BUG 55816 / GitHub issue #6496 + // When the thread is stopped mid-transaction (e.g. during ramp-down), + // we must account for the time elapsed since the last child sample ended + // as pause/idle time, so it is not counted in the transaction elapsed time. + if (!isIncludeTimers()) { + long processingTimeOfLastChild = res.currentTimeInMillis() - prevEndTime; + pauseTime += processingTimeOfLastChild; + } res.setIdleTime(pauseTime + res.getIdleTime()); res.sampleEnd(); res.setSuccessful(TRUE.equals(JMeterContextService.getContext().getVariables().get(JMeterThread.LAST_SAMPLE_OK))); diff --git a/src/core/src/main/java/org/apache/jmeter/control/TransactionSampler.java b/src/core/src/main/java/org/apache/jmeter/control/TransactionSampler.java index b8ee999cb62..aa3a04559b9 100644 --- a/src/core/src/main/java/org/apache/jmeter/control/TransactionSampler.java +++ b/src/core/src/main/java/org/apache/jmeter/control/TransactionSampler.java @@ -119,7 +119,7 @@ public void addSubSamplerResult(SampleResult res) { totalConnectTime += res.getConnectTime(); } - protected void setTransactionDone() { + public void setTransactionDone() { this.transactionDone = true; // Set the overall status for the transaction sample // TODO: improve, e.g. by adding counts to the SampleResult class diff --git a/src/core/src/main/java/org/apache/jmeter/threads/JMeterThread.java b/src/core/src/main/java/org/apache/jmeter/threads/JMeterThread.java index 35f94b26982..477b364d51a 100644 --- a/src/core/src/main/java/org/apache/jmeter/threads/JMeterThread.java +++ b/src/core/src/main/java/org/apache/jmeter/threads/JMeterThread.java @@ -526,6 +526,12 @@ private SampleResult processSampler(Sampler current, Sampler parent, JMeterConte && transactionResult == null && transactionSampler != null && transactionPack != null) { + // Thread was stopped mid-transaction (e.g. during ramp-down). + // Ensure setTransactionDone() is called so that elapsed time and idle time + // are correctly computed (see GitHub issue #6496 / Bug 55816). + if (!transactionSampler.isTransactionDone()) { + transactionSampler.setTransactionDone(); + } transactionResult = doEndTransactionSampler(transactionSampler, parent, transactionPack, threadContext); } diff --git a/xdocs/changes.xml b/xdocs/changes.xml index 56b5657563c..356459c84a2 100644 --- a/xdocs/changes.xml +++ b/xdocs/changes.xml @@ -120,6 +120,7 @@ Summary Bug fixes

General

    +
  • 67706496Fix Transaction Controller (parent mode) so that timer delays are excluded from the elapsed time when a thread is stopped mid-transaction.
  • 66546611Support JDK 25 and above for result collectors with empty file names
  • Trim whitespace when parsing numeric JMeter properties so accidental spaces do not silently change configuration values.
  • 6372Fix KeyManager logging when using CLI mode so keystore passwords are not incorrectly reported as missing. Contributed by Patrick Uiterwijk (patrick at puiterwijk.org)