Bug 58950 - NoHttpResponseException when Pause between samplers exceeds keepalive sent by server
Summary: NoHttpResponseException when Pause between samplers exceeds keepalive sent by...
Status: RESOLVED FIXED
Alias: None
Product: JMeter
Classification: Unclassified
Component: HTTP (show other bugs)
Version: Nightly (Please specify date)
Hardware: All All
: P1 regression (vote)
Target Milestone: ---
Assignee: JMeter issues mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-01-31 17:26 UTC by Philippe Mouawad
Modified: 2016-02-26 22:52 UTC (History)
1 user (show)



Attachments
Modified MeasuringConnectionManager (8.79 KB, text/plain)
2016-01-31 17:29 UTC, Philippe Mouawad
Details
Hack to enable better stale management (13.89 KB, text/plain)
2016-01-31 17:29 UTC, Philippe Mouawad
Details
AWS Monitoring showing the difference in behaviour between versions (173.94 KB, image/png)
2016-01-31 17:34 UTC, Philippe Mouawad
Details
Test case to reproduce the keepalive issue (7.45 KB, application/xml)
2016-01-31 17:44 UTC, Felix Schumacher
Details
Test Plan that reproduces the issues with a Tomcat 8 (26.95 KB, application/xml)
2016-02-20 17:41 UTC, Philippe Mouawad
Details
Thread Dump during low CPU (92.38 KB, text/plain)
2016-02-20 17:43 UTC, Philippe Mouawad
Details

Note You need to log in before you can comment on or make changes to this bug.
Comment 1 Philippe Mouawad 2016-01-31 17:29:03 UTC
Created attachment 33504 [details]
Modified MeasuringConnectionManager

Some changes tried on KeepAlive management.
Comment 2 Philippe Mouawad 2016-01-31 17:29:37 UTC
Created attachment 33505 [details]
Hack to enable better stale management
Comment 3 Philippe Mouawad 2016-01-31 17:32:04 UTC
Regression affecting Nightly build as of 30 jan 2016
Comment 4 Philippe Mouawad 2016-01-31 17:34:06 UTC
Created attachment 33506 [details]
AWS Monitoring showing the difference in behaviour between versions

High metrics are for r1715087, low are for current trunk
Comment 5 Felix Schumacher 2016-01-31 17:44:05 UTC
Created attachment 33507 [details]
Test case to reproduce the keepalive issue

The server under test is configured with a keepalive timeout of 2 seconds. The test waits 3 seconds after each request.

This results in a Exception on the second request: org.apache.http.NoHttpResponseException: localhost:8080 failed to respond
Comment 6 Philippe Mouawad 2016-02-20 17:41:13 UTC
Created attachment 33575 [details]
Test Plan that reproduces the issues with a Tomcat 8

Hi,
I have a strange issue which also occurs with 2.13 by the way.

Tomcat configuration:

apache-tomcat-8.0.30/webapps/ROOT/WEB-INF/web.xml contains:
  <session-config>
	  <session-timeout>1</session-timeout>
</session-config>

setenv.sh in tomcat/bin contains:
export CATALINA_OPTS="-Xmx1024m -Xms1024m"


server.xml:
    <Connector port="8080" protocol="HTTP/1.1"
               connectionTimeout="20000"
               enableLookups="false"
               keepAliveTimeout="2000"
               minSpareThreads="25"
               compression="off"
               redirectPort="8443" />



When I run the test, I get a boost in CPU, then a pause (a thread dump shows threads stuck:
java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
	- locked <0x00000007a2804870> (a java.net.SocksSocketImpl)


Then after some time a new peak in CPU and then the pause....


JMeter config at defaults and Java options:
-server -Xms1024m -Xmx1024m -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -Xss256k -Dcom.sun.management.jmxremote.port=3333 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false  -XX:+UseThreadPriorities -XX:ThreadPriorityPolicy=42  -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCCause  -Xloggc:/data/jmeter/verbose-3.0.log -Djava.net.preferIPv4Stack=true -Djava.net.preferIPv6Addresses=false


It could be my machine TCP configuration but could somebody check on Linux machine ?
Thanks
Comment 7 Philippe Mouawad 2016-02-20 17:43:01 UTC
Created attachment 33576 [details]
Thread Dump during low CPU
Comment 8 Philippe Mouawad 2016-02-20 18:14:17 UTC
There might be an explanation to this issue related to starvation of ephemeral ports as http request downloads embedded resources.
Having the tomcat and jmeter colocated is not great.
Parallel downloads is more aggressive than a real client in terms of ephemeral ports usage as a new thread pool is created for each request that does not reuse httpclient (as spotted in another issue)

- My test has no timer as it aims at comparing throughput between versions.
Comment 9 Philippe Mouawad 2016-02-21 08:16:20 UTC
(In reply to Philippe Mouawad from comment #6)
> Created attachment 33575 [details]
> Test Plan that reproduces the issues with a Tomcat 8
> 
> Hi,
> I have a strange issue which also occurs with 2.13 by the way.
> 
> Tomcat configuration:
> 
> apache-tomcat-8.0.30/webapps/ROOT/WEB-INF/web.xml contains:
>   <session-config>
> 	  <session-timeout>1</session-timeout>
> </session-config>
> 
> setenv.sh in tomcat/bin contains:
> export CATALINA_OPTS="-Xmx1024m -Xms1024m"
> 
> 
> server.xml:
>     <Connector port="8080" protocol="HTTP/1.1"
>                connectionTimeout="20000"
>                enableLookups="false"
>                keepAliveTimeout="2000"
>                minSpareThreads="25"
>                compression="off"
>                redirectPort="8443" />
> 
> 
> 
> When I run the test, I get a boost in CPU, then a pause (a thread dump shows
> threads stuck:
> java.lang.Thread.State: RUNNABLE
> 	at java.net.PlainSocketImpl.socketConnect(Native Method)
> 	at
> java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> 	- locked <0x00000007a2804870> (a java.net.SocksSocketImpl)
> 
> 
> Then after some time a new peak in CPU and then the pause....
> 
> 
> JMeter config at defaults and Java options:
> -server -Xms1024m -Xmx1024m -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -Xss256k
> -Dcom.sun.management.jmxremote.port=3333
> -Dcom.sun.management.jmxremote.authenticate=false
> -Dcom.sun.management.jmxremote.ssl=false  -XX:+UseThreadPriorities
> -XX:ThreadPriorityPolicy=42  -verbose:gc -XX:+PrintGCDetails
> -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
> -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
> -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintHeapAtGC
> -XX:+PrintGCCause  -Xloggc:/data/jmeter/verbose-3.0.log
> -Djava.net.preferIPv4Stack=true -Djava.net.preferIPv6Addresses=false
> 
> 
> It could be my machine TCP configuration but could somebody check on Linux
> machine ?
> Thanks

Hello,
The issue was due to ephemeral ports saturation.
After fixing my machine configuration, I was able to run the test in better conditions.
On Mac OSX, I setup socket reuse time to 1s (it was 15s before) and the CPU drop falled down to 1s range vs 15s range before.

So this benchmark, confirms what Bug 59034 mentions regarding management of Connections when Parallel download is used for embedded resources.
But there are good news with it, with 15 threads we make 138% more samples with 3.0 than with 2.13 thanks to fixing of Bug 57804.
Comment 10 Philippe Mouawad 2016-02-21 21:13:52 UTC
(In reply to Philippe Mouawad from comment #9)
> (In reply to Philippe Mouawad from comment #6)
> > Created attachment 33575 [details]
> > Test Plan that reproduces the issues with a Tomcat 8
> > 
> > Hi,
> > I have a strange issue which also occurs with 2.13 by the way.
> > 
> > Tomcat configuration:
> > 
> > apache-tomcat-8.0.30/webapps/ROOT/WEB-INF/web.xml contains:
> >   <session-config>
> > 	  <session-timeout>1</session-timeout>
> > </session-config>
> > 
> > setenv.sh in tomcat/bin contains:
> > export CATALINA_OPTS="-Xmx1024m -Xms1024m"
> > 
> > 
> > server.xml:
> >     <Connector port="8080" protocol="HTTP/1.1"
> >                connectionTimeout="20000"
> >                enableLookups="false"
> >                keepAliveTimeout="2000"
> >                minSpareThreads="25"
> >                compression="off"
> >                redirectPort="8443" />
> > 
> > 
> > 
> > When I run the test, I get a boost in CPU, then a pause (a thread dump shows
> > threads stuck:
> > java.lang.Thread.State: RUNNABLE
> > 	at java.net.PlainSocketImpl.socketConnect(Native Method)
> > 	at
> > java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
> > 	- locked <0x00000007a2804870> (a java.net.SocksSocketImpl)
> > 
> > 
> > Then after some time a new peak in CPU and then the pause....
> > 
> > 
> > JMeter config at defaults and Java options:
> > -server -Xms1024m -Xmx1024m -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -Xss256k
> > -Dcom.sun.management.jmxremote.port=3333
> > -Dcom.sun.management.jmxremote.authenticate=false
> > -Dcom.sun.management.jmxremote.ssl=false  -XX:+UseThreadPriorities
> > -XX:ThreadPriorityPolicy=42  -verbose:gc -XX:+PrintGCDetails
> > -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
> > -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
> > -XX:+PrintTenuringDistribution -XX:+PrintGCDetails -XX:+PrintHeapAtGC
> > -XX:+PrintGCCause  -Xloggc:/data/jmeter/verbose-3.0.log
> > -Djava.net.preferIPv4Stack=true -Djava.net.preferIPv6Addresses=false
> > 
> > 
> > It could be my machine TCP configuration but could somebody check on Linux
> > machine ?
> > Thanks
> 
> Hello,
> The issue was due to ephemeral ports saturation.
> After fixing my machine configuration, I was able to run the test in better
> conditions.
> On Mac OSX, I setup socket reuse time to 1s (it was 15s before) and the CPU
> drop falled down to 1s range vs 15s range before.
> 
> So this benchmark, confirms what Bug 59034 mentions regarding management of
> Connections when Parallel download is used for embedded resources.
> But there are good news with it, with 15 threads we make 138% more samples
> with 3.0 than with 2.13 thanks to fixing of Bug 57804.

I meant fixing of Bug 58099 (not Bug 57804)
Comment 11 Sebb 2016-02-24 19:13:49 UTC
Not a JMeter problem
Comment 12 Philippe Mouawad 2016-02-25 22:21:20 UTC
This issue mentions 1 issue related to HttpClient 4.5.1 fixed in 4.5.2
See comment 5 from Felix
Comment 13 Philippe Mouawad 2016-02-26 22:52:12 UTC
Author: pmouawad
Date: Fri Feb 26 22:35:18 2016
New Revision: 1732569

URL: http://svn.apache.org/viewvc?rev=1732569&view=rev
Log:
Upgrade to HttpClient/httpmime 4.5.2 which fixes at the same time:
- Bug 58881 - HTTP Request : HTTPHC4Impl shows exception when server uses "deflate" compression
- Bug 58583 - HTTP client fails to close connection if server misbehaves by not sending "connection: close", violating HTTP RFC 2616 / RFC 7230
- Bug 56358 - Cookie manager supports cross port cookies and RFC6265
- Bug 57319 - Upgrade to HttpClient 4.5.2
Bugzilla Id: 57319

Modified:
    jmeter/trunk/build.properties
    jmeter/trunk/eclipse.classpath
    jmeter/trunk/lib/   (props changed)
    jmeter/trunk/lib/aareadme.txt
    jmeter/trunk/licenses/bin/README.txt
    jmeter/trunk/res/maven/ApacheJMeter_parent.pom
    jmeter/trunk/test/src/org/apache/jmeter/protocol/http/control/TestCookieManager.java
    jmeter/trunk/test/src/org/apache/jmeter/protocol/http/sampler/TestHTTPSamplersAgainstHttpMirrorServer.java
    jmeter/trunk/xdocs/changes.xml


Author: pmouawad
Date: Fri Feb 26 22:50:37 2016
New Revision: 1732574

URL: http://svn.apache.org/viewvc?rev=1732574&view=rev
Log:
Bug 58950 - NoHttpResponseException when Pause between samplers exceeds keepalive sent by server
Bugzilla Id: 58950

Modified:
    jmeter/trunk/src/protocol/http/org/apache/jmeter/protocol/http/sampler/HTTPHC4Impl.java
    jmeter/trunk/xdocs/changes.xml