61254 – Summariser : Active thread count in is not correct during high load distributing test when using statistical mode

Bug 61254 - Summariser : Active thread count in is not correct during high load distributing test when using statistical mode

Summary: Summariser : Active thread count in is not correct during high load distribut...

Status:	NEW

Alias:	None

Product:	JMeter - Now in Github
Classification:	Unclassified
Component:	Main (show other bugs)
Version:	3.1
Hardware:	PC All

Importance:	P2 normal (vote)
Target Milestone:	---
Assignee:	JMeter issues mailing list

URL:
Keywords:

Depends on:
Blocks:

Reported:	2017-07-06 01:51 UTC by Liu XP
Modified:	2017-07-24 03:34 UTC (History)
CC List:	1 user (show)

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Liu XP 2017-07-06 01:51:30 UTC

1. Start JMeter distributing test with statistical mode(used 60 JMeter servers and each instance start with 5000 threads).
2. After finished test, I checked the jmeter.log file and found the active thread count[29,8199] is less than expect number[60*5000=300,000].

The below is part of logs:
...
2017/06/30 11:16:59 INFO  - jmeter.engine.ClientJMeterEngine: sent test to 172.18.50.171 basedir='jmeter' 
2017/06/30 11:16:59 INFO  - jmeter.engine.ClientJMeterEngine: Sending properties {sServerIP=172.18.2.11, nSize=1, nThreadNum=5000, nRampUp=5, nSleepTimes=0.25, nDuration=300} 
2017/06/30 11:16:59 INFO  - jmeter.engine.ClientJMeterEngine: sent run command to 172.18.50.171 
2017/06/30 11:16:59 INFO  - jmeter.engine.DistributedRunner: Remote engines have been started 
2017/06/30 11:16:59 INFO  - jmeter.JMeter: Started remote host:  172.18.50.171 (1498792619927) 
2017/06/30 11:17:01 INFO  - jmeter.reporters.Summariser: summary + 1170057 in 00:00:06 = 209088.1/s Avg:   267 Min:   248 Max:  1386 Err:     0 (0.0000%) Active: 161508 Started: 47672 Finished: 0
2017/06/30 11:17:01 INFO  - jmeter.reporters.Summariser: summary = 1170058 in 00:00:06 = 197211.9/s Avg:   267 Min:   248 Max:  1386 Err:     0 (0.0000%)
2017/06/30 11:17:10 INFO  - jmeter.reporters.Summariser: summary + 7412000 in 00:00:09 = 823372.6/s Avg:   317 Min:   224 Max:  2064 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:17:10 INFO  - jmeter.reporters.Summariser: summary = 8582058 in 00:00:15 = 574588.8/s Avg:   310 Min:   224 Max:  2064 Err:     0 (0.0000%)
2017/06/30 11:17:20 INFO  - jmeter.reporters.Summariser: summary + 8955000 in 00:00:10 = 895768.7/s Avg:   330 Min:   223 Max:  1753 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:17:20 INFO  - jmeter.reporters.Summariser: summary = 17537058 in 00:00:25 = 703367.3/s Avg:   321 Min:   223 Max:  2064 Err:     0 (0.0000%)
2017/06/30 11:17:30 INFO  - jmeter.reporters.Summariser: summary + 8486000 in 00:00:10 = 848515.1/s Avg:   347 Min:    85 Max:  2167 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:17:30 INFO  - jmeter.reporters.Summariser: summary = 26023058 in 00:00:35 = 744920.7/s Avg:   329 Min:    85 Max:  2167 Err:     0 (0.0000%)
2017/06/30 11:17:40 INFO  - jmeter.reporters.Summariser: summary + 8964000 in 00:00:10 = 896489.6/s Avg:   331 Min:   224 Max:  2038 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:17:40 INFO  - jmeter.reporters.Summariser: summary = 34987058 in 00:00:45 = 778649.5/s Avg:   330 Min:    85 Max:  2167 Err:     0 (0.0000%)
2017/06/30 11:17:50 INFO  - jmeter.reporters.Summariser: summary + 8988000 in 00:00:10 = 898530.4/s Avg:   331 Min:   218 Max:  1444 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:17:50 INFO  - jmeter.reporters.Summariser: summary = 43975058 in 00:00:55 = 800478.0/s Avg:   330 Min:    85 Max:  2167 Err:     0 (0.0000%)
2017/06/30 11:18:00 INFO  - jmeter.reporters.Summariser: summary + 8931000 in 00:00:10 = 893368.0/s Avg:   332 Min:   114 Max:  1636 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:18:00 INFO  - jmeter.reporters.Summariser: summary = 52906058 in 00:01:05 = 814779.2/s Avg:   330 Min:    85 Max:  2167 Err:     0 (0.0000%)
2017/06/30 11:18:10 INFO  - jmeter.reporters.Summariser: summary + 8900000 in 00:00:10 = 889911.0/s Avg:   333 Min:    76 Max:  1871 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:18:10 INFO  - jmeter.reporters.Summariser: summary = 61806058 in 00:01:15 = 824806.6/s Avg:   331 Min:    76 Max:  2167 Err:     0 (0.0000%)
2017/06/30 11:18:20 INFO  - jmeter.reporters.Summariser: summary + 8943000 in 00:00:10 = 894389.4/s Avg:   332 Min:   224 Max:  1457 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:18:20 INFO  - jmeter.reporters.Summariser: summary = 70749058 in 00:01:25 = 832998.5/s Avg:   331 Min:    76 Max:  2167 Err:     0 (0.0000%)
2017/06/30 11:18:30 INFO  - jmeter.reporters.Summariser: summary + 8931000 in 00:00:10 = 893010.7/s Avg:   333 Min:   107 Max:  2363 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:18:30 INFO  - jmeter.reporters.Summariser: summary = 79680058 in 00:01:35 = 839320.6/s Avg:   331 Min:    76 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:18:40 INFO  - jmeter.reporters.Summariser: summary + 8899000 in 00:00:10 = 889811.0/s Avg:   334 Min:    50 Max:  1758 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:18:40 INFO  - jmeter.reporters.Summariser: summary = 88579058 in 00:01:45 = 844132.6/s Avg:   331 Min:    50 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:18:50 INFO  - jmeter.reporters.Summariser: summary + 8870000 in 00:00:10 = 887177.4/s Avg:   334 Min:   230 Max:  1659 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:18:50 INFO  - jmeter.reporters.Summariser: summary = 97449058 in 00:01:55 = 847862.3/s Avg:   332 Min:    50 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:19:00 INFO  - jmeter.reporters.Summariser: summary + 8892000 in 00:00:10 = 889377.9/s Avg:   332 Min:    37 Max:  1954 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:19:00 INFO  - jmeter.reporters.Summariser: summary = 106341058 in 00:02:05 = 851184.7/s Avg:   332 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:19:10 INFO  - jmeter.reporters.Summariser: summary + 8868000 in 00:00:10 = 886711.3/s Avg:   336 Min:    46 Max:  2089 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:19:10 INFO  - jmeter.reporters.Summariser: summary = 115209058 in 00:02:15 = 853817.9/s Avg:   332 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:19:20 INFO  - jmeter.reporters.Summariser: summary + 8871000 in 00:00:10 = 887100.0/s Avg:   334 Min:   215 Max:  1830 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:19:20 INFO  - jmeter.reporters.Summariser: summary = 124080058 in 00:02:25 = 856114.2/s Avg:   332 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:19:30 INFO  - jmeter.reporters.Summariser: summary + 8809000 in 00:00:10 = 880900.0/s Avg:   337 Min:    54 Max:  1679 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:19:30 INFO  - jmeter.reporters.Summariser: summary = 132889058 in 00:02:35 = 857714.0/s Avg:   332 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:19:40 INFO  - jmeter.reporters.Summariser: summary + 8858000 in 00:00:10 = 885800.0/s Avg:   336 Min:    62 Max:  1822 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:19:40 INFO  - jmeter.reporters.Summariser: summary = 141747058 in 00:02:45 = 859416.8/s Avg:   333 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:19:50 INFO  - jmeter.reporters.Summariser: summary + 8849000 in 00:00:10 = 884900.0/s Avg:   334 Min:   223 Max:  1850 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:19:50 INFO  - jmeter.reporters.Summariser: summary = 150596058 in 00:02:55 = 860873.6/s Avg:   333 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:20:00 INFO  - jmeter.reporters.Summariser: summary + 8843000 in 00:00:10 = 884388.4/s Avg:   335 Min:   103 Max:  2088 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:20:00 INFO  - jmeter.reporters.Summariser: summary = 159439058 in 00:03:05 = 862145.0/s Avg:   333 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:20:10 INFO  - jmeter.reporters.Summariser: summary + 8812000 in 00:00:10 = 881200.0/s Avg:   337 Min:    84 Max:  1756 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:20:10 INFO  - jmeter.reporters.Summariser: summary = 168251058 in 00:03:15 = 863118.1/s Avg:   333 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:20:20 INFO  - jmeter.reporters.Summariser: summary + 8785000 in 00:00:10 = 878587.9/s Avg:   338 Min:   224 Max:  2063 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:20:20 INFO  - jmeter.reporters.Summariser: summary = 177036058 in 00:03:25 = 863872.9/s Avg:   333 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:20:30 INFO  - jmeter.reporters.Summariser: summary + 8809000 in 00:00:10 = 880900.0/s Avg:   336 Min:   140 Max:  1864 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:20:30 INFO  - jmeter.reporters.Summariser: summary = 185845058 in 00:03:35 = 864665.1/s Avg:   333 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:20:40 INFO  - jmeter.reporters.Summariser: summary + 8812000 in 00:00:10 = 881200.0/s Avg:   337 Min:    67 Max:  1915 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:20:40 INFO  - jmeter.reporters.Summariser: summary = 194657058 in 00:03:45 = 865400.2/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:20:50 INFO  - jmeter.reporters.Summariser: summary + 8862000 in 00:00:10 = 886111.4/s Avg:   335 Min:   203 Max:  1793 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:20:50 INFO  - jmeter.reporters.Summariser: summary = 203519058 in 00:03:55 = 866281.8/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:00 INFO  - jmeter.reporters.Summariser: summary + 8848000 in 00:00:10 = 884888.5/s Avg:   335 Min:   189 Max:  1575 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:21:00 INFO  - jmeter.reporters.Summariser: summary = 212367058 in 00:04:05 = 867041.4/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:10 INFO  - jmeter.reporters.Summariser: summary + 8790000 in 00:00:10 = 879000.0/s Avg:   336 Min:   103 Max:  1823 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:21:10 INFO  - jmeter.reporters.Summariser: summary = 221157058 in 00:04:15 = 867510.5/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:20 INFO  - jmeter.reporters.Summariser: summary + 8810000 in 00:00:10 = 880911.9/s Avg:   336 Min:   182 Max:  2116 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:21:20 INFO  - jmeter.reporters.Summariser: summary = 229967058 in 00:04:25 = 868016.4/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:30 INFO  - jmeter.reporters.Summariser: summary + 8784000 in 00:00:10 = 878400.0/s Avg:   338 Min:    46 Max:  1805 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:21:30 INFO  - jmeter.reporters.Summariser: summary = 238751058 in 00:04:35 = 868390.9/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:40 INFO  - jmeter.reporters.Summariser: summary + 8857000 in 00:00:10 = 885700.0/s Avg:   336 Min:    46 Max:  1880 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:21:40 INFO  - jmeter.reporters.Summariser: summary = 247608058 in 00:04:45 = 868998.4/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:50 INFO  - jmeter.reporters.Summariser: summary + 8868000 in 00:00:10 = 886888.7/s Avg:   334 Min:   120 Max:  1751 Err:     0 (0.0000%) Active: 298199 Started: 184363 Finished: 0
2017/06/30 11:21:50 INFO  - jmeter.reporters.Summariser: summary = 256476058 in 00:04:55 = 869604.9/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:21:59 INFO  - jmeter.JMeter: Finished remote host: 172.18.51.2 (1498792919164) 
2017/06/30 11:22:00 INFO  - jmeter.reporters.Summariser: summary + 6522285 in 00:00:10 = 652032.9/s Avg:   338 Min:   221 Max:  1924 Err:     0 (0.0000%) Active: 122961 Started: 184363 Finished: 175238
2017/06/30 11:22:00 INFO  - jmeter.reporters.Summariser: summary = 262998343 in 00:05:05 = 862467.8/s Avg:   334 Min:    37 Max:  2363 Err:     0 (0.0000%)
2017/06/30 11:22:01 INFO  - jmeter.JMeter: Finished remote host: 172.16.206.218 (1498792921307) 
2017/06/30 11:22:02 INFO  - jmeter.JMeter: Finished remote host: 172.16.206.242 (1498792922004) 
...

Comment 1 Philippe Mouawad 2017-07-16 13:57:47 UTC

Hello,
Thanks for report.
Can you test with default mode (MODE_STRIPPED_BATCH)  StrippedAsynch.

Thank you

Comment 2 Liu XP 2017-07-21 07:16:47 UTC

When used default mode (MODE_STRIPPED_BATCH)  StrippedAsynch, it will used up network bandwith on JMeter client side and the count of active thread number also not correct.

The below is part of logs:

2017/07/21 15:03:04 INFO  - jmeter.samplers.BatchSampleSender: Using batching (client settings) for this run. Thresholds: num=100, time=5000 
2017/07/21 15:03:04 INFO  - jmeter.samplers.DataStrippingSampleSender: Using DataStrippingSampleSender for this run 
2017/07/21 15:03:04 INFO  - jmeter.JMeter: Started remote host:  172.18.50.184 (1500620584062) 
2017/07/21 15:03:04 INFO  - jmeter.engine.ClientJMeterEngine: sent test to 172.18.51.15 basedir='.' 
2017/07/21 15:03:04 INFO  - jmeter.engine.ClientJMeterEngine: Sending properties {sServerIP=172.18.2.11, nSize=1, nThreadNum=5000, nRampUp=5, nSleepTimes=0.25, nDuration=180} 
2017/07/21 15:03:04 INFO  - jmeter.engine.ClientJMeterEngine: sent run command to 172.18.51.15 
2017/07/21 15:03:04 INFO  - jmeter.engine.DistributedRunner: Remote engines have been started 
2017/07/21 15:03:04 INFO  - jmeter.JMeter: Started remote host:  172.18.51.15 (1500620584200) 
2017/07/21 15:03:10 INFO  - jmeter.reporters.Summariser: summary +  13592 in 00:00:06 = 2229.3/s Avg:   261 Min:   249 Max:   612 Err:     0 (0.0000%) Active: 29318 Started: 26887 Finished: 0
2017/07/21 15:03:10 INFO  - jmeter.reporters.Summariser: summary =  13593 in 00:00:07 = 2064.2/s Avg:   261 Min:   249 Max:   612 Err:     0 (0.0000%)
2017/07/21 15:03:21 INFO  - jmeter.reporters.Summariser: summary +  22202 in 00:00:12 = 1874.2/s Avg:   295 Min:   249 Max:   962 Err:     0 (0.0000%) Active: 33402 Started: 30971 Finished: 0
2017/07/21 15:03:21 INFO  - jmeter.reporters.Summariser: summary =  35795 in 00:00:18 = 1942.1/s Avg:   282 Min:   249 Max:   962 Err:     0 (0.0000%)
2017/07/21 15:03:31 INFO  - jmeter.reporters.Summariser: summary +   7254 in 00:00:10 =  730.0/s Avg:   309 Min:   249 Max:   950 Err:     0 (0.0000%) Active: 33402 Started: 30971 Finished: 0
2017/07/21 15:03:31 INFO  - jmeter.reporters.Summariser: summary =  43049 in 00:00:28 = 1517.4/s Avg:   287 Min:   249 Max:   962 Err:     0 (0.0000%)
2017/07/21 15:03:43 INFO  - jmeter.reporters.Summariser: summary +   2184 in 00:00:11 =  191.2/s Avg:   291 Min:   250 Max:   712 Err:     0 (0.0000%) Active: 33402 Started: 30971 Finished: 0
2017/07/21 15:03:43 INFO  - jmeter.reporters.Summariser: summary =  45233 in 00:00:40 = 1136.7/s Avg:   287 Min:   249 Max:   962 Err:     0 (0.0000%)
2017/07/21 15:04:00 INFO  - jmeter.reporters.Summariser: summary +   2233 in 00:00:17 =  130.3/s Avg:   295 Min:   250 Max:   633 Err:     0 (0.0000%) Active: 33402 Started: 30971 Finished: 0
2017/07/21 15:04:00 INFO  - jmeter.reporters.Summariser: summary =  47466 in 00:00:57 =  833.6/s Avg:   287 Min:   249 Max:   962 Err:     0 (0.0000%)
...

Comment 3 Philippe Mouawad 2017-07-22 13:12:59 UTC

Hello, 
So for your last test, your issue looks to me like a consequence of a saturated network right ? 

For initial test, did you check that network between jmeter servers and client is not saturated ?

Did you add a unique ID to Thread Group names of each thread ?

Comment 4 Liu XP 2017-07-24 03:34:35 UTC

So for your last test, your issue looks to me like a consequence of a saturated network right ? 
Yes.

For initial test, did you check that network between jmeter servers and client is not saturated ?
I had checked network bandwith in initial test. The network between jmeter servers and client is not saturated because I used Statistical mode and set num_sample_threshold=1000 to reduce network bandwidth.

Did you add a unique ID to Thread Group names of each thread ?
I hadn't added unique ID to Thread Group name because I don't know where to trace them with Statistical mode.

Comment 5 The ASF infrastructure team 2022-09-24 20:38:09 UTC

This issue has been migrated to GitHub: https://github.com/apache/jmeter/issues/4417