Update on strange slowdown

[Michael Smith <ms...@xn.com.au>]

The slowdown I was reporting seems to have become more repeatable. This
is good, because it meant I could track down (though not fix - I don't
know the tomcat code nearly well enough) the problem. It's also not so
good, because it MAY be that there are actually two problems.

It turns out that the hosts which were seeing a huge slowdown didn't
have any dns entries (they're internal to our network), and weren't in
my /etc/hosts. As soon as I added a host to /etc/hosts (on the server),
the problem stopped (for that host only). This is with a tomcat 4.0
snapshot from today, but I didn't try using the http/1.0 connector (I
can still do this if you think it'd be useful, Remy).

So, my guess is that it's trying to reverse-resolve the host, and just
waiting until it times out for some reason (logging, perhaps?). I'd
still consider this a serious bug, but a somewhat less crucial one since
there's an easy workaround for it.

However, the symptoms here were entirely reproducible - the original
problem was not. So I think there may be a second problem - if so, I'll
let you know, but it may not be terribly soon because of the fact that
it isn't reproducible. For the moment, I think it's safe to assume that
it was just the single problem.

Michael

Re: Update on strange slowdown

[Remy Maucherat <re...@apache.org>]

> It really should be an option. For speed reasons, you don't usually want
> to do hostname lookups on a major production server, but it's useful on
> smaller and/or test servers.
>
> The problem here, really, is that the hostname lookup is (presumably)
> blocking the thread handling that request. Not really very nice. In the
> meantime, I can easily enough turn off that log.

I've just fixed the logger using a flag. By default, it won't resolve hosts
anymore.

Tomorrow's nightly build will have the fix, as well as beta 2.

Thanks a lot for the help resolving that issue !
Remy

Re: Update on strange slowdown

[Michael Smith <ms...@xn.com.au>]

> The logger was one of my primary suspects, along with the connector (of
> course). I noticed it was logging the host names in the log.
> Should we try to log only the IP address instead of trying to get the fully
> qualified name of the host (which is quite convinient, since it makes the
> log easier to read). Or maybe we could add a a parameter to configure the
> logger to enable / disable host resolution.

It really should be an option. For speed reasons, you don't usually want
to do hostname lookups on a major production server, but it's useful on
smaller and/or test servers. 

The problem here, really, is that the hostname lookup is (presumably)
blocking the thread handling that request. Not really very nice. In the
meantime, I can easily enough turn off that log.

Thanks for looking into this.

Michael

Re: Update on strange slowdown

[Remy Maucherat <re...@apache.org>]

> The only place Tomcat should be doing the DNS lookup is if you actually
call
> request.getRemoteHost() anywhere -- at least, that is the way that the
original
> code worked.  If you only call request.getRemoteAddr(), or you never call
either
> of them, then the DNS lookup is not necessary.
>
> NOTE:  It looks like the default access log valve is doing remote host
lookups
> :-(.  You might try commenting that out of your server.xml file.

The logger was one of my primary suspects, along with the connector (of
course). I noticed it was logging the host names in the log.
Should we try to log only the IP address instead of trying to get the fully
qualified name of the host (which is quite convinient, since it makes the
log easier to read). Or maybe we could add a a parameter to configure the
logger to enable / disable host resolution.

Remy

Re: Update on strange slowdown

["Craig R. McClanahan" <Cr...@eng.sun.com>]

Remy Maucherat wrote:

> > The slowdown I was reporting seems to have become more repeatable. This
> > is good, because it meant I could track down (though not fix - I don't
> > know the tomcat code nearly well enough) the problem. It's also not so
> > good, because it MAY be that there are actually two problems.
> >
> > It turns out that the hosts which were seeing a huge slowdown didn't
> > have any dns entries (they're internal to our network), and weren't in
> > my /etc/hosts. As soon as I added a host to /etc/hosts (on the server),
> > the problem stopped (for that host only). This is with a tomcat 4.0
> > snapshot from today, but I didn't try using the http/1.0 connector (I
> > can still do this if you think it'd be useful, Remy).
> >
> > So, my guess is that it's trying to reverse-resolve the host, and just
> > waiting until it times out for some reason (logging, perhaps?). I'd
> > still consider this a serious bug, but a somewhat less crucial one since
> > there's an easy workaround for it.
> >
> > However, the symptoms here were entirely reproducible - the original
> > problem was not. So I think there may be a second problem - if so, I'll
> > let you know, but it may not be terribly soon because of the fact that
> > it isn't reproducible. For the moment, I think it's safe to assume that
> > it was just the single problem.
>
> I hope there isn't a second problem, because it looks like it would be quite
> hard to reproduce and debug ;)
>
> The host resolution problem is definitely something I'll have to fix ASAP. I
> don't really know yet which part of Tomcat is doing the lookup.
> I would have been very surprised if it was a Slide problem (but of course,
> you never know).
>

The only place Tomcat should be doing the DNS lookup is if you actually call
request.getRemoteHost() anywhere -- at least, that is the way that the original
code worked.  If you only call request.getRemoteAddr(), or you never call either
of them, then the DNS lookup is not necessary.

NOTE:  It looks like the default access log valve is doing remote host lookups
:-(.  You might try commenting that out of your server.xml file.

>
> Thanks a lot for the bug report :)
> Remy

Craig

Re: Update on strange slowdown

[Remy Maucherat <re...@apache.org>]

> The slowdown I was reporting seems to have become more repeatable. This
> is good, because it meant I could track down (though not fix - I don't
> know the tomcat code nearly well enough) the problem. It's also not so
> good, because it MAY be that there are actually two problems.
>
> It turns out that the hosts which were seeing a huge slowdown didn't
> have any dns entries (they're internal to our network), and weren't in
> my /etc/hosts. As soon as I added a host to /etc/hosts (on the server),
> the problem stopped (for that host only). This is with a tomcat 4.0
> snapshot from today, but I didn't try using the http/1.0 connector (I
> can still do this if you think it'd be useful, Remy).
>
> So, my guess is that it's trying to reverse-resolve the host, and just
> waiting until it times out for some reason (logging, perhaps?). I'd
> still consider this a serious bug, but a somewhat less crucial one since
> there's an easy workaround for it.
>
> However, the symptoms here were entirely reproducible - the original
> problem was not. So I think there may be a second problem - if so, I'll
> let you know, but it may not be terribly soon because of the fact that
> it isn't reproducible. For the moment, I think it's safe to assume that
> it was just the single problem.

I hope there isn't a second problem, because it looks like it would be quite
hard to reproduce and debug ;)

The host resolution problem is definitely something I'll have to fix ASAP. I
don't really know yet which part of Tomcat is doing the lookup.
I would have been very surprised if it was a Slide problem (but of course,
you never know).

Thanks a lot for the bug report :)
Remy