[pmwiki-users] Wiki speed diferences, no apparent reason
Patrick R. Michaud
pmichaud at pobox.com
Wed Mar 22 10:50:11 CST 2006
On Wed, Mar 22, 2006 at 04:07:06PM +0100, Joachim Durchholz wrote:
> Patrick R. Michaud schrieb:
> > On Wed, Mar 22, 2006 at 02:09:05PM +0100, Joachim Durchholz wrote:
> > I also find it bizarre that many of the PmWiki/PHP processes
> > continue running beyond the "max execution time" parameter
> > (30 seconds on pmwiki.org), which again would seem to indicate
> > a problem in PHP or Apache and not PmWiki.
> That might be because the numbers might relate to different things.
> IIRC PHP's resource limit is userspace CPU seconds and doesn't include
> the time for subprocesses or system calls.
Yes, that's correct, but I'm saying the numbers still don't make sense.
For background, the numbers I'm looking at are wall-clock time as
reported by Apache's server-status handler. For those who are interested,
I've gone ahead and opened up the server-status report on my server
for public viewing -- it's at http://www.pmwiki.org/server-status.
More on this below.
Let's assume that PHP's max_execution_time on pmwiki.org is set to
30 seconds, and that it measures only userspace CPU seconds. So, if
I have an Apache process that is taking 400 wall-clock seconds to
service a request, that would mean that a minimum of those 370
wall-clock seconds are being spent on things other than PHP
processing. Now then, that time could be spent servicing other
requests (and other requests *are* being handled during this time),
or blocking on I/O, or a number of other things, but it seems
clear to me that PmWiki is effectively "suspended" from doing
any processing, and it has to be something in PHP, the OS, or
Apache that is blocked up. (What's more, since PmWiki isn't in
control at that point, nor does it ever receive control again,
there's not much it can do about it.)
Here's an excerpt of a pmwiki.org server-status snapshot I've just taken
(some columns removed here to make it fit in 80 columns):
Srv PID Acc M CPU SS Req Conn Child
0-1 13624 0/1/63051 W 0.00 23 0 0.0 0.0000
1-1 23763 0/64/62822 _ 25.83 11 1664 0.0 1.50
2-1 23958 8/123/61190 K 78.95 6674 25 0.0 3.23
3-1 7729 0/10/62540 W 5.76 2 0 0.0 0.12
4-1 20844 0/90/60998 W 29.94 4 0 0.0 1.36
5-1 18123 0/78/60513 W 24.93 398 0 0.0 1.25
Each line represents an Apache process. The "M" column says what the
process is currently doing, _ == idle, R == reading request,
W == sending reply, K == keepalive, L == logging.
The "SS" column is the one I'm looking at -- it represents the
number of seconds (wall-clock) since the beginning of the most
recent request to that process. So, let's look at slot #5,
process ID #18123, which at the time was processing a request for
/wiki/PmWiki/ChangeLog . According to the server-status report,
it's taken 398 wall-clock seconds to process thus far ("SS" column),
and Apache is in the process of sending the reply ("W" in "M" column).
Thus far 0.0 bytes have been sent back to the browser ("Conn" column),
which means the poor browser has been waiting over six minutes for
the page results, assuming it's still there. Regardless of whether
the browser is actually there, Apache *thinks* it's still there
and is holding the process open, along with any memory, open files,
and locks that may be in use by the process.
I think we can all agree that it doesn't normally take six minutes
to process the PmWiki.ChangeLog page. :-)
A *very* interesting process in the snapshot above is slot #2,
process ID #23958 -- I have no clue what is happening there.
At the time of the snapshot, that process was servicing a
request for /wiki/Main/AllRecentChanges?action=rss , and had
apparently been doing so for 6674 seconds (yes, that's
over 110 minutes!). The process is in the "KeepAlive" state,
and pmwiki.org has its KeepAlive setting at 2 seconds, so the
request should've been closed long before this snapshot was taken.
Apache being in the KeepAlive state also means that PmWiki
finished successfully, so it's Apache that is "stuck".
What's more, I know that this particular request didn't take
much time to process, because pmwiki.org currently has "?action=rss"
on Main.AllRecentChanges set to immediately exit processing.
(There's someone with an RSS feed aggregator that is still looking
at the old location for the RSS feed.)
So, at the least there's something bizarre happening in Apache
or Apache/PHP that eats up resources and causes processing to take longer
More information about the pmwiki-users