Mailing-List: contact dev-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@httpd.apache.org
Received-SPF: neutral (nike.apache.org: local policy)
From: Arkadiusz =?utf-8?q?Mi=C5=9Bkiewicz?= <arekm@maven.pl>
To: dev@httpd.apache.org
Subject: Re: 2.4.4 graceful restart taking long time
Date: Thu, 11 Apr 2013 15:28:18 +0200
User-Agent: KMail/1.13.7 (Linux/3.8.6-dirty; KDE/4.10.2; x86_64; ; )
Cc: "=?utf-8?q?Pl=C3=BCm?=, =?utf-8?q?R=C3=BCdiger?=,
 Vodafone Group" <ruediger.pluem@vodafone.com>
References: <201304111343.03985.arekm@maven.pl>
 <AB1691BE05AE7F4992697F2A0835627A5B6FB81C@VOEXM09W.internal.vodafone.com>
In-Reply-To: 
 <AB1691BE05AE7F4992697F2A0835627A5B6FB81C@VOEXM09W.internal.vodafone.com>
MIME-Version: 1.0
Content-Type: Text/Plain;
  charset="utf-8"
Content-Transfer-Encoding: quoted-printable
Message-Id: <201304111528.18891.arekm@maven.pl>

On Thursday 11 of April 2013, Pl=C3=BCm, R=C3=BCdiger, Vodafone Group wrote:

> > On apache 2.2.22, 2.2.23 and 2.4.4 I'm able to reproduce a problem
> > where graceful restart takes very long time. Linux 3.7.10, glibc 2.17
> > here.
> > Example strace of main httpd process while doing graceful restart:
> > http://pastebin.com/QFH5TjT6
>=20
> From the strace

Here is similar strace but without ab running, one second is enough
http://pastebin.com/HKjxxP2p (StartServers 64 this time, ab -c 64)

> it looks like the connect takes a lot of time later on (the
> poll is waiting 1 second for the connect to complete).=20

That strace was done with StartServers 128 but ab was using -c 64, so looks=
=20
like idle children responded fast (that first second), busy - too slowly.

Another strace including children
http://ixion.pld-linux.org/~arekm/apache1.txt

Graceful restart and first OPTIONS write at=20

12594 15:10:01.397356 write(7, "OPTIONS * HTTP/1.0\r\nUser-Agent: Apache/2.=
4.4=20
(Unix) (internal dummy connection)\r\n\r\n", 83 <unfinished ...>

but first read is long after write

13279 15:10:52.636685 <... read resumed> "OPTIONS * HTTP/1.0\r\nUser-Agent:=
=20
Apache/2.4.4 (Unix) (internal dummy connection)\r\n\r\n", 8000) =3D 83=20
<0.000014>

Huh?

That's even after resuming operations mesage which was a bit earlier:

12594 15:10:52.606253 write(2, "[Thu Apr 11 15:10:52.606236 2013]=20
[mpm_prefork:notice] [pid 12594] AH00163: Apache/2.4.4 (Unix) configured --=
=20
resuming normal operations\n", 137) =3D 137 <0.000009>

Compare that to case where ab wasn't running:
http://ixion.pld-linux.org/~arekm/apache-no-ab.txt
write OPTIONS in main process and read in childrens are interleaving as=20
expected.

Now why these aren't interleaving in apache1.txt where ab was running?

> As the accept call
> on httpd side only returns when the first data is send on the socket, IMHO
> the time the poll takes does take place in the kernel and not in the httpd
> children code.

Well, I think kernel is not the one to blame.

> Have you checked your messages file if the kernel reports
> something when this happens? How does your run queue and CPU load look
> like when this happens (top)?

No kernel messages, no cpu spikes - looks normal.

> Regards
> R=C3=BCdiger

=2D-=20
Arkadiusz Mi=C5=9Bkiewicz, arekm / maven.pl