Bug 62045 - timing difference for large (?) requests
Summary: timing difference for large (?) requests
Status: NEEDINFO
Alias: None
Product: JMeter
Classification: Unclassified
Component: HTTP (show other bugs)
Version: 3.3
Hardware: PC All
: P2 normal (vote)
Target Milestone: ---
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-01-25 15:49 UTC by Alex Podelko
Modified: 2018-03-08 21:16 UTC (History)
1 user (show)



Attachments
Fiddler session including that request (../import) (873.49 KB, application/zip)
2018-01-28 18:09 UTC, Alex Podelko
Details
Jmeter log (19.81 KB, text/plain)
2018-02-07 18:40 UTC, Alex Podelko
Details
gc log (125.64 KB, text/plain)
2018-02-07 18:42 UTC, Alex Podelko
Details
jmeter log (7.82 KB, text/plain)
2018-02-07 18:42 UTC, Alex Podelko
Details
new Fiddler session (995.98 KB, application/zip)
2018-02-07 18:50 UTC, Alex Podelko
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Alex Podelko 2018-01-25 15:49:28 UTC
Moving one my script to JMeter (3.3) I noticed a significant timing difference for some requests (between JMeter and measurements / other tools). 
 
For example, here is what I see in Fiddler for one request:

POST http://xxx:9000/epm/ui-rest/v1/requests/52ea978d-e94d-4d37-8d2d-5b9049bd2916/import HTTP/1.1
Host: xxx:9000
Connection: keep-alive
Content-Length: 157
Accept: */*
Origin: http://xxx:9000
Timezone: America/DenverX-Requested-With: XMLHttpRequest
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64;x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36
Content-Type: application/json
Referer: http://xxx:9000/epm/?root=workarea&workarea=view&id=ui-rest%2Fv1%2Fviews%2F4c819c71-4cb4-4498-ad2d-7c93a3ec6b7d
Accept-Encoding:gzip, deflate
Accept-Language: en-US,en;q=0.9
Cookie: EPM_Remote_User=b8e6T+U6DAXmDCZyx8WntMnvce/g39f2Di5KKPTe9yS2jvCmac6KM11weVtqKwEY;
JSESSIONID=TZviFRa7mudww7e1LIFyialL8CIo6MZS2Nu9yjyw6AYUCObhMgCt!-236747468

{"fileUri": "http://xxx:9000/epm/ui-rest/v1/requests/52ea978d-e94d-4d37-8d2d-5b9049bd2916/attachments/importFile/b94d2b50-d529-4a01-afb9-2bfdd0d78a4f"
}

Request Count:   1
Bytes Sent:      950 (headers:793; body:157)
Bytes Received:  7,065,667
(headers:550; body:7,065,117)
ACTUAL PERFORMANCE--------------
ClientConnected: 15:06:58.147
ClientBeginRequest: 15:07:11.094
GotRequestHeaders: 15:07:11.094
ClientDoneRequest: 15:07:11.094
Determine Gateway: 16ms
DNS Lookup:  0ms
TCP/IP Connect: 0ms
HTTPS Handshake: 0ms
ServerConnected: 15:07:10.964
FiddlerBeginRequest: 15:07:11.095
ServerGotRequest: 15:07:11.095
ServerBeginResponse: 15:08:26.158
GotResponseHeaders: 15:08:26.158
ServerDoneResponse: 15:08:26.210
ClientBeginResponse: 15:08:26.222
ClientDoneResponse: 15:08:26.227
Overall Elapsed: 0:01:15.132
RESPONSE BYTES (by Content-Type)--------------application/json: 7,065,117       ~headers~:
550

and here is what I see in JMeter (from the same machine):

POST http://xxx:9000/epm/ui-rest/v1/requests/b079bd62-4964-4adf-8564-d35ec33d0993/import

POST data:{"fileUri": "http://xxx:9000/epm/ui-rest/v1/requests/b079bd62-4964-4adf-
8564-d35ec33d0993/attachments/importFile/5eb5f197-ebfb-4de1-8238-35ad0060d857"
}

 Cookie Data:
EPM_Remote_User=UngMo7mbHE9R5SdofArYMZO44fBaRL3QcmxFT6e5kmnPp0a5QV5IbXoJFJmVCCzf; JSESSIONID=7GHhvdbivYNGxwfwd2MPPbsoFpj3hzd5nGD4_nE1RjeaAx_TT1tG!-236747468
Request Headers:Connection: keep-alive
Referer: http://xxx:9000/epm/?root=workarea&workarea=view&id=ui-rest%2Fv1%2Fviews%2F4c819c71-4cb4-4498-ad2d-7c93a3ec6b7d
Accept-Language: en-US,en;q=0.5
Timezone: America/DenverX-Requested-With: XMLHttp
RequestContent-Type: application/json
Accept-Encoding: gzip, deflate
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:52.0) Gecko/20100101
Firefox/52.0
Accept: */*
Content-Length: 157
Host: xxx:9000


Thread Name: Thread Group 1-1Sample Start: 2018-01-10 13:28:41 MST
Load time: 37327
Connect Time: 0
Latency: 37272
Size in bytes: 7065667
Sent bytes:863
Headers size in bytes: 550
Body size in bytes: 7065117
Sample Count: 1
Error Count: 0
Data type ("text"|"bin"|""): text
Response code: 200
Response message: OK
Response headers:HTTP/1.1 200 OKCache-Control: no-cache, no-store, max-age=0, must-revalidateDate:
Wed, 10 Jan 2018 20:28:41 GMTPragma: no-cacheTransfer-Encoding: chunkedContent-Type: application/jsonExpires:
0Access-Control-Allow-Methods: GET, POST, DELETE, PUT, PATCHP3P: X-CONTENT-TYPE-OPTIONS:nosniffX-XSS-Protection:
1; mode=blockAccess-Control-Allow-Headers: X-Requested-With, Content-TypeX-Content-Type-Options:
nosniffAccess-Control-Allow-Origin: *Content-Language: en-USX-Powered-By: Servlet/2.5 JSP/2.1X-Frame-Options:
DENY

HTTPSampleResult fields:ContentType: application/jsonDataEncoding: null

So in JMeter it takes 37 sec while in the real product (and another load testing tool) it takes ab. 75 sec. I see some difference in other requests too, but this one looks as a better example (my guess is that the difference becomes bigger for larger requests - and this one returns 7M). Everything inside a single data center, latency (ping) < 1 ms. 

Was posted to the user mail list http://mail-archives.apache.org/mod_mbox/jmeter-user/201801.mbox/%3C998028789.728908.1515623551353%40mail.yahoo.com%3E , but no real answer there - so it may be a bug.
Comment 1 Philippe Mouawad 2018-01-28 13:25:33 UTC
Hello,
Does you file contain an uploaded file ?
What does the response look like ? Would it be possible to attach the fiddler response ?
Thank you


On Thu, Jan 25, 2018 at 5:21 PM, Alexander Podelko <apodelko@yahoo.com> wrote:

    Hi,

    1. For example, in Fiddler - as specified below.

    2. Oracle Application Testing Suite. No rendering, it is recording on protocol level.

    3. 3.3

    4. Only that in real browser / Fiddler I see different time - and that pretty much matching what I see in OATS.

    I understand that here we may have interesting subtle issues - but I'd like to understand what they are as difference is quite noticeable. Clearly timing issues are very difficult to investigate - but this looks like may be a good example to check if there is any issue with that. 

    I will be happy to do whatever further measurement is needed. 

    Thanks,
    Alex

    On Thursday, January 25, 2018, 11:00:40 AM EST, Philippe Mouawad <philippe.mouawad@gmail.com> wrote:


    Hello Alexander,
    Could you give more details on:
    1/ How you measure response time in real product ? Is it a browser ?
    2/ In the other tool you use ? what is used ? does it take into account
    Rendering ?
    3/ which version of JMeter are you using ?
    4/ IMU, JMeter measures shorter response time, so what makes you think it's
    the other tool that is correct ?

    JMeter only computes time to receive last byte not full rendering time, but
    if your tool has some Rendering that takes time it would not be measured
    and would explain the difference.

    Unless you provide more details , I am afraid it is hard to help.
    Regards
Comment 2 Alex Podelko 2018-01-28 18:09:11 UTC
Created attachment 35701 [details]
Fiddler session including that request (../import)
Comment 3 Philippe Mouawad 2018-01-28 18:28:48 UTC
Hello,
Thanks.
1/ Did you set this property, I don't think so but double checking:
- httpsampler.max_bytes_to_store_per_request

2/ What is the read buffer used by your application or 

3/ Is the response time of this request constant ? Isn't it possible that by chance it was faster for JMeter and less for fiddler 

It seems you didn't record it at the same time

4/ Is this difference constant accross multiple runs ?
Comment 4 Alex Podelko 2018-01-28 18:43:20 UTC
No, I didn't change that parameter:

# Max size of bytes stored in memory per SampleResult
# Ensure you don't exceed max capacity of a Java Array and remember 
# that the higher it is, the higher JMeter will consume heap
# Defaults to 0, which means no truncation
#httpsampler.max_bytes_to_store_per_request=0

Not sure what read buffer you are asking about - could you please elaborate?

There is some variability between runs, but it is very small comparing to the difference between JMeter and Fiddler. And yes, it remains constant - I am running tests tests with each build. All happens inside one data center, so latency is <1ms.
Comment 5 Philippe Mouawad 2018-01-28 19:49:36 UTC
(In reply to Alex Podelko from comment #4)
> No, I didn't change that parameter:
> 
> # Max size of bytes stored in memory per SampleResult
> # Ensure you don't exceed max capacity of a Java Array and remember 
> # that the higher it is, the higher JMeter will consume heap
> # Defaults to 0, which means no truncation
> #httpsampler.max_bytes_to_store_per_request=0
> 
> Not sure what read buffer you are asking about - could you please elaborate?

I am looking into a reason that would explain the difference.
For now I see no reason. I was thinking about a difference in read buffer between JMeter and other tools when reading the response.

> 
> There is some variability between runs, but it is very small comparing to
> the difference between JMeter and Fiddler. And yes, it remains constant - I
> am running tests tests with each build. All happens inside one data center,
> so latency is <1ms.

On how much runs do you see this difference ? 
Did you compute a percentile 90 for both tools for 1000 measurements for example ?
Comment 6 Alex Podelko 2018-01-31 16:42:51 UTC
Even in JMeter it takes 37 sec - while in real life it takes 75 sec. There are few second variations, but overall the ratio is rather stable.

Even if forget about time to do it repeatable - it is a part of the process and it creates a large number of entries. Doing that many times in a loop will create other performance issues in the system.

That large request is specified more for example - because the difference is so large and evident that you can't ignore / misinterpret it. 

In most cases I use smaller requests in tests - where we still have the difference, but it is smaller.
Comment 7 Philippe Mouawad 2018-01-31 17:02:50 UTC
(In reply to Alex Podelko from comment #6)
> Even in JMeter it takes 37 sec - while in real life it takes 75 sec. There
> are few second variations, but overall the ratio is rather stable.
> 
> Even if forget about time to do it repeatable - it is a part of the process
> and it creates a large number of entries. Doing that many times in a loop
> will create other performance issues in the system.
> 
> That large request is specified more for example - because the difference is
> so large and evident that you can't ignore / misinterpret it. 

Ok, but in my experience, I have faced applications that were very unstable in terms of response time for the same request (not under load, but really during scripting/recording) but ran at different timings.
That's why I was asking for this particularly because the logs you attach show that you ran them at very different timings:
- 15h08
- 13h28


Can you attach your jmeter.log and the gc.log after uncommenting in jmeter.bat this part:
set VERBOSE_GC=-verbose:gc -Xloggc:gc_jmeter_%%p.log -XX:+PrintGCDetails -XX:+PrintGCCause -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintAdaptiveSizePolicy

> 
> In most cases I use smaller requests in tests - where we still have the
> difference, but it is smaller.


Frankly I have no idea of what is happening and it is very difficult to figure out without have the application available.
Comment 8 Philippe Mouawad 2018-02-06 21:42:17 UTC
Any feedback on this ?
Thanks
Comment 9 Alex Podelko 2018-02-07 18:38:57 UTC
There were some changes in product, but the ratio is still somewhat hold. 

Fiddler 69 sec:

POST /epm/ui-rest/v1/requests/67841168-5d29-4950-9c29-9af063a1f67a/import

Request Count:   1
Bytes Sent:      868		(headers:711; body:157)
Bytes Received:  7,065,667		(headers:550; body:7,065,117)

ACTUAL PERFORMANCE
--------------
ClientConnected:	10:42:59.074
ClientBeginRequest:	10:42:59.130
GotRequestHeaders:	10:42:59.130
ClientDoneRequest:	10:42:59.131
Determine Gateway:	0ms
DNS Lookup: 		0ms
TCP/IP Connect:	0ms
HTTPS Handshake:	0ms
ServerConnected:	10:42:59.083
FiddlerBeginRequest:	10:42:59.131
ServerGotRequest:	10:42:59.131
ServerBeginResponse:	10:44:08.251
GotResponseHeaders:	10:44:08.251
ServerDoneResponse:	10:44:08.307
ClientBeginResponse:	10:44:08.311
ClientDoneResponse:	10:44:08.313

	Overall Elapsed:	0:01:09.183

RESPONSE BYTES (by Content-Type)
--------------
application/json: 7,065,117
       ~headers~: 550


Jemeter 45 sec


Thread Name: Thread Group 1-1
Sample Start: 2018-02-07 10:56:57 MST
Load time: 45315
Connect Time: 0
Latency: 45252
Size in bytes: 7065667
Sent bytes:863
Headers size in bytes: 550
Body size in bytes: 7065117
Sample Count: 1
Error Count: 0
Data type ("text"|"bin"|""): text
Response code: 200
Response message: OK

Response headers:
HTTP/1.1 200 OK
Cache-Control: no-cache, no-store, max-age=0, must-revalidate
Date: Wed, 07 Feb 2018 17:56:57 GMT
Pragma: no-cache
Transfer-Encoding: chunked
Content-Type: application/json
Expires: 0
Access-Control-Allow-Methods: GET, POST, DELETE, PUT, PATCH
P3P: X-CONTENT-TYPE-OPTIONS:nosniff
X-XSS-Protection: 1; mode=block
Access-Control-Allow-Headers: X-Requested-With, Content-Type
X-Content-Type-Options: nosniff
Access-Control-Allow-Origin: *
Content-Language: en-US
X-Powered-By: Servlet/2.5 JSP/2.1
X-Frame-Options: DENY


HTTPSampleResult fields:
ContentType: application/json
DataEncoding: null

POST http://xxx:9000/epm/ui-rest/v1/requests/3ee9025d-761d-4557-b6df-7760a3ef07ac/import

POST data:
{"fileUri": "http://xxx:9000/epm/ui-rest/v1/requests/3ee9025d-761d-4557-b6df-7760a3ef07ac/attachments/importFile/7e0030de-cf2e-4be5-9fd4-e3cfac637082" }

Cookie Data:
EPM_Remote_User=pXpYvDEtl2VtSKJSuJW4X3oQVc+2XQjZ+SKT6I25aOB7QJyKMMm+eC0RSbNAJFqB; JSESSIONID=cJtxZ1oncdI2akQg9IXEK0gz6Pl_4lECPhYv3b49xIz_fMRnPns0!-348502596

Request Headers:
Connection: keep-alive
Referer: http://xxx:9000/epm/?root=workarea&workarea=view&id=ui-rest%2Fv1%2Fviews%2F4c819c71-4cb4-4498-ad2d-7c93a3ec6b7d
Accept-Language: en-US,en;q=0.5
Timezone: America/Denver
X-Requested-With: XMLHttpRequest
Content-Type: application/json
Accept-Encoding: gzip, deflate
User-Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:52.0) Gecko/20100101 Firefox/52.0
Accept: */*
Content-Length: 157
Comment 10 Alex Podelko 2018-02-07 18:40:32 UTC
Created attachment 35717 [details]
Jmeter log
Comment 11 Alex Podelko 2018-02-07 18:42:17 UTC
Created attachment 35718 [details]
gc log
Comment 12 Alex Podelko 2018-02-07 18:42:44 UTC
Created attachment 35719 [details]
jmeter log
Comment 13 Alex Podelko 2018-02-07 18:50:44 UTC
Created attachment 35720 [details]
new Fiddler session
Comment 14 Philippe Mouawad 2018-03-08 21:16:13 UTC
Hello,
Getting back to this, did you check server  logs to see how much time the server took to handle the request ?

Thank you