Re: Problem with Constant Throughput Timer behavior

[Felix Schumacher]

Am 19.11.20 um 12:34 schrieb Krister Nilsson:
> OK, copied straight into the mail... 😊
>
>
>
> 2020-11-19 12:11:26,647 ERROR o.a.j.g.a.Save: Could not backup file! Backup 
> directory does not exist, is not a directory or could not be created ! 
> <C:\install\apache-jmeter-5.2.1\backups>
>
> 2020-11-19 12:11:29,253 INFO o.a.j.e.StandardJMeterEngine: Running the test!
>
> 2020-11-19 12:11:29,253 INFO o.a.j.s.SampleEvent: List of sample_variables: 
> [kundID]
>
> 2020-11-19 12:11:29,253 INFO o.a.j.g.u.JMeterMenuBar: setRunning(true, 
> *local*)
>
> 2020-11-19 12:11:29,284 INFO o.a.j.e.StandardJMeterEngine: Starting 
> ThreadGroup: 1 : Thread Group
>
> 2020-11-19 12:11:29,284 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads 
> for group Thread Group.
>
> 2020-11-19 12:11:29,284 INFO o.a.j.e.StandardJMeterEngine: Thread will 
> continue on error
>
> 2020-11-19 12:11:29,284 INFO o.a.j.t.ThreadGroup: Starting thread group... 
> number=1 threads=1 ramp-up=1 delayedStart=false
>
> 2020-11-19 12:11:29,284 INFO o.a.j.t.ThreadGroup: Started thread group number 
> 1
>
> 2020-11-19 12:11:29,284 INFO o.a.j.e.StandardJMeterEngine: All thread groups 
> have been started
>
> 2020-11-19 12:11:29,284 INFO o.a.j.t.JMeterThread: Thread started: Thread 
> Group 1-1
>
> 2020-11-19 12:11:29,315 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:29.315 in loop # 2
>
> 2020-11-19 12:11:29,331 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:29.331 in loop # 3
>
> 2020-11-19 12:11:31,304 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:31.304 in loop # 4
>
> 2020-11-19 12:11:33,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:33.302 in loop # 6
>
> 2020-11-19 12:11:33,302 INFO o.a.j.p.j.s.J.Sampler 3: Sampler 3 and Time is 
> 2020-11-19T12:11:33.302 in loop # 6
>
> 2020-11-19 12:11:33,302 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:33.302 in loop # 7
>
> 2020-11-19 12:11:33,318 INFO o.a.j.p.j.s.J.Sampler 4: Sampler 4 and Time is 
> 2020-11-19T12:11:33.318 in loop # 7
>
> 2020-11-19 12:11:35,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:35.302 in loop # 8
>
> 2020-11-19 12:11:35,302 INFO o.a.j.p.j.s.J.Sampler 5: Sampler 5 and Time is 
> 2020-11-19T12:11:35.302 in loop # 8
>
> 2020-11-19 12:11:37,311 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:37.311 in loop # 10
>
> 2020-11-19 12:11:37,311 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:37.311 in loop # 11
>
> 2020-11-19 12:11:37,311 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:37.311 in loop # 11
>
> 2020-11-19 12:11:39,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:39.303 in loop # 12
>
> 2020-11-19 12:11:41,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:41.302 in loop # 14
>
> 2020-11-19 12:11:41,302 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:41.302 in loop # 15
>
> 2020-11-19 12:11:43,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:43.303 in loop # 16
>
> 2020-11-19 12:11:43,303 INFO o.a.j.p.j.s.J.Sampler 3: Sampler 3 and Time is 
> 2020-11-19T12:11:43.303 in loop # 16
>
> 2020-11-19 12:11:45,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:45.303 in loop # 18
>
> 2020-11-19 12:11:45,303 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:45.303 in loop # 19
>
> 2020-11-19 12:11:45,303 INFO o.a.j.p.j.s.J.Sampler 4: Sampler 4 and Time is 
> 2020-11-19T12:11:45.303 in loop # 19
>
> 2020-11-19 12:11:47,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:47.303 in loop # 20
>
> 2020-11-19 12:11:49,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:49.302 in loop # 22
>
> 2020-11-19 12:11:49,302 INFO o.a.j.p.j.s.J.Sampler 5: Sampler 5 and Time is 
> 2020-11-19T12:11:49.302 in loop # 22
>
> 2020-11-19 12:11:49,302 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:49.302 in loop # 23
>
> 2020-11-19 12:11:51,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:51.302 in loop # 24
>
> 2020-11-19 12:11:53,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:53.303 in loop # 26
>
> 2020-11-19 12:11:53,303 INFO o.a.j.p.j.s.J.Sampler 3: Sampler 3 and Time is 
> 2020-11-19T12:11:53.303 in loop # 26
>
> 2020-11-19 12:11:53,303 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:53.303 in loop # 27
>
> 2020-11-19 12:11:53,303 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:53.303 in loop # 27
>
> 2020-11-19 12:11:55,304 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:55.304 in loop # 28
>
> 2020-11-19 12:11:57,301 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:57.301 in loop # 30
>
> 2020-11-19 12:11:57,301 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:11:57.301 in loop # 31
>
> 2020-11-19 12:11:59,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:11:59.303 in loop # 32
>
> 2020-11-19 12:11:59,303 INFO o.a.j.p.j.s.J.Sampler 4: Sampler 4 and Time is 
> 2020-11-19T12:11:59.303 in loop # 32
>
> 2020-11-19 12:12:01,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:01.302 in loop # 34
>
> 2020-11-19 12:12:01,302 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:12:01.302 in loop # 35
>
> 2020-11-19 12:12:03,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:03.302 in loop # 36
>
> 2020-11-19 12:12:03,302 INFO o.a.j.p.j.s.J.Sampler 3: Sampler 3 and Time is 
> 2020-11-19T12:12:03.302 in loop # 36
>
> 2020-11-19 12:12:03,302 INFO o.a.j.p.j.s.J.Sampler 5: Sampler 5 and Time is 
> 2020-11-19T12:12:03.302 in loop # 36
>
> 2020-11-19 12:12:05,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:05.303 in loop # 38
>
> 2020-11-19 12:12:05,303 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:12:05.303 in loop # 39
>
> 2020-11-19 12:12:07,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:07.302 in loop # 40
>
> 2020-11-19 12:12:09,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:09.302 in loop # 42
>
> 2020-11-19 12:12:09,302 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:12:09.302 in loop # 43
>
> 2020-11-19 12:12:09,302 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:12:09.302 in loop # 43
>
> 2020-11-19 12:12:11,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:11.303 in loop # 44
>
> 2020-11-19 12:12:11,303 INFO o.a.j.p.j.s.J.Sampler 4: Sampler 4 and Time is 
> 2020-11-19T12:12:11.303 in loop # 44
>
> 2020-11-19 12:12:13,303 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:13.303 in loop # 46
>
> 2020-11-19 12:12:13,303 INFO o.a.j.p.j.s.J.Sampler 3: Sampler 3 and Time is 
> 2020-11-19T12:12:13.303 in loop # 46
>
> 2020-11-19 12:12:13,303 INFO o.a.j.p.j.s.J.Sampler 2: Sampler 2 and Time is 
> 2020-11-19T12:12:13.303 in loop # 47
>
> 2020-11-19 12:12:15,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:15.302 in loop # 48
>
> 2020-11-19 12:12:17,302 INFO o.a.j.p.j.s.J.Sampler 1: Sampler 1 and Time is 
> 2020-11-19T12:12:17.302 in loop # 50

I think my theory still applies. The timer still tries to put as much
delay before the samplers to allow as many requests per time unit, as
you configured.

If you take the logs and run a small conversion to show the difference
in seconds to the last sampler, you will see, that almost all
differences are two seconds or larger (probably indicating a tpm of 30)
and those that are smaller (zero that is) are directly after samplers,
that had a difference bigger than two (four mostly). As the controller
uses the throughput of the sampler and takes more than the last run
sampler into account, the zero second difference is OK for the sampler.

I think it is best seen, when you add a Summary Report listener and look
at the resulting throughput column. Depending on the number of threads,
it will show a value higher than your limit at the beginning (if you use
"all active threads" or something similar for "Calculate Throughput
based on"), but JMeter will try to get to the configured limit over time.

Here are the converted logs:

$ perl -MTime::ParseDate -ne '($sampler, $timestamp) = ($_ =~ m/(Sampler
\d+) and Time is ([^ ]+)/); $seconds = parsedate($timestamp); next
unless $sampler; if ($samplers{$sampler}) { $last = $samplers{$sampler};
$diff = $seconds - $last; print "$sampler => $timestamp ($diff)\n" };
$samplers{$sampler} = $seconds;' /tmp/krister.logs
Sampler 1 => 2020-11-19T12:11:31.304 (2)
Sampler 1 => 2020-11-19T12:11:33.302 (2)
Sampler 2 => 2020-11-19T12:11:33.302 (4)
Sampler 1 => 2020-11-19T12:11:35.302 (2)
Sampler 1 => 2020-11-19T12:11:37.311 (2)
Sampler 2 => 2020-11-19T12:11:37.311 (4)
Sampler 2 => 2020-11-19T12:11:37.311 (0)
Sampler 1 => 2020-11-19T12:11:39.303 (2)
Sampler 1 => 2020-11-19T12:11:41.302 (2)
Sampler 2 => 2020-11-19T12:11:41.302 (4)
Sampler 1 => 2020-11-19T12:11:43.303 (2)
Sampler 3 => 2020-11-19T12:11:43.303 (10)
Sampler 1 => 2020-11-19T12:11:45.303 (2)
Sampler 2 => 2020-11-19T12:11:45.303 (4)
Sampler 4 => 2020-11-19T12:11:45.303 (12)
Sampler 1 => 2020-11-19T12:11:47.303 (2)
Sampler 1 => 2020-11-19T12:11:49.302 (2)
Sampler 5 => 2020-11-19T12:11:49.302 (14)
Sampler 2 => 2020-11-19T12:11:49.302 (4)
Sampler 1 => 2020-11-19T12:11:51.302 (2)
Sampler 1 => 2020-11-19T12:11:53.303 (2)
Sampler 3 => 2020-11-19T12:11:53.303 (10)
Sampler 2 => 2020-11-19T12:11:53.303 (4)
Sampler 2 => 2020-11-19T12:11:53.303 (0)
Sampler 1 => 2020-11-19T12:11:55.304 (2)
Sampler 1 => 2020-11-19T12:11:57.301 (2)
Sampler 2 => 2020-11-19T12:11:57.301 (4)
Sampler 1 => 2020-11-19T12:11:59.303 (2)
Sampler 4 => 2020-11-19T12:11:59.303 (14)
Sampler 1 => 2020-11-19T12:12:01.302 (2)
Sampler 2 => 2020-11-19T12:12:01.302 (4)
Sampler 1 => 2020-11-19T12:12:03.302 (2)
Sampler 3 => 2020-11-19T12:12:03.302 (10)
Sampler 5 => 2020-11-19T12:12:03.302 (14)
Sampler 1 => 2020-11-19T12:12:05.303 (2)
Sampler 2 => 2020-11-19T12:12:05.303 (4)
Sampler 1 => 2020-11-19T12:12:07.302 (2)
Sampler 1 => 2020-11-19T12:12:09.302 (2)
Sampler 2 => 2020-11-19T12:12:09.302 (4)
Sampler 2 => 2020-11-19T12:12:09.302 (0)
Sampler 1 => 2020-11-19T12:12:11.303 (2)
Sampler 4 => 2020-11-19T12:12:11.303 (12)
Sampler 1 => 2020-11-19T12:12:13.303 (2)
Sampler 3 => 2020-11-19T12:12:13.303 (10)
Sampler 2 => 2020-11-19T12:12:13.303 (4)
Sampler 1 => 2020-11-19T12:12:15.302 (2)
Sampler 1 => 2020-11-19T12:12:17.302 (2)

Felix

>
> 2020-11-19 12:12:17,302 INFO o.a.j.t.JMeterThread: Thread is done: Thread 
> Group 1-1
>
> 2020-11-19 12:12:17,302 INFO o.a.j.t.JMeterThread: Thread finished: Thread 
> Group 1-1
>
> 2020-11-19 12:12:17,302 INFO o.a.j.e.StandardJMeterEngine: Notifying test 
> listeners of end of test
>
> 2020-11-19 12:12:17,302 INFO o.a.j.g.u.JMeterMenuBar: setRunning(false, 
> *local*)
>
>
>
> /Krister
>
>
>
> -----Ursprungligt meddelande-----
> Från: Felix Schumacher <felix.schumac...@internetallee.de>
> Skickat: den 19 november 2020 12:31
> Till: user@jmeter.apache.org
> Ämne: Re: Problem with Constant Throughput Timer behavior
>
>
>
>
>
> Am 19.11.20 um 12:24 schrieb Krister Nilsson:
>
>> Hello again Felix!
>>> If so, than I think it is because of the way the throughput
>>> controller is working. It tries to limit the sampling to the amount
>>> that you configured. As the samples below are already limited to
>>> ${tpm}, they will not get a further delay and can execute right away.
>> I would buy that explanation if it was in the same loop, but it is not 
>> always. I have added three additional Thr Cont and also some extra debug 
>> printouts showing loop number and clock. I have also altered the percentages 
>> and increased the number of loops. A log file is attached and also the 
>> extended test plan.
>
>
> There is no log file attached to your mail (may be it has been stripped by 
> the mailing list manager).
>
>
>
> Why do you think they are in different loops? (Maybe your logs will show me 
> more, if I get them :) )
>
>
>
>> Do you still believe your explanation is valid?
>
>
> Can't tell yet ;)
>
>
>
> Felix
>
>
>
>> BR
>> /Krister
>> -----Ursprungligt meddelande-----
>> Från: Felix Schumacher 
>> <felix.schumac...@internetallee.de<mailto:felix.schumac...@internetallee.de>>
>> Skickat: den 19 november 2020 11:09
>> Till: JMeter Users List 
>> <user@jmeter.apache.org<mailto:user@jmeter.apache.org>>
>> Ämne: Re: SV: Problem with Constant Throughput Timer behavior
>> Am 19. November 2020 10:54:42 MEZ schrieb Krister Nilsson 
>> <krister.nils...@pensionsmyndigheten.se<mailto:krister.nils...@pensionsmyndigheten.se>>:
>>> Hi Felix!
>>> There is a difference between your test plan and mine. If it is
>>> significant, I dare not say.
>>> I have the Constant Throughput Timer as a child to an HTTP request,
>>> while you have it as a child to the JSR233 Sampler. The Beanshell
>>> Sampler I am using is on the same level as the HTTP request, i.e.
>>> they have the same parent. The CCT is NOT a child to the Beanshell
>>> Sampler though. As I said, I don't know if that difference makes any
>>> actual difference, but different it is... ??
>> I don't think, that it makes a difference. I left out the beanshell sampler, 
>> as they are not affected by the cct. The usage of the jsr223 sampler instead 
>> of an http sampler was on purpose, as it doesn't need a server to talk to. 
>> There should be no difference in behavior.
>> The real question is, does it perform the same way, as you expect?
>> Felix
>>> Cheers!
>>> /Krister
>>> -----Ursprungligt meddelande-----
>>> Från: Felix Schumacher 
>>> <felix.schumac...@internetallee.de<mailto:felix.schumac...@internetallee.de>>
>>> Skickat: den 18 november 2020 17:52
>>> Till: user@jmeter.apache.org<mailto:user@jmeter.apache.org>
>>> Ämne: Re: Problem with Constant Throughput Timer behavior
>>> Hi Krister,
>>> is the attached version of a test plan like the one, you are using?
>>> Has it the same problems you see?
>>> If so, than I think it is because of the way the throughput
>>> controller is working. It tries to limit the sampling to the amount
>>> that you configured. As the samples below are already limited to
>>> ${tpm}, they will not get a further delay and can execute right away.
>>> Felix
>>> Am 18.11.20 um 15:38 schrieb Krister Nilsson:
>>>> Hello! I sent the below question to this group about three weeks
>>>> ago,
>>> but I have not received any reply. I give it another try...
>>>> Hello!
>>>> I have a test plan schematically looking as below. Since I have two
>>>> Bean Shell Samplers which I do not want to be affected by the
>>> Constant
>>>> Throughput Timer, I have put the CTT as children to all the HTTP
>>>> requests. It has the desired effect as far as not affecting the Bean
>>> Shell Samplers.
>>>> However, I am surprised as the CTT does not add a delay for all HTTP
>>>> requests, only for the HTTP request which is used most frequently
>>>> (i.e. having the highest percentage set in Throughput Controller).
>>>> Let's call that request "HTTP request 1". Any other HTTP request
>>>> gets no delay, no matter if it is executed in the same loop as "HTTP
>>> request 1" or by itself in a loop or together with some other HTTP
>>> request (than #1) in the same loop.
>>>> The same property and tpm is used for all CTTs.
>>>> Someone who can straighten this out for me?
>>>> Thread group
>>>> |__ Once only controller
>>>>         |__ Bean shell sampler
>>>> |__ Switch controller (A or B)
>>>>         |__ Simple controller A
>>>>                |__ Throughput controller 1
>>>>                       |__ CSV Data set config 1
>>>>                               Bean shell sampler X
>>>>                               Bean shell sampler Y
>>>>                               HTTP request 1
>>>>                               |__ Constant throughput timer
>>> (${__property(tpm)})
>>>>                |__ Throughput controller 2
>>>>                       |__ CSV Data set config 2
>>>>                               HTTP request 2
>>>>                               |__ Constant throughput timer
>>> (${__property(tpm)})
>>>>                |__ Throughput controller 3
>>>>                       |__ CSV Data set config 3
>>>>                               HTTP request 3
>>>>                               |__ Constant throughput timer
>>> (${__property(tpm)})
>>>>                |__ Throughput controller 4
>>>>                       |__ CSV Data set config 4
>>>>                              HTTP request 4
>>>>                               |__ Constant throughput timer
>>> (${__property(tpm)})
>>>>         |__ Simple controller B
>>>> Med vänlig hälsning
>>>> Krister Nilsson
>>>> ____________________________________________________________
>>>> Krister Nilsson / översteprest, prestandatest IT Fond konto och
>>>> teknisk plattform Telefon direkt 010-454 21 97, mobil 072-210 21 97
>>> krister.nils...@pensionsmyndigheten.se<mailto:krister.nilsson@pension<mailto:krister.nils...@pensionsmyndigheten.se%3cmailto:krister.nilsson@pension>
>>> s<
>>> mailto:krister.nils...@pensionsmyndigheten.se%3cmailto:krister.nilsso
>>> n@
>>> pensions>
>>>> myndigheten.se>
>>>> Pensionsmyndigheten,
>>>> Telefon vxl 0771-771 771, fax 08-658 13 00,
>>> www.pensionsmyndigheten.se<http://www.pensionsmyndigheten.se/<http://<http://www.pensionsmyndigheten.se%3chttp:/www.pensionsmyndigheten.se/%3chttp:/>
>>> ww w.pensionsmyndigheten.se%3chttp:/www.pensionsmyndigheten.se/>>
>>>> P Överväg miljöpåverkan innan du skriver ut detta e-brev.
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: 
>> user-unsubscr...@jmeter.apache.org<mailto:user-unsubscr...@jmeter.apache.org>
>> For additional commands, e-mail: 
>> user-h...@jmeter.apache.org<mailto:user-h...@jmeter.apache.org>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: 
>> user-unsubscr...@jmeter.apache.org<mailto:user-unsubscr...@jmeter.apache.org>
>> For additional commands, e-mail: 
>> user-h...@jmeter.apache.org<mailto:user-h...@jmeter.apache.org>

---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscr...@jmeter.apache.org
For additional commands, e-mail: user-h...@jmeter.apache.org