Bug 57346 - Summariser : The + (difference) reports show wrong elapsed time and throughput
Summary: Summariser : The + (difference) reports show wrong elapsed time and throughput
Status: RESOLVED FIXED
Alias: None
Product: JMeter
Classification: Unclassified
Component: Main (show other bugs)
Version: 2.12
Hardware: All All
: P2 normal (vote)
Target Milestone: ---
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-12-12 14:40 UTC by UbikLoadPack support
Modified: 2015-01-05 10:47 UTC (History)
1 user (show)



Attachments
Test plan showing issue (5.22 KB, application/xml)
2014-12-22 22:12 UTC, UbikLoadPack support
Details

Note You need to log in before you can comment on or make changes to this bug.
Description UbikLoadPack support 2014-12-12 14:40:13 UTC
Hello,
We have a test with and average of 155 to 160 req/s.

Summariser is configured to display every 10s:
summariser.name=summary
# interval between summaries (in seconds) default 3 minutes
summariser.interval=10
# Write messages to log file
summariser.log=true
# Write messages to System.out
summariser.out=true

It shows the following:
summary +   1597 in   591s =    2.7/s Avg:   276 Min:     0 Max: 18732 Err:     0 (0.00%) Active: 3024 Started: 3024 Finished: 0
summary = 1372439 in  8683s =  158.1/s Avg:   316 Min:     0 Max: 32952 Err:     3 (0.00%)
summary +   1676 in   580s =    2.9/s Avg:   250 Min:     0 Max: 18193 Err:     0 (0.00%) Active: 3024 Started: 3024 Finished: 0
summary = 1374115 in  8693s =  158.1/s Avg:   316 Min:     0 Max: 32952 Err:     3 (0.00%)
summary +   1640 in   591s =    2.8/s Avg:   326 Min:     0 Max: 20648 Err:     0 (0.00%) Active: 3024 Started: 3024 Finished: 0
summary = 1375755 in  8703s =  158.1/s Avg:   316 Min:     0 Max: 32952 Err:     3 (0.00%)
summary +   1552 in   589s =    2.6/s Avg:   344 Min:     0 Max: 19179 Err:     0 (0.00%) Active: 3024 Started: 3024 Finished: 0
summary = 1377307 in  8713s =  158.1/s Avg:   316 Min:     0 Max: 32952 Err:     3 (0.00%)



As you can see, summary throughtput is OK while interval throughput is wrong:
It says 589s instead of 10s
It computes 2.6/s to 2.9/s due to the time interval.
If it had divided by 10 throughput would be OK.

Issue affects all version of JMeter from 2.6 to 2.12

Regards
@ubikloadpack
Comment 1 UbikLoadPack support 2014-12-22 17:10:55 UTC
Hi,
One additional info, the report really happens every 10 seconds but the  in "XXXX" is wrong as long as throughput which uses it.

Regards
@ubikloadpack
Comment 2 Sebb 2014-12-22 19:28:28 UTC
I cannot reproduce this.
Does the test use any 3rd party add-ons?

Can you provide a simple test case that shows the issue?
Comment 3 UbikLoadPack support 2014-12-22 21:56:50 UTC
Hi,
When reported we were using jmeter plugins.
But we made new tests without it and issue persists.

I wonder if the problem is not the following:
- What if a sampler takes more than the configured interval of Summariser to run or even worst what if TransactionController is used and contained such Samplers.

I think current code of RunningSample would lead to what is happening as firstTime would be very far in the past.;

I will try to build a simple test plan showing issue.

Regards
@ubikloadpack
Comment 4 UbikLoadPack support 2014-12-22 22:12:24 UTC
Created attachment 32324 [details]
Test plan showing issue
Comment 5 Sebb 2014-12-28 00:08:17 UTC
OK, I see the problem now.

At present the times are taken from the samples; they should really be taken from the current time.

This applies to both total types, though the problem is unlikely to be noticed with the overall total. At present, the overall total does not take into account that the start time might be later than the start of the actual test. Also that the end-time might be later than the end of the last sample (there may be initial and final time delays).
Comment 6 Sebb 2014-12-28 01:03:17 UTC
Further notes: 
The DELTA RunningSample start time needs to be reset each time, but the TOTAL RunningSample start time needs to remain as the start of the test. For both, the end time needs to be the time when the samples are merged/printed.

The RunningSample class was created a long while before the Summariser.
It only now seems to be used for the Summariser.
Previously it was used for the StatVisualizer; possibly other classes.
The code may still be useful as it is, so probably best to create a new (local) class for handling the accumulation.
Comment 7 Sebb 2014-12-28 02:56:12 UTC
URL: http://svn.apache.org/r1648146
Log:
Summariser : The + (difference) reports show wrong elapsed time and throughput
Bugzilla Id: 57346

Added:
    jmeter/trunk/src/core/org/apache/jmeter/reporters/SummariserRunningSample.java
Modified:
    jmeter/trunk/src/core/org/apache/jmeter/reporters/Summariser.java
    jmeter/trunk/xdocs/changes.xml
Comment 8 Philippe Mouawad 2014-12-28 14:01:26 UTC
Date: Sun Dec 28 13:58:42 2014
New Revision: 1648204

URL: http://svn.apache.org/r1648204
Log:
BUG 57346 Summariser : The + (difference) reports show wrong elapsed time and throughput
Remove useless index field
Add javadocs
Add Apache License Header
Bugzilla Id: 57346

Modified:
    jmeter/trunk/src/core/org/apache/jmeter/reporters/SummariserRunningSample.java

Date: Sun Dec 28 13:59:38 2014
New Revision: 1648205

URL: http://svn.apache.org/r1648205
Log:
BUG 57346 Summariser : The + (difference) reports show wrong elapsed time and throughput
Impact removal of useless index field in SummariserRunningSample
Add javadocs
Rename some variables to make code clear
Bugzilla Id: 57346

Modified:
    jmeter/trunk/src/core/org/apache/jmeter/reporters/Summariser.java
Comment 9 UbikLoadPack support 2015-01-05 10:47:24 UTC
Hi,
We tested with nightly build and it is working fine.
Thanks a lot for the fix.

And happy new year 2015 to the Apache JMeter team.

Regards
@ubikloadpack