Mailing-List: contact users-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: users@httpd.apache.org
Received-SPF: unknown (athena.apache.org: error in processing during lookup of
 Laurent.DENIS@mail.mobistar.be)
Content-class: urn:content-classes:message
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable
Date: Wed, 25 Jan 2012 14:18:32 +0100
Message-ID: 
 <FF13B04E2FF6D444A6FF20652E31036706E44E89@oceanus.mobilebelgium.be>
Thread-Topic: External module suspected to be slow - how to add timer around
    calls
Thread-Index: AczbYKfDOhK1hafiSXutmpC+HGL/Kg==
From: "DENIS Laurent" <Laurent.DENIS@mail.mobistar.be>
To: <users@httpd.apache.org>
Subject: [users@httpd] External module suspected to be slow - how to add timer
 around calls

Hello,


*** Question ***
How can I measure how much time is spent in the processing function of
module?

Of course, the supplier of the module does not provide any source code.

My idea is to add an APRLOG_DEBUG the "apr_time_now" before and after
the function is called (don't know yet which hook it's registered to,
guess I'll have to add debug around all hooks).
But I haven't found in which source code file the function is called.

Even the faintest hint would greatly help me.


*** Context ***
On a Sparc T5120 server with (1 CPUs, 64vCPU, 64GB memory), running
Solaris 10 + apache 2.2.21 worker / 2.2.17 prefork, I have
"intermittent" slow responses.
The server is not overloaded (5% CPU, 50GB free memory, 5MB/second on
network link).

The problem occurs for around 0.5% of the request (ran thousands of
request) - even for very simple pages like an index.html of 20 bytes on
non-SSL server.

The delay occurs between the moment the moment the request is received
and the moment the first byte of the header is sent to the client
(verified with tcpdump on server + perl script with IO::Socket to have a
better idea that with a wget).

The time shown by the logs (%D) is way above the second (sometimes up to
120 seconds where the average time is 4ms).

The server is under moderate load: 200 requests / second and have a very
complex configuration (lots of forwards, rewrite, aliases, vhosts,
etc...)

There's an external module loaded for CA Siteminder that performs
authentication. I suspect this one to be guilty for the delay, maybe by
its communication with the policy server.
I cannot isolate the traffic to the policy server for one request, the
channel is cyphered and used for all the requests.
No "timing" log option available in this module as far as I can find.
On a lightly loaded server, the delay does not appear, so I need to test
on the production server.


Laurent

*****DISCLAIMER*****

This electronic transmission (and any attached document) is intended=20
exclusively for the person or entity to whom it is addressed and may=20
contain confidential and/or privileged material.=20
Any disclosure, copying, distribution or other action  based upon=20
the information by persons or entities other than the intended recipient
is prohibited. If you receive this message in error, please contact the=20
sender and delete the material from any and all computers.=20
Mobistar does not warrant a proper and complete transmission of this
information, nor does it accept liability for any delays.

*****END OF DISCLAIMER*****

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