[users@httpd] External module suspected to be slow - how to add timer around calls

[DENIS Laurent <La...@mail.mobistar.be>]

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 
exclusively for the person or entity to whom it is addressed and may 
contain confidential and/or privileged material. 
Any disclosure, copying, distribution or other action  based upon 
the information by persons or entities other than the intended recipient
is prohibited. If you receive this message in error, please contact the 
sender and delete the material from any and all computers. 
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

Re: [users@httpd] External module suspected to be slow - how to add timer around calls

[Rainer Jung <ra...@kippdata.de>]

On 25.01.2012 14:18, DENIS Laurent wrote:
> 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.

Since it is on Solaris, you could try to use Dtrace.

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

%T gives better resolution.

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

And it is not one connection per request?

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

mod_info could tell you about the hoks used by siteminder, so it could 
be possible to narrow down the cause with a custom module.

Regards,

Rainer

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