activating xml2enc makes client getting HTML-Page take very long

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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!



[Index of Archives]     [Open SSH Users]     [Linux ACPI]     [Linux Kernel]     [Linux Laptop]     [Kernel Newbies]     [Security]     [Netfilter]     [Bugtraq]     [Squid]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Samba]     [Video 4 Linux]     [Device Mapper]

  Powered by Linux