httpd-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Martin Gerdes <marting...@googlemail.com>
Subject [users@httpd] activating xml2enc makes client getting HTML-Page take very long
Date Tue, 10 Nov 2009 08:56:50 GMT
Alright, xml2enc works, does not crash, and correctly translates UTF8 back
to ISO-8859-1 after it was converted to UTF-8 by mod_proxy_html.

However, activating that translation back to ISO-8859-1 makes the whole
process take up a lot of time, and I have no idea why, so I am asking for
ideas.
First, how slow is slow? Time from pushing the send button until the new
webpage is loaded rises from 10.6 to 103 seconds.
And every page of the webapplication I have tried is just as slow, so its
not just a particular page which loads very slowly.

Top on the server shows that the server is sitting idle, so it's not that
the recoding is taking up that much CPU (which would be ridiculous anyway).

Configuration which is slow (in /etc/apache2/apache2.conf):
ProxyHTMLEnable On
ProxyHTMLCharsetOut *
ProxyHTMLExtended On
ProxyHTMLMeta On
ProxyHTMLLogVerbose On

It becomes fast if I comment out the line "ProxyHTMLCharsetOut *"
SSL has been disabled to reduce the complexity of the problem.

==Snippets from /var/log/apache2/error.log (Loglevel debug)==
[Mon Nov 09 11:38:14 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL
//localhost:50100/dwhfe/pub/Authentication.htm;jsessionid=26BB5D99A6206A68651C07DFCDD291B1
...
[Mon Nov 09 11:38:16 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:38:16 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)
[Mon Nov 09 11:38:31 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL //localhost:50100/dwhfe/app/style/ajax/theme/ui.base.css
...
[Mon Nov 09 11:38:31 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:38:31 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)
[Mon Nov 09 11:38:46 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL //localhost:50100/dwhfe/pub/Authentication.htm
...
[Mon Nov 09 11:38:46 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:38:46 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)
[Mon Nov 09 11:39:01 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL //localhost:50100/dwhfe/pub/Authentication.htm
...
[Mon Nov 09 11:39:01 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:39:01 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)
[Mon Nov 09 11:39:16 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL //localhost:50100/dwhfe/pub/Authentication.htm
...
[Mon Nov 09 11:39:16 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:39:16 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)
[Mon Nov 09 11:39:31 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL //localhost:50100/dwhfe/pub/Authentication.htm
...
[Mon Nov 09 11:39:31 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:39:31 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)
[Mon Nov 09 11:39:46 2009] [debug] mod_proxy_http.c(60): proxy: HTTP:
canonicalising URL //localhost:50100/dwhfe/pub/Authentication.htm
...
[Mon Nov 09 11:39:46 2009] [debug] mod_proxy_http.c(1803): proxy: end body
send
[Mon Nov 09 11:39:46 2009] [debug] proxy_util.c(2008): proxy: HTTP: has
released connection for (localhost)

As can be seen, in each case the connection is released, and then there is
no more work for 15 seconds. So the time is not lost while the module is
translating (e.g. because of a timeout).

==Packet traffic sniffed in front of the proxy (client is 192.168.0.9,
outgoing port is 443 (no SSL), and between proxy and backend (port serving
the data internally is 50100)==
( I=traffic between proxy and backend; E=traffic between proxy and client )
I 16:25:42.693049 IP 127.0.0.1.50100 > 127.0.0.1.41421: P 9513:14946(5433)
ack 2117 win 297 #HTML Data
I 16:25:42.693125 IP 127.0.0.1.41421 > 127.0.0.1.50100: . ack 14946 win 387
E 16:25:42.694255 IP 192.168.0.100.443 > 192.168.0.9.55306: .
9473:13853(4380) ack 1895 win 82 #HTML Data Part 1
E 16:25:42.694412 IP 192.168.0.100.443 > 192.168.0.9.55306: P
13853:14924(1071) ack 1895 win 82 #HTML Data Part 2
E 16:25:42.694860 IP 192.168.0.9.55306 > 192.168.0.100.443: . ack 12393 win
16425
E 16:25:42.695077 IP 192.168.0.9.55306 > 192.168.0.100.443: . ack 14924 win
16425
E 16:25:57.702107 IP 192.168.0.100.443 > 192.168.0.9.55306: F 14924:14924(0)
ack 1895 win 82
E 16:25:57.702514 IP 192.168.0.9.55306 > 192.168.0.100.443: . ack 14925 win
16425
E 16:25:57.702715 IP 192.168.0.9.55306 > 192.168.0.100.443: F 1895:1895(0)
ack 14925 win 16425
E 16:25:57.702736 IP 192.168.0.100.443 > 192.168.0.9.55306: . ack 1896 win
82
E 16:25:59.105400 IP 192.168.0.9.55308 > 192.168.0.100.443: S
1692924107:1692924107(0) win 8192 <mss 1460,nop,wscale 2,nop,nop,sackOK>
E 16:25:59.105543 IP 192.168.0.100.443 > 192.168.0.9.55308: S
3020885945:3020885945(0) ack 1692924108 win 5840 <mss
1460,nop,nop,sackOK,nop,wscale 7>
E 16:25:59.105832 IP 192.168.0.9.55308 > 192.168.0.100.443: . ack 1 win
16425
E 16:25:59.106002 IP 192.168.0.9.55308 > 192.168.0.100.443: P 1:523(522) ack
1 win 16425 # GET Request
I 16:25:59.106895 IP 127.0.0.1.41852 > 127.0.0.1.50100: F
1298653661:1298653661(0) ack 1288489298 win 900
I 16:25:59.106932 IP 127.0.0.1.50100 > 127.0.0.1.41852: R
1288489298:1288489298(0) win 0
I 16:25:59.107142 IP 127.0.0.1.41424 > 127.0.0.1.50100: S
3012199744:3012199744(0) win 32792 <mss 16396,nop,nop,sackOK,nop,wscale 7>
I 16:25:59.107217 IP 127.0.0.1.50100 > 127.0.0.1.41424: S
3023186444:3023186444(0) ack 3012199745 win 32792 <mss
16396,nop,nop,sackOK,nop,wscale 7>
I 16:25:59.107245 IP 127.0.0.1.41424 > 127.0.0.1.50100: . ack 1 win 257
I 16:25:59.107985 IP 127.0.0.1.41424 > 127.0.0.1.50100: P 1:597(596) ack 1
win 257 # the GET Request

I'm not sure if I am interpreting all of this correctly, but to me it seems
obvious, that nobody is talking to the backend: The proxy is sending back
its acknowledgment that it got the data at 16:25:42.693125. The next time
anyone talks to the backend at all is at 16:25:59.106895, at which point the
TCP connection is reestablished.
There seems to be a problem between client and proxy making them reestablish
their TCP connection at 16:25:59.105400.
Seeing how regularly spaced the delays are, I am going to assume that the
TCP connection is lost and reestablished after each send file.
But what does ANY of this have to do with whether or not I enable xml2enc in
the reverse proxy!?

Does anyone have any reasoning that can make a bit of sense out of this. I
simply fail to see the logic here...

Thanks in advance!

Mime
View raw message