At end of scheduler duration lots of Samplers gets executed at the same time

[asfimport]

@FSchumacher (Bug 63490): Samplers might get started at the end of the scheduled duration, when they are configured with a delay. That delay has already been shortened to end at the end of duration with https://github.com/apache/jmeter/issues/4073.

That might lead to a stampede of samplers getting started at the end of a load test. When the tested system is too weak to handle this, those samples will take a lot of time. This will result in a strange looking report with high latency at the end of the test.

To mitigate this, I propose to check for end of scheduler duration before right after the delaying logic inside the sampling setup.

Created attachment stop-samplers-at-end-of-scheduler.diff: Check for end of scheduler duration before the real sampling occurs

stop-samplers-at-end-of-scheduler.diff

````diff Index: src/core/org/apache/jmeter/threads/JMeterThread.java =================================================================== --- src/core/org/apache/jmeter/threads/JMeterThread.java (Revision 1860784) +++ src/core/org/apache/jmeter/threads/JMeterThread.java (Arbeitskopie) @@ -539,6 +539,9 @@ threadVars.putObject(PACKAGE_OBJECT, pack); delay(pack.getTimers()); + if (scheduler) { + stopSchedulerIfNeeded(); + } SampleResult result = null; if (running) { Sampler sampler = pack.getSampler(); ````

Severity: normal OS: All

[asfimport]

@vlsi (migrated from Bugzilla): @Felix, I think this fix should be put right into delay method, because it has extra delay that "prevents" delays that exceed scheduled timeframe.

In other words, dealay method should stop scheduling rather than calling "adjustDelay".

[asfimport]

@FSchumacher (migrated from Bugzilla): End test in delay method, if the computed delay would result in waiting till the end of the scheduler duration.

Created attachment stop-samplers-at-end-of-scheduler.diff: Check for end of scheduler duration before the real sampling occurs

stop-samplers-at-end-of-scheduler.diff

````diff Index: src/core/org/apache/jmeter/threads/JMeterThread.java =================================================================== --- src/core/org/apache/jmeter/threads/JMeterThread.java (Revision 1860784) +++ src/core/org/apache/jmeter/threads/JMeterThread.java (Arbeitskopie) @@ -951,10 +951,11 @@ } if (totalDelay > 0) { try { - if (scheduler) { - // We reduce pause to ensure end of test is not delayed by a sleep ending after test scheduled end - // See Bug 60049 - totalDelay = TIMER_SERVICE.adjustDelay(totalDelay, endTime); + // Stop test for this thread, if duration of schedule would end with the delay + // See Bug 60049 and 63490 + if (scheduler && endTime - totalDelay <= System.currentTimeMillis()) { + running = false; + return; } TimeUnit.MILLISECONDS.sleep(totalDelay); } catch (InterruptedException e) { ````

[asfimport]

@FSchumacher (migrated from Bugzilla): The attached test plan will not execute any samplers with this fix and end the scheduler directly.

Without it, it will run for the scheduled period of time and execute the sampler afterwards.

Created attachment bug63490.jmx: Simple test plan to reproduce bug

bug63490.jmx

````xml false true false continue false 1 1 1 true 5 20000 true sleep(5000) "OK" groovy false saveConfig true true true true true true true true true false true true false false false true false false false true 0 true true true true true true ````

[asfimport]

@pmouawad (migrated from Bugzilla): Hi Felix, Can't we find a way to put this code in TimerService and add junit testing ?

For example, make it return Pair<Boolean, Long> (exit or not/sleep time).

As you noticed it, it's the 3rd bug around this feature.

Thanks

[asfimport]

@FSchumacher (migrated from Bugzilla): (In reply to Philippe Mouawad from comment 4)

Hi Felix, Can't we find a way to put this code in TimerService and add junit testing ?

For example, make it return Pair<Boolean, Long> (exit or not/sleep time).

I would probably go for an Optional<Long> and define an empty Optional to mean, we should end the test, but I am not sure, whether it is a good idea to create another object instance for this. Same could be expressed by returning a negative long.

As you noticed it, it's the 3rd bug around this feature.

The missing test case is one of the reasons, why I haven't committed it yet.

Thanks

[asfimport]

@pmouawad (migrated from Bugzilla): (In reply to Felix Schumacher from comment 5)

(In reply to Philippe Mouawad from comment 4) > Hi Felix, > Can't we find a way to put this code in TimerService and add junit testing ? > > For example, make it return Pair<Boolean, Long> (exit or not/sleep time).

I would probably go for an Optional<Long> and define an empty Optional to mean, we should end the test, but I am not sure, whether it is a good idea to create another object instance for this. Same could be expressed by returning a negative long.

+1 for this idea

> > As you noticed it, it's the 3rd bug around this feature.

The missing test case is one of the reasons, why I haven't committed it yet.

Great, thanks

> > Thanks

[asfimport]

@vlsi (migrated from Bugzilla):

Optional<Long> and define an empty Optional to mean, we should end the test

As for me, it would look cryptic.

[asfimport]

@FSchumacher (migrated from Bugzilla): (In reply to Vladimir Sitnikov from comment 7)

> Optional<Long> and define an empty Optional to mean, we should end the test

As for me, it would look cryptic.

Which one do you prefer? Or any other alternative?

[asfimport]

@FSchumacher (migrated from Bugzilla): The current logic of TimerService has now been changed to return -1, when delay would be too long for the end time.

JMeterThread#delay stops the current thread, when delay is -1 (which could be surprising, when a timer uses -1 to indicate no waiting).

A test case has been added to test the current behaviour (and an old one has been adapted to check for -1 in TimerService) and two tests have been added to complete all possible cases in adjustDelay.

Created attachment stop-samplers-at-end-of-scheduler.diff: Check for end of scheduler duration before the real sampling occurs

stop-samplers-at-end-of-scheduler.diff

````diff Index: src/core/org/apache/jmeter/threads/JMeterThread.java =================================================================== --- src/core/org/apache/jmeter/threads/JMeterThread.java (Revision 1860784) +++ src/core/org/apache/jmeter/threads/JMeterThread.java (Arbeitskopie) @@ -935,6 +935,15 @@ } } + /** + * Run all configured timers and sleep the total amount of time. + *

+ * If the amount of time would amount to an ending after endTime, then + * end the current thread by setting {@code running} to {@code false} and + * return immediately. + * + * @param timers to be used for calculating the delay + */ private void delay(List timers) { long totalDelay = 0; for (Timer timer : timers) { @@ -955,6 +964,11 @@ // We reduce pause to ensure end of test is not delayed by a sleep ending after test scheduled end // See Bug 60049 totalDelay = TIMER_SERVICE.adjustDelay(totalDelay, endTime); + if (totalDelay < 0) { + log.debug("The delay would be longer than the scheduled period, so stop thread now."); + running = false; + return; + } } TimeUnit.MILLISECONDS.sleep(totalDelay); } catch (InterruptedException e) { Index: src/core/org/apache/jmeter/timers/TimerService.java =================================================================== --- src/core/org/apache/jmeter/timers/TimerService.java (Revision 1860783) +++ src/core/org/apache/jmeter/timers/TimerService.java (Arbeitskopie) @@ -60,13 +60,13 @@ * Adjust delay so that initialDelay does not exceed end of test * @param initialDelay initial delay in millis * @param endTime End time of JMeterThread - * @return initialDelay or adjusted delay + * @return initialDelay or {@code -1} if delay is too long */ public long adjustDelay(final long initialDelay, long endTime) { if (endTime > 0) { long now = System.currentTimeMillis(); if (initialDelay > endTime - now) { - return endTime - now; + return -1; } } return initialDelay; Index: test/src/org/apache/jmeter/threads/TestJMeterThread.java =================================================================== --- test/src/org/apache/jmeter/threads/TestJMeterThread.java (Revision 1860783) +++ test/src/org/apache/jmeter/threads/TestJMeterThread.java (Arbeitskopie) @@ -18,7 +18,17 @@ package org.apache.jmeter.threads; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; + +import java.util.Date; + +import org.apache.jmeter.control.LoopController; +import org.apache.jmeter.samplers.AbstractSampler; +import org.apache.jmeter.samplers.Entry; +import org.apache.jmeter.samplers.SampleResult; import org.apache.jmeter.testelement.ThreadListener; +import org.apache.jmeter.timers.ConstantTimer; import org.apache.jorphan.collections.HashTree; import org.junit.Test; @@ -26,6 +36,43 @@ * Tests for {@link JMeterThread} */ public class TestJMeterThread { + + private static final class DummySampler extends AbstractSampler { + private static final long serialVersionUID = 1L; + private boolean called = false; + + public boolean isCalled() { + return called; + } + + @Override + public SampleResult sample(Entry e) { + called = true; + return null; + } + + @Override + public int hashCode() { + final int prime = 31; + int result = super.hashCode(); + result = prime * result + (called ? 1231 : 1237); + return result; + } + + @Override + public boolean equals(Object obj) { + if (this == obj) + return true; + if (!super.equals(obj)) + return false; + if (getClass() != obj.getClass()) + return false; + DummySampler other = (DummySampler) obj; + return called == other.called; + } + + } + private static class ThrowingThreadListener implements ThreadListener { private boolean throwError; @@ -71,5 +118,60 @@ new JMeterThread.ThreadListenerTraverser(true); hashTree.traverse(traverser); } - + + @Test + public void testBug63490EndTestWhenDelayIsTooLongForScheduler() { + + JMeterContextService.getContext().setVariables(new JMeterVariables()); + + HashTree testTree = new HashTree(); + LoopController samplerController = createLoopController(); + testTree.add(samplerController); + testTree.add(samplerController, createConstantTimer("3000")); + DummySampler dummySampler = createSampler(); + testTree.add(samplerController, dummySampler); + + TestCompiler compiler = new TestCompiler(testTree); + testTree.traverse(compiler); + + ThreadGroup threadGroup = new ThreadGroup(); + threadGroup.setNumThreads(1); + long maxDuration = 2000l; + threadGroup.setDuration(maxDuration); + + JMeterThread jMeterThread = new JMeterThread(testTree, threadGroup, null); + jMeterThread.setScheduled(true); + jMeterThread.setEndTime(System.currentTimeMillis() + maxDuration); + jMeterThread.setThreadGroup(threadGroup); + long startTime = new Date().getTime(); + jMeterThread.run(); + long duration = new Date().getTime() - startTime; + + assertFalse("Sampler should not be called", dummySampler.isCalled()); + + // the duration of this test plan should currently be around zero seconds, + // but it is allowed to take up to maxDuration amount of time + assertTrue("Test plan should not run for longer than duration", duration <= maxDuration); + } + + private LoopController createLoopController() { + LoopController result = new LoopController(); + result.setLoops(LoopController.INFINITE_LOOP_COUNT); + result.setEnabled(true); + return result; + } + + private DummySampler createSampler() { + DummySampler result = new DummySampler(); + result.setName("Call me"); + return result; + } + + private ConstantTimer createConstantTimer(String delay) { + ConstantTimer constantTimer = new ConstantTimer(); + constantTimer.setEnabled(true); + constantTimer.setDelay(delay); + constantTimer.setName("Long delay"); + return constantTimer; + } } Index: test/src/org/apache/jmeter/timers/TimerServiceTest.java =================================================================== --- test/src/org/apache/jmeter/timers/TimerServiceTest.java (Revision 1860783) +++ test/src/org/apache/jmeter/timers/TimerServiceTest.java (Arbeitskopie) @@ -30,8 +30,21 @@ public void testBigInitialDelay() { long now = System.currentTimeMillis(); long adjustedDelay = sut.adjustDelay(Long.MAX_VALUE, now + 1000L); - // As #adjustDelay uses System#currentTimeMillis we can't be sure, that the value is exact 1000L - Assert.assertThat(Math.abs(adjustedDelay - 1000L) < 150L, CoreMatchers.is(true)); + Assert.assertThat("TimerService should return -1 as delay would lead to a time after end time", + Long.valueOf(adjustedDelay), CoreMatchers.is(Long.valueOf(-1))); } + @Test + public void testSmallInitialDelay() { + long now = System.currentTimeMillis(); + Assert.assertThat("TimerService should not change the delay as the end time is far away", + Long.valueOf(sut.adjustDelay(1000L, now + 20000L)), CoreMatchers.is(Long.valueOf(1000L))); + } + + @Test + public void testNegativeEndTime() { + Assert.assertThat("TimerService should not change the delay as the indicated end time is far away", + Long.valueOf(sut.adjustDelay(1000L, -1)), CoreMatchers.is(Long.valueOf(1000L))); + } + } ````

[asfimport]

@pmouawad (migrated from Bugzilla): (In reply to Felix Schumacher from comment 9)

Created attachment 36615 [details] Check for end of scheduler duration before the real sampling occurs

The current logic of TimerService has now been changed to return -1, when delay would be too long for the end time.

JMeterThread#delay stops the current thread, when delay is -1 (which could be surprising, when a timer uses -1 to indicate no waiting).

A test case has been added to test the current behaviour (and an old one has been adapted to check for -1 in TimerService) and two tests have been added to complete all possible cases in adjustDelay.

+1 for merging

[asfimport]

@FSchumacher (migrated from Bugzilla): commit a72e68ca69e874be020b1bda5ccf3a5756e14f21 AuthorDate: Sun Jun 16 19:55:54 2019 +0200

At end of scheduler duration lots of Samplers gets executed at the same time

The old behaviour lead to strange long sampling times at the end of scheduled
test runs.

https://github.com/apache/jmeter/issues/5099

---

.../org/apache/jmeter/threads/JMeterThread.java | 14 +++ .../org/apache/jmeter/timers/TimerService.java | 4 +- .../apache/jmeter/threads/TestJMeterThread.java | 104 ++++++++++++++++++++- .../org/apache/jmeter/timers/TimerServiceTest.java | 17 +++- xdocs/changes.xml | 1 + 5 files changed, 135 insertions(+), 5 deletions(-)

commit 2dc8f5b511dfb814c47402b348bc1aebe2991880 AuthorDate: Sun Jun 16 20:05:25 2019 +0200

Make checkstyle happy

Use braces with if statements and use uppercase L for long literals.
A bit of whitespace police while we are here anyway.

https://github.com/apache/jmeter/issues/5099

[asfimport]

@pmouawad (migrated from Bugzilla): Closing after fix of https://github.com/apache/jmeter/issues/5148 on nightly introduced by fix of this