You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Greg Ames <gr...@remulak.net> on 2002/01/17 02:54:34 UTC
load spikes revisited
I had 2.0.30-dev up briefly on daedalus tonight to collect doc on our load spike
problem. Brian B, my apologies if you got paged.
Anyway, there's about 20 seconds worth of ktrace output at
http://www.apache.org/~gregames/ktrace. We might have some kind of thundering
herd problem - I see a whole bunch of unproductive context switches about the
time a select pops.
Then I tried 2.0.29-dev from Nov. 15, with Ryan's patch to fix the timeouts on
top of that. That's got the load spikes as well, and that's not very long after
we tagged 2_0_28.
Greg
Re: load spikes revisited
Posted by Jeff Trawick <tr...@attglobal.net>.
Justin Erenkrantz <je...@ebuilt.com> writes:
> On Wed, Jan 16, 2002 at 08:54:34PM -0500, Greg Ames wrote:
> > Anyway, there's about 20 seconds worth of ktrace output at
> > http://www.apache.org/~gregames/ktrace. We might have some kind of thundering
> > herd problem - I see a whole bunch of unproductive context switches about the
> > time a select pops.
>
> You mentioned that daedalus doesn't use any AcceptMutex. I tried to
> find your config files, but couldn't find any reference to
> AcceptMutex (in /usr/local/apache*). Could we try httpd with some
> locking mechanism? (I'm guessing you use modified code to bypass
> AcceptMutex.)
apache.org has only one listen statement, and since it is FreeBSD it
isn't supposed to need a mutex for that configuration.
--
Jeff Trawick | trawick@attglobal.net | PGP public key at web site:
http://www.geocities.com/SiliconValley/Park/9289/
Born in Roswell... married an alien...
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Greg Ames wrote:
> While trying out ktrace on my test config, I saw that
> the fcntl() accept mutex has got a thundering herd problem on daedalus.
uhhh, I might have been wrong about this.
Looking at the ktrace from 2.0.30-dev in production last night, I see very
similar behavior (big bunches of processes getting woken up and immediately
going back to sleep with no intervening trace records) for processes that are
blocked in select or poll with a timeout. This happens maybe 8-16 times a
second until the timeout expires or the socket is ready.
If one of those timers popped at about the same time the fcntl mutex was
released, it would look pretty much the same as what I saw with the test
config. So let's look at FreeBSD's fcntl locking more closely before we rip it
out. I sure wish there was a timer interrupt trace record.
Greg
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Aaron Bannert wrote:
>
> On Thu, Jan 17, 2002 at 10:20:00AM -0500, Greg Ames wrote:
> [snip]
> > As a matter of fact, I typically listen on two ports while testing to disable
> > S_L_U_A, so I can easily figure out which process will get the next connection
> > in case I want to gdb it. While trying out ktrace on my test config, I saw that
> > the fcntl() accept mutex has got a thundering herd problem on daedalus. After
> > releasing the fcntl mutex, you see the kernel context switching to all of the
> > idle httpd processes. The first process that wakes up gets the mutex, the rest
> > of the context switches simply burn a little CPU, then block again. Moral: the
> > default cure looks as bad as the disease.
>
> Is there anywhere else that we've started using cross process locks
> since 2.0.28? If fcntl() is known to cause this behaviour, why is it
> enabled at all on this version of FreeBSD?
I didn't know about this until yesterday. Nobody else mentioned it AFAIK.
> Based on your ktrace output from a couple days ago, I have a working
> theory that I have yet to reproduce: I noticed that there is a very
> high occurance of sendfile returning with errno 35 (Resource temporarily
> unavailable).
On FreeBSD, sendfile will almost always return -1 errno 35 for big files. That
simply means the file is bigger than the socket buffers and the disk i/o
bandwidth is higher than the network bandwidth to the user. But we call
sendfile twice as often as we need to on FreeBSD and probably Solaris. I
consistently see a pattern of two sendfiles then a select. When apr sees that
sendfile sent some bytes, we change the retval from -1 and quickly forget that
it told us it would block. We do need to exit from apr_sendfile after it sends
bytes so that the app can update the offset & length etc. But before exiting,
apr should put a mark on the wall that tells us to issue select() first next
time apr_sendfile is called, because the kernel just told us what was likely to
happen.
We already have this kind of logic in apr_recv. It uses the APR_INCOMPLETE_READ
flag to predict whether the next call will return EAGAIN/EWOULDBLOCK, so we know
to try select() first on the next apr call. Perhaps we should rename this to
APR_INCOMPLETE_IO and use it in apr_sendfile, or get really crazy and use a new
flag.
> Unfortunately, I don't think this will account for the short bursts of run
> queue growth we're talking about here, but it is something to look into.
Right. The double sendfiles() have been happening for ages, so they are not the
cause of the load spike problem. They certainly need to be addressed, along
with a number of other extra syscall problems. However, if you look at the
change log for apr_sendfile, you'll see that we've gone round and round trying
to get it right on FreeBSD. So this change needs to coded, reviewed and tested
very carefully.
Greg
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Aaron Bannert wrote:
>
> On Thu, Jan 17, 2002 at 11:08:37PM -0500, Greg Ames wrote:
> > No, you have to look at how sendfile_it_all interacts with apr_sendfile and the
> > kernel. It blocks in select() until the kernel is happy with the amount of room
> > in its socket buffers.
> Yes, I see that now. If I get a chance I'll try to add the
> APR_INCOMPLETE_foo state you were talking about. Is there a reason we
> don't just call sendfile in blocking mode?
unfortunately, yes. We want to be able to time out if the sendfile isn't making
progress. I believe that a blocking sendfile would hang the process forever if
the client just disappears.
It would be great if there were a way around this, at least on FreeBSD. Some
kind of blocking sendfile with a built-in way to timeout if no progress is being
made that doesn't involve many unproductive context switches a second. It would
be even better if select with a timeout could avoid all those nearly useless
dispatches, because select is more general purpose.
Greg
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Aaron Bannert wrote:
> If I get a chance I'll try to add the
> APR_INCOMPLETE_foo state you were talking about. Is there a reason we
> don't just call sendfile in blocking mode?
Your question about blocking mode has got me thinking more about this. It sure
would be nice if we could persuade TCP to time out the connection if the client
disappears. Maybe it does already; maybe we need to set some sockopts; I don't
know. Besides getting rid of a lot of sendfile syscalls, that would get rid of
a lot of selects with timeouts, which should reduce the size of our remaining
thundering herd. Well, it's not really thundering any more, it's more of a
distant rumble.
Remember that Justin commented about seeing a run queue size of 50 on daedalus?
(actually, it goes up into the 60's fairly regularly.) I'll bet nearly half of
those are due to selects for people doing big downloads.
Greg
Re: load spikes revisited
Posted by Aaron Bannert <aa...@clove.org>.
On Thu, Jan 17, 2002 at 11:08:37PM -0500, Greg Ames wrote:
> No, you have to look at how sendfile_it_all interacts with apr_sendfile and the
> kernel. It blocks in select() until the kernel is happy with the amount of room
> in its socket buffers. Then the select returns to apr_sendfile, which issues
> the next sendfile which will send some data (a multiple of 4k usually on
> daedalus) but returns with -1 errno 35 anyway. We change the retval to 0,
> forget that the kernel warned us about blocking, and unwind to sendfile_it_all.
> It updates its offset and length to account for what was sent, and calls
> apr_sendfile again. apr_sendfile issues another sendfile right away, which is
> almost always doomed to get -1 errno 35 with no bytes sent. (This unproductive
> sendfile call could be eliminated by remembering that the kernel told us it
> would block across apr_sendfile invocations.) Then we call select and block and
> start over.
Yes, I see that now. If I get a chance I'll try to add the
APR_INCOMPLETE_foo state you were talking about. Is there a reason we
don't just call sendfile in blocking mode?
-aaron
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Aaron Bannert wrote:
got my nose out of the ktraces finally, so I re-read this a little closer.
> A quick glance at sendfile_it_all in server/core.c looks to me
> like it would loop repeatedly on that error condition, as we are seeing
> it in the ktrace output.
No, you have to look at how sendfile_it_all interacts with apr_sendfile and the
kernel. It blocks in select() until the kernel is happy with the amount of room
in its socket buffers. Then the select returns to apr_sendfile, which issues
the next sendfile which will send some data (a multiple of 4k usually on
daedalus) but returns with -1 errno 35 anyway. We change the retval to 0,
forget that the kernel warned us about blocking, and unwind to sendfile_it_all.
It updates its offset and length to account for what was sent, and calls
apr_sendfile again. apr_sendfile issues another sendfile right away, which is
almost always doomed to get -1 errno 35 with no bytes sent. (This unproductive
sendfile call could be eliminated by remembering that the kernel told us it
would block across apr_sendfile invocations.) Then we call select and block and
start over.
Greg
Re: load spikes revisited
Posted by Aaron Bannert <aa...@clove.org>.
On Thu, Jan 17, 2002 at 10:20:00AM -0500, Greg Ames wrote:
[snip]
> As a matter of fact, I typically listen on two ports while testing to disable
> S_L_U_A, so I can easily figure out which process will get the next connection
> in case I want to gdb it. While trying out ktrace on my test config, I saw that
> the fcntl() accept mutex has got a thundering herd problem on daedalus. After
> releasing the fcntl mutex, you see the kernel context switching to all of the
> idle httpd processes. The first process that wakes up gets the mutex, the rest
> of the context switches simply burn a little CPU, then block again. Moral: the
> default cure looks as bad as the disease.
Is there anywhere else that we've started using cross process locks
since 2.0.28? If fcntl() is known to cause this behaviour, why is it
enabled at all on this version of FreeBSD?
Based on your ktrace output from a couple days ago, I have a working
theory that I have yet to reproduce: I noticed that there is a very
high occurance of sendfile returning with errno 35 (Resource temporarily
unavailable). The sendfile(2) man page reveals that this means sendfile
was called in non-blocking mode, and the kernel buffers have filled
up. A quick glance at sendfile_it_all in server/core.c looks to me
like it would loop repeatedly on that error condition, as we are seeing
it in the ktrace output. This means that on low-bandwidth connections
like modems, we'll burn cycles testing if the kernel buffer is ready
for more data while the modem still hasn't pulled the next packet down.
I haven't been able to reproduce this, since I am not exactly sure what
conditions are required to trigger sendfile. Can someone give me a
URL that will consistently trigger the use of sendfile?
Unfortunately, I don't think this will account for the short bursts of run
queue growth we're talking about here, but it is something to look into.
-aaron
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Justin Erenkrantz wrote:
>
> On Wed, Jan 16, 2002 at 08:54:34PM -0500, Greg Ames wrote:
> > Anyway, there's about 20 seconds worth of ktrace output at
> > http://www.apache.org/~gregames/ktrace. We might have some kind of thundering
> > herd problem - I see a whole bunch of unproductive context switches about the
> > time a select pops.
>
> You mentioned that daedalus doesn't use any AcceptMutex. I tried to
> find your config files,
not hard to find - /usr/local/apache/conf/httpd.conf for the current production
server
> but couldn't find any reference to
> AcceptMutex (in /usr/local/apache*). Could we try httpd with some
> locking mechanism? (I'm guessing you use modified code to bypass
> AcceptMutex.)
as Jeff pointed out, FreeBSD's accept() is supposed to be free of thundering
herd, so Single Listen Unserialized Accept kicks in with the production config
which only listens on port 80. I wouldn't jump to the conclusion that accept()
is causing it before looking at the data.
As a matter of fact, I typically listen on two ports while testing to disable
S_L_U_A, so I can easily figure out which process will get the next connection
in case I want to gdb it. While trying out ktrace on my test config, I saw that
the fcntl() accept mutex has got a thundering herd problem on daedalus. After
releasing the fcntl mutex, you see the kernel context switching to all of the
idle httpd processes. The first process that wakes up gets the mutex, the rest
of the context switches simply burn a little CPU, then block again. Moral: the
default cure looks as bad as the disease.
> Based on looking at daedalus over the weekend, I saw the run-queue
> spike up to 50
I don't get excited about 50. When I put up code beyond Nov 15, the spikes go
up to the 250 - 350 range (i.e. _all_ httpd processes plus whatever else wants
to run). After several minutes of running, the load averages start climbing
into the double digits. If that continues long enough, Brian Behlendorf gets
paged. He doesn't get paged when 2_0_28 is running.
Greg
Re: load spikes revisited
Posted by Justin Erenkrantz <je...@ebuilt.com>.
On Wed, Jan 16, 2002 at 08:54:34PM -0500, Greg Ames wrote:
> Anyway, there's about 20 seconds worth of ktrace output at
> http://www.apache.org/~gregames/ktrace. We might have some kind of thundering
> herd problem - I see a whole bunch of unproductive context switches about the
> time a select pops.
You mentioned that daedalus doesn't use any AcceptMutex. I tried to
find your config files, but couldn't find any reference to
AcceptMutex (in /usr/local/apache*). Could we try httpd with some
locking mechanism? (I'm guessing you use modified code to bypass
AcceptMutex.)
Based on looking at daedalus over the weekend, I saw the run-queue
spike up to 50 - this should have been with 2.0.28, so I think this
load spike problem happens with that version as well.
Another thing to try would be to update icarus's httpd to 2.0.28
or HEAD and see how it fares. It should handle all of the ViewCVS
traffic, but I think icarus has identical HW/OS setup to
daedalus. (I can't seem to reproduce it here.) -- justin
Re: load spikes revisited
Posted by Brian Pane <bp...@pacbell.net>.
Aaron Bannert wrote:
>>So is the situation basically this:
>> * Single listener unserialized accept is enabled on daedalus,
>> * We thus have all the idle httpd procs doing a poll before the
>> accept,
>> * And the spikes in load happen because of the thundering herd
>> waking up from the poll when a connection arrives?
>>
>>If that's the root cause, then I guess 2.0.29 or later with, say,
>>pthread mutex accept serialization should be able to run without
>>load spikes on daedalus?
>>
>
>I agree, but I have the same reply as above. This may only hide the
>problem.
>
Right, it will only hide the problem. The real point of trying
the accept mutex on daedalus is as a test case to prove or disprove
the idea that a thundering herd in poll is the problem.
--Brian
Re: load spikes revisited
Posted by Brian Pane <bp...@pacbell.net>.
Aaron Bannert wrote:
>On Thu, Jan 17, 2002 at 10:43:18PM -0800, Brian Pane wrote:
>[snip]
>
>>>prefork was changed to do a apr_poll before the accept, even in the single
>>>listen case, on Nov 10. The polls seem to get added to the herd of selects
>>>that
>>>wake up several times a second for no real good reason. We need to get rid
>>>of
>>>this poll once again.
>>>
>
>We should get rid of the poll() for S_L_U_A, but I think that would
>only treat the symptom, since it would come back when we had multiple
>listeners.
>
But in the multiple listener case, access to the poll will always
be serialized, so we won't be vulnerable to a thundering herd problem,
right?
> Personally, I think poll() is itself the problem, and my
>theory is that poll() has a thundering hurd problem on this particular
>version of FreeBSD. We can try this out by #undef'ing HAVE_POLL in
>srclib/apr/network_io/unix/poll.c, so we use select() instead, which
>is what we used to do before Nov 10th.
>
Yep, I think the poll is the problem too. We ought to be
able to remove it altogether in the single-listener case,
though.
--Brian
Re: load spikes revisited
Posted by Aaron Bannert <aa...@clove.org>.
On Thu, Jan 17, 2002 at 10:43:18PM -0800, Brian Pane wrote:
[snip]
> >prefork was changed to do a apr_poll before the accept, even in the single
> >listen case, on Nov 10. The polls seem to get added to the herd of selects
> >that
> >wake up several times a second for no real good reason. We need to get rid
> >of
> >this poll once again.
We should get rid of the poll() for S_L_U_A, but I think that would
only treat the symptom, since it would come back when we had multiple
listeners. Personally, I think poll() is itself the problem, and my
theory is that poll() has a thundering hurd problem on this particular
version of FreeBSD. We can try this out by #undef'ing HAVE_POLL in
srclib/apr/network_io/unix/poll.c, so we use select() instead, which
is what we used to do before Nov 10th.
> So is the situation basically this:
> * Single listener unserialized accept is enabled on daedalus,
> * We thus have all the idle httpd procs doing a poll before the
> accept,
> * And the spikes in load happen because of the thundering herd
> waking up from the poll when a connection arrives?
>
> If that's the root cause, then I guess 2.0.29 or later with, say,
> pthread mutex accept serialization should be able to run without
> load spikes on daedalus?
I agree, but I have the same reply as above. This may only hide the
problem.
-aaron
Re: load spikes revisited
Posted by Brian Pane <bp...@pacbell.net>.
Greg Ames wrote:
>Getting a lot closer. httpd://www.apache.org/~gregames/ktrace.2_0_28 now has 30
>some seconds of ktrace for comparison purposes. Interestingly enough, this file
>is considerably smaller than the 2.0.30-dev file which ran for less time.
>There's about twice the context switches in 2.0.30-dev's ktrace.
>
>prefork was changed to do a apr_poll before the accept, even in the single
>listen case, on Nov 10. The polls seem to get added to the herd of selects that
>wake up several times a second for no real good reason. We need to get rid of
>this poll once again.
>
So is the situation basically this:
* Single listener unserialized accept is enabled on daedalus,
* We thus have all the idle httpd procs doing a poll before the
accept,
* And the spikes in load happen because of the thundering herd
waking up from the poll when a connection arrives?
If that's the root cause, then I guess 2.0.29 or later with, say,
pthread mutex accept serialization should be able to run without
load spikes on daedalus?
--Brian
Re: load spikes revisited
Posted by Greg Ames <gr...@remulak.net>.
Greg Ames wrote:
>
> I had 2.0.30-dev up briefly on daedalus tonight to collect doc on our load spike
> problem.
> Anyway, there's about 20 seconds worth of ktrace output at
> http://www.apache.org/~gregames/ktrace. We might have some kind of thundering
> herd problem - I see a whole bunch of unproductive context switches about the
> time a select pops.
>
> Then I tried 2.0.29-dev from Nov. 15, with Ryan's patch to fix the timeouts on
> top of that. That's got the load spikes as well, and that's not very long after
> we tagged 2_0_28.
Getting a lot closer. httpd://www.apache.org/~gregames/ktrace.2_0_28 now has 30
some seconds of ktrace for comparison purposes. Interestingly enough, this file
is considerably smaller than the 2.0.30-dev file which ran for less time.
There's about twice the context switches in 2.0.30-dev's ktrace.
prefork was changed to do a apr_poll before the accept, even in the single
listen case, on Nov 10. The polls seem to get added to the herd of selects that
wake up several times a second for no real good reason. We need to get rid of
this poll once again.
Greg