Re: Why client connection's port changed always when server support Keep-alive?

Wed, 24 Dec 2008 18:35:18 -0800 

Dear Oleg:

Thank you very much for the help.
Here is the total trace level log of  two httpclient requests and responses,
split with "--------- finish first send ------------" .

httpclient4 log:
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter http.useragent =
Jakarta Commons-HttpClient/3.0.1
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter
http.protocol.version = HTTP/1.1
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter
http.connection-manager.class = class
org.apache.commons.httpclient.SimpleHttpConnectionManager
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter
http.protocol.cookie-policy = rfc2109
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter
http.protocol.element-charset = US-ASCII
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter
http.protocol.content-charset = ISO-8859-1
10:27:29,478 DEBUG DefaultHttpParams:150 - Set parameter
http.method.retry-handler =
org.apache.commons.httpclient.defaulthttpmethodretryhand...@1a73d3c
10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter
http.dateparser.patterns = [EEE, dd MMM yyyy HH:mm:ss zzz, EEEE, dd-MMM-yy
HH:mm:ss zzz, EEE MMM d HH:mm:ss yyyy, EEE, dd-MMM-yyyy HH:mm:ss z, EEE,
dd-MMM-yyyy HH-mm-ss z, EEE, dd MMM yy HH:mm:ss z, EEE dd-MMM-yyyy HH:mm:ss
z, EEE dd MMM yyyy HH:mm:ss z, EEE dd-MMM-yyyy HH-mm-ss z, EEE dd-MMM-yy
HH:mm:ss z, EEE dd MMM yy HH:mm:ss z, EEE,dd-MMM-yy HH:mm:ss z,
EEE,dd-MMM-yyyy HH:mm:ss z, EEE, dd-MM-yyyy HH:mm:ss z]
10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter
http.connection-manager.max-total = 1000
10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter
http.connection-manager.max-per-host = {HostConfiguration[]=2}
10:27:29,494 DEBUG DefaultHttpParams:150 - Set parameter
http.connection.timeout = 5000
10:27:29,510 DEBUG DefaultHttpParams:150 - Set parameter http.socket.timeout
= 5000
10:27:29,510 DEBUG DefaultHttpParams:150 - Set parameter
http.connection.stalecheck = true
10:27:29,510 DEBUG HttpClient:71 - Java version: 1.5.0
10:27:29,510 DEBUG HttpClient:72 - Java vendor: Sun Microsystems Inc.
10:27:29,510 DEBUG HttpClient:73 - Java class path:
D:\workspace\top-java-client\trunk\target\test-classes;D:\workspace\top-java-client\trunk\target\classes;D:\setup\program\m2\commons-codec\commons-codec\1.2\commons-codec-1.2.jar;D:\setup\program\m2\commons-httpclient\commons-httpclient\3.0.1\commons-httpclient-3.0.1.jar;D:\setup\program\m2\commons-lang\commons-lang\2.3\commons-lang-2.3.jar;D:\setup\program\m2\commons-logging\commons-logging\1.1.1\commons-logging-1.1.1.jar;D:\setup\program\m2\org\apache\httpcomponents\httpclient\4.0-beta2\httpclient-4.0-beta2.jar;D:\setup\program\m2\org\apache\httpcomponents\httpcore\4.0-beta3\httpcore-4.0-beta3.jar;D:\setup\program\m2\junit\junit\4.4\junit-4.4.jar;D:\setup\program\m2\log4j\log4j\1.2.12\log4j-1.2.12.jar
10:27:29,510 DEBUG HttpClient:74 - Operating system name: Windows XP
10:27:29,510 DEBUG HttpClient:75 - Operating system architecture: x86
10:27:29,510 DEBUG HttpClient:76 - Operating system version: 5.1
10:27:29,572 DEBUG HttpClient:81 - SUN 1.5: SUN (DSA key/parameter
generation; DSA signing; SHA-1, MD5 digests; SecureRandom; X.509
certificates; JKS keystore; PKIX CertPathValidator; PKIX CertPathBuilder;
LDAP, Collection CertStores)
10:27:29,572 DEBUG HttpClient:81 - SunRsaSign 1.5: Sun RSA signature
provider
10:27:29,572 DEBUG HttpClient:81 - SunJSSE 1.5: Sun JSSE provider(PKCS12,
SunX509 key/trust factories, SSLv3, TLSv1)
10:27:29,588 DEBUG HttpClient:81 - SunJCE 1.5: SunJCE Provider (implements
RSA, DES, Triple DES, AES, Blowfish, ARCFOUR, RC2, PBE, Diffie-Hellman,
HMAC)
10:27:29,588 DEBUG HttpClient:81 - SunJGSS 1.0: Sun (Kerberos v5)
10:27:29,588 DEBUG HttpClient:81 - SunSASL 1.5: Sun SASL provider(implements
client mechanisms for: DIGEST-MD5, GSSAPI, EXTERNAL, PLAIN, CRAM-MD5; server
mechanisms for: DIGEST-MD5, GSSAPI, CRAM-MD5)
10:27:29,588 DEBUG DefaultHttpParams:150 - Set parameter
http.connection.timeout = 1000
10:27:29,588 DEBUG DefaultHttpParams:150 - Set parameter http.socket.timeout
= 1000
10:27:29,744 DEBUG ClientParamsStack:219 - 'http.conn-manager.timeout': 5000
10:27:29,744 DEBUG ThreadSafeClientConnManager:171 -
ThreadSafeClientConnManager.getConnection: HttpRoute[{}->
http://192.168.208.110], timeout = 5000
10:27:29,744 DEBUG ConnPoolByRoute:289 - Total connections kept alive: 0
10:27:29,744 DEBUG ConnPoolByRoute:290 - Total issued connections: 0
10:27:29,744 DEBUG ConnPoolByRoute:291 - Total allocated connection: 0 out
of 1000
10:27:29,744 DEBUG ConnPoolByRoute:462 - No free connections [HttpRoute[{}->
http://192.168.208.110]][null]
10:27:29,744 DEBUG ConnPoolByRoute:308 - Available capacity: 2 out of 2
[HttpRoute[{}->http://192.168.208.110]][null]
10:27:29,744 DEBUG ConnPoolByRoute:489 - Creating new connection
[HttpRoute[{}->http://192.168.208.110]]
10:27:29,822 DEBUG ClientParamsStack:219 - 'http.protocol.version': HTTP/1.1
10:27:29,822 DEBUG RequestAddCookies:125 - CookieSpec selected: best-match
10:27:29,838 DEBUG DefaultRequestDirector:408 - Attempt 1 to execute request
10:27:29,838 DEBUG wire:78 - >> "POST /router/rest HTTP/1.1[EOL]"
10:27:29,853 DEBUG wire:78 - >> "Content-Length: 188[EOL]"
10:27:29,853 DEBUG wire:78 - >> "Content-Type:
application/x-www-form-urlencoded[EOL]"
10:27:29,853 DEBUG wire:78 - >> "Host: 192.168.208.110[EOL]"
10:27:29,853 DEBUG wire:78 - >> "Connection: Keep-Alive[EOL]"
10:27:29,853 DEBUG wire:78 - >> "[EOL]"
10:27:29,853 DEBUG headers:251 - >> POST /router/rest HTTP/1.1
10:27:29,853 DEBUG headers:254 - >> Content-Length: 188
10:27:29,853 DEBUG headers:254 - >> Content-Type:
application/x-www-form-urlencoded
10:27:29,853 DEBUG headers:254 - >> Host: 192.168.208.110
10:27:29,853 DEBUG headers:254 - >> Connection: Keep-Alive
10:27:29,853 DEBUG wire:78 - >>
"fields=name%2Cbuyer_credit%2Cphone%2Creal_name&timestamp=2008-12-25+10%3A27%3A29&api_key=suibian&nick=tbtest5&method=taobao.user.get&sign=82D375615F2EC704D9DAD60992359B3A&format=json&v=1.0"
10:27:29,869 DEBUG wire:78 - << "HTTP/1.1 200 OK[EOL]"
10:27:29,869 DEBUG wire:78 - << "Date: Thu, 25 Dec 2008 02:26:40 GMT[EOL]"
10:27:29,869 DEBUG wire:78 - << "Server: Apache-Coyote/1.1[EOL]"
10:27:29,869 DEBUG wire:78 - << "X-Powered-By: Servlet 2.4;
JBoss-4.2.2.GA(build: SVNTag=JBoss_4_2_2_GA
date=200710221139)/Tomcat-5.5[EOL]"
10:27:29,869 DEBUG wire:78 - << "Content-Type:
text/javascript;charset=UTF-8[EOL]"
10:27:29,869 DEBUG wire:78 - << "Content-Length: 85[EOL]"
10:27:29,885 DEBUG wire:78 - << "Vary: Accept-Encoding[EOL]"
10:27:29,885 DEBUG wire:78 - << "Keep-Alive: timeout=15, max=100[EOL]"
10:27:29,885 DEBUG wire:78 - << "Connection: Keep-Alive[EOL]"
10:27:29,885 DEBUG headers:237 - << HTTP/1.1 200 OK
10:27:29,885 DEBUG headers:240 - << Date: Thu, 25 Dec 2008 02:26:40 GMT
10:27:29,885 DEBUG headers:240 - << Server: Apache-Coyote/1.1
10:27:29,885 DEBUG headers:240 - << X-Powered-By: Servlet 2.4;
JBoss-4.2.2.GA (build: SVNTag=JBoss_4_2_2_GA date=200710221139)/Tomcat-5.5
10:27:29,885 DEBUG headers:240 - << Content-Type:
text/javascript;charset=UTF-8
10:27:29,885 DEBUG headers:240 - << Content-Length: 85
10:27:29,885 DEBUG headers:240 - << Vary: Accept-Encoding
10:27:29,885 DEBUG headers:240 - << Keep-Alive: timeout=15, max=100
10:27:29,885 DEBUG headers:240 - << Connection: Keep-Alive
10:27:29,900 DEBUG DefaultRequestDirector:463 - Connection can be kept alive
for 15000 ms
10:27:29,900 DEBUG wire:78 - <<
"{"rsp":{"users":[{"buyer_credit":{"good_num":1,"level":0,"score":1,"total_num":1}}]}}"
10:27:29,900 DEBUG ThreadSafeClientConnManager:221 - Released connection is
reusable.
10:27:29,900 DEBUG ConnPoolByRoute:374 - Releasing connection
[HttpRoute[{}->http://192.168.208.110]][null]
10:27:29,900 DEBUG ConnPoolByRoute:394 - Pooling connection [HttpRoute[{}->
http://192.168.208.110]][null]; keep alive for 15000 MILLISECONDS
10:27:29,900 DEBUG IdleConnectionHandler:78 - Adding connection at:
1230172049900
10:27:29,900 DEBUG ConnPoolByRoute:631 - Notifying no-one, there are no
waiting threads
--------- finish first send ------------
10:27:29,916 DEBUG ClientParamsStack:219 - 'http.conn-manager.timeout': 5000
10:27:29,916 DEBUG ThreadSafeClientConnManager:171 -
ThreadSafeClientConnManager.getConnection: HttpRoute[{}->
http://192.168.208.110], timeout = 5000
10:27:29,916 DEBUG ConnPoolByRoute:289 - Total connections kept alive: 1
10:27:29,916 DEBUG ConnPoolByRoute:290 - Total issued connections: 0
10:27:29,916 DEBUG ConnPoolByRoute:291 - Total allocated connection: 1 out
of 1000
10:27:29,916 DEBUG ConnPoolByRoute:436 - Getting free connection
[HttpRoute[{}->http://192.168.208.110]][null]
10:27:29,916 DEBUG DefaultRequestDirector:334 - Stale connection check
10:27:29,932 DEBUG ClientParamsStack:219 - 'http.protocol.version': HTTP/1.1
10:27:29,932 DEBUG RequestAddCookies:125 - CookieSpec selected: best-match
10:27:29,932 DEBUG DefaultRequestDirector:408 - Attempt 1 to execute request
10:27:29,932 DEBUG wire:78 - >> "POST /router/rest HTTP/1.1[EOL]"
10:27:29,932 DEBUG wire:78 - >> "Content-Length: 188[EOL]"
10:27:29,932 DEBUG wire:78 - >> "Content-Type:
application/x-www-form-urlencoded[EOL]"
10:27:29,932 DEBUG wire:78 - >> "Host: 192.168.208.110[EOL]"
10:27:29,932 DEBUG wire:78 - >> "Connection: Keep-Alive[EOL]"
10:27:29,932 DEBUG wire:78 - >> "[EOL]"
10:27:29,932 DEBUG headers:251 - >> POST /router/rest HTTP/1.1
10:27:29,932 DEBUG headers:254 - >> Content-Length: 188
10:27:29,932 DEBUG headers:254 - >> Content-Type:
application/x-www-form-urlencoded
10:27:29,932 DEBUG headers:254 - >> Host: 192.168.208.110
10:27:29,932 DEBUG headers:254 - >> Connection: Keep-Alive
10:27:29,932 DEBUG wire:78 - >>
"fields=name%2Cbuyer_credit%2Cphone%2Creal_name&timestamp=2008-12-25+10%3A27%3A29&api_key=suibian&nick=tbtest5&method=taobao.user.get&sign=82D375615F2EC704D9DAD60992359B3A&format=json&v=1.0"
10:27:29,963 DEBUG wire:78 - << "HTTP/1.1 200 OK[EOL]"
10:27:29,963 DEBUG wire:78 - << "Date: Thu, 25 Dec 2008 02:26:40 GMT[EOL]"
10:27:29,963 DEBUG wire:78 - << "Server: Apache-Coyote/1.1[EOL]"
10:27:29,963 DEBUG wire:78 - << "X-Powered-By: Servlet 2.4;
JBoss-4.2.2.GA(build: SVNTag=JBoss_4_2_2_GA
date=200710221139)/Tomcat-5.5[EOL]"
10:27:29,963 DEBUG wire:78 - << "Content-Type:
text/javascript;charset=UTF-8[EOL]"
10:27:29,963 DEBUG wire:78 - << "Content-Length: 85[EOL]"
10:27:29,963 DEBUG wire:78 - << "Vary: Accept-Encoding[EOL]"
10:27:29,963 DEBUG wire:78 - << "Keep-Alive: timeout=15, max=99[EOL]"
10:27:29,963 DEBUG wire:78 - << "Connection: Keep-Alive[EOL]"
10:27:29,963 DEBUG headers:237 - << HTTP/1.1 200 OK
10:27:29,963 DEBUG headers:240 - << Date: Thu, 25 Dec 2008 02:26:40 GMT
10:27:29,963 DEBUG headers:240 - << Server: Apache-Coyote/1.1
10:27:29,963 DEBUG headers:240 - << X-Powered-By: Servlet 2.4;
JBoss-4.2.2.GA (build: SVNTag=JBoss_4_2_2_GA date=200710221139)/Tomcat-5.5
10:27:29,963 DEBUG headers:240 - << Content-Type:
text/javascript;charset=UTF-8
10:27:29,963 DEBUG headers:240 - << Content-Length: 85
10:27:29,963 DEBUG headers:240 - << Vary: Accept-Encoding
10:27:29,963 DEBUG headers:240 - << Keep-Alive: timeout=15, max=99
10:27:29,963 DEBUG headers:240 - << Connection: Keep-Alive
10:27:29,963 DEBUG DefaultRequestDirector:463 - Connection can be kept alive
for 15000 ms
10:27:29,963 DEBUG wire:78 - <<
"{"rsp":{"users":[{"buyer_credit":{"good_num":1,"level":0,"score":1,"total_num":1}}]}}"
10:27:29,963 DEBUG ThreadSafeClientConnManager:221 - Released connection is
reusable.
10:27:29,963 DEBUG ConnPoolByRoute:374 - Releasing connection
[HttpRoute[{}->http://192.168.208.110]][null]
10:27:29,963 DEBUG ConnPoolByRoute:394 - Pooling connection [HttpRoute[{}->
http://192.168.208.110]][null]; keep alive for 15000 MILLISECONDS
10:27:29,963 DEBUG IdleConnectionHandler:78 - Adding connection at:
1230172049963
10:27:29,963 DEBUG ConnPoolByRoute:631 - Notifying no-one, there are no
waiting threads

total duration:328
httpclient4.x0-->firstDuration:281
httpclient4.x0-->successDuration:47,successTimes:1


On Wed, Dec 24, 2008 at 8:57 PM, Oleg Kalnichevski <[email protected]> wrote:

> On Wed, 2008-12-24 at 09:32 +0800, alin(王霖) wrote:
> > Dear Oleg:
> > Thanks for your reply. And here is my simple code (usging
> > httpclient4.0-beta2):
> >
> > private void initHttpClient() {
> > SchemeRegistry schemeRegistry = new SchemeRegistry();
> >         schemeRegistry.register(
> >                 new Scheme("http", PlainSocketFactory.getSocketFactory(),
> > 80));
> > httpParams = new BasicHttpParams();
> > HttpProtocolParams.setVersion(httpParams, HttpVersion.HTTP_1_1);
> > this.setMaxTotalConnections(DEFAULT_MAX_TOTAL_CONNECTIONS);
> > this.setReadTimeout(DEFAULT_READ_TIMEOUT);
> > ClientConnectionManager cm = new ThreadSafeClientConnManager(
> > httpParams, schemeRegistry);
> > httpClient = new DefaultHttpClient(cm, httpParams);
> > }
> >
>
> The code looks all right to me, but it is of little use. I need to see a
> _complete_ wire / context log of the HTTP session to be able to tell why
> connections are not kept alive.
>
> Oleg
>
>
> >
> > On Tue, Dec 23, 2008 at 10:51 PM, Oleg Kalnichevski <[email protected]
> >wrote:
> >
> > > On Mon, 2008-12-22 at 17:46 +0800, alin(王霖) wrote:
> > > > HI:
> > > > I use httpclient3 and httpclient4 for a multi-thread load test,  and
> > > > always set http request header with "Connection:Keep-Alive".
> > > > When i input command "netstat -na | grep myserverhost:myserverport"
> in
> > > > console(My system is windows xp + cygwin) ,  output  like following:
> > > >
> > > > C:\Documents and Settings\lin.wangl>netstat -na | grep
> > > 192.168.208.110:80
> > > >   TCP    10.1.26.82:4159        192.168.208.110:80     ESTABLISHED
> > > >   TCP    10.1.26.82:4160        192.168.208.110:80     ESTABLISHED
> > > >
> > > > But the ports of client connections(here is 10.1.26.82)  is changing
> > > while
> > > > load test is running.
> > > > through log4j, httpclient4 told me:
> > > >
> > > > 17:33:33,049 DEBUG DefaultRequestDirector:463 - Connection can be
> kept
> > > alive
> > > > for 15000 ms
> > > > 17:33:33,065 DEBUG ThreadSafeClientConnManager:221 - Released
> connection
> > > is
> > > > reusable.
> > > > 17:33:33,065 DEBUG ConnPoolByRoute:374 - Releasing connection
> > > > [HttpRoute[{}->http://192.168.208.110]][null]
> > > > 17:33:33,065 DEBUG ConnPoolByRoute:394 - Pooling connection
> > > [HttpRoute[{}->
> > > > http://192.168.208.110]][null]; keep alive for 15000 MILLISECONDS
> > > >
> > > > Who can tell me why this is?
> > > >
> > > >
> > >
> > >
> > > It is just not possible to tell from 16 milliseconds of logs.
> > >
> > > Oleg
> > >
> > >
> > > ---------------------------------------------------------------------
> > > To unsubscribe, e-mail: [email protected]
> > > For additional commands, e-mail: [email protected]
> > >
> > >
> >
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [email protected]
> For additional commands, e-mail: [email protected]
>
>


-- 
Yours alin
msn  [email protected]
phone  88155188-17496
mobile   13858061999

Reply via email to