[users@httpd] activating xml2enc makes client getting HTML-Page take very long

[Martin Gerdes <ma...@googlemail.com>]

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!

Re: [users@httpd] activating xml2enc makes client getting HTML-Page take very long

[Martin Gerdes <ma...@googlemail.com>]

>
>
>  Can you get mod_diagnostics
>> output to track the data running through the filter?
>>
>> I'll try that after lunch. Ask if you want to know anything else. (I can
> for example packet sniff the connection between IE and the proxy, and give
> you the debug output of mod_proxy_html in that constallation. Provided you
> are interested in that information.)
>
>
Okay, I have created a debian package with alien (as there does not seem to
exist a native debian package), and gotten apache to load the module.
Which configuration makes it give it the output you want? (on
http://apache.webthing.com/mod_diagnostics/ I don't see any usage
instructions)

If I still used the old version of proxy-html, I guess I'd change the filter
chain to "SetOutputFilter diagnostics proxy-html diagnostics"?
But that line is commented out now, and replaced by "ProxyHTMLEnable On".
So just tell me how to generate the output you want to have. I'd then send
the output to your email adress only, as there is no need for the
application data to be on the public list.

Martin

Re: [users@httpd] activating xml2enc makes client getting HTML-Page take very long

[Martin Gerdes <ma...@googlemail.com>]

>
> On 10 Nov 2009, at 08:56, Martin Gerdes wrote:
>
>  First, how slow is slow? Time from pushing the send button until the new
>> webpage is loaded rises from 10.6 to 103 seconds.
>>
>
> 10.6 is already horrendously slow (unless perhaps it's a 20-year-old PC),
> which leads me to wonder what you're doing.  One thing is that with
> ProxyHTMLExtended On you could be parsing lots of text, so make
> sure you use flags to ensure you don't apply more rules to it than
> you absolutely need to.


Its a complex application, its running in a slow VM for testing purposes,
and is itself communicating with a slow test backend in another slow VM. I
am not programming the application, but I have no fear about the 10 seconds.
Especially since they have nothing to do with the proxy: It stays just as
slow if I connect directly to the application (without any encoding
transformations at all). So that simply isn't part of my problem (if it is a
problem, it's someone else's).


>
> Does it make any difference if lots of small rewrites have happened
> vs. if nothing matched any proxy_html rules?
>
> No. It stays just as slow if there isn't a single transformation rule at
all (mod_proxy_html is not doing anything).


>  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).
>>
>
> Does it make any difference if you send an HTTP/1.0 request
> or force a connection close?

The version used in the connections is HTTP/1.1 (I see that in the content
of the transmitted packets).
I wasn't able to try out HTTP/1.0, and haven't looked into how to force a
connection close (what exactly should I try there?)

Instead I have other very interesting observations: I tried the application
out in IE (with the intent to force HTTP/1.0).
Once I press the login button, IE tells me I have no connection to the
internet, and stays with that opinion for any and all sites until I restart
it. Interestingly, IE shows this behaviour even if I comment the line
"ProxyHTMLCharsetOut *" out (which is enough to make firefox fast). [All of
this tried with and without forcing HTTP/1.0]
Commenting out all ProxyHTML directives makes the website work, and work
fast.

 Can you get mod_diagnostics
> output to track the data running through the filter?
>
> I'll try that after lunch. Ask if you want to know anything else. (I can
for example packet sniff the connection between IE and the proxy, and give
you the debug output of mod_proxy_html in that constallation. Provided you
are interested in that information.)

Kind regards,

Martin

Re: [users@httpd] activating xml2enc makes client getting HTML-Page take very long

[Nick Kew <ni...@webthing.com>]

On 10 Nov 2009, at 08:56, Martin Gerdes wrote:

> First, how slow is slow? Time from pushing the send button until the  
> new webpage is loaded rises from 10.6 to 103 seconds.

10.6 is already horrendously slow (unless perhaps it's a 20-year-old  
PC),
which leads me to wonder what you're doing.  One thing is that with
ProxyHTMLExtended On you could be parsing lots of text, so make
sure you use flags to ensure you don't apply more rules to it than
you absolutely need to.

> And every page of the webapplication I have tried is just as slow,  
> so its not just a particular page which loads very slowly.

The encoding to utf-8 happens within libxml2 if the input encoding is
supported.  The output is a invokes apr_xlate, which in turn is normally
a wrapper for iconv.  So this could be pointing the finger at your  
iconv.

Does it make any difference if lots of small rewrites have happened
vs. if nothing matched any proxy_html rules?

> 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).

Does it make any difference if you send an HTTP/1.0 request
or force a connection close?  Can you get mod_diagnostics
output to track the data running through the filter?

-- 
Nick Kew

---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@httpd.apache.org
   "   from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org