You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2009/01/30 14:55:57 UTC

DO NOT REPLY [Bug 46634] New: Requests sometimes take too long, wrong time taken reported in logs

https://issues.apache.org/bugzilla/show_bug.cgi?id=46634

           Summary: Requests sometimes take too long, wrong time taken
                    reported in logs
           Product: Apache httpd-2
           Version: 2.2.3
          Platform: PC
        OS/Version: Linux
            Status: NEW
          Severity: critical
          Priority: P2
         Component: Core
        AssignedTo: bugs@httpd.apache.org
        ReportedBy: m-b@nurfuerspam.de


Created an attachment (id=23199)
 --> (https://issues.apache.org/bugzilla/attachment.cgi?id=23199)
screendump.jpg

Our Apache servers, each processing some 7 million requests a day, sometimes
take way to long to send a response (1500000ns as compared to the normal
500ns). This happens with content stored on the local disk and under different
load conditions all day round and can be observed in the server access logs as
well as on the client side.

Using tcpdump we've tracked the problem down to the following:
1) server receives request A (for tab1_active.gif) and sends response
immediately
2) server receives request B (for btn_pfeil.gif) on the same connection (using
keep-alive), waits some 2 seconds after accepting the GET and then sends out
response for B
3) however in the logfiles, the time taken for request A ist given as over 2
seconds whereas request B is logged as processed in 200ns.

This looks like for some reason Apache suffers from some delay between
receiving a request and sending out the response, but before(!) calculating the
time taken for the previous request. The problem was tracked down on 2.2.3 but
also occures on 2.2.10.

So there are two sub-problems:
A) the time taken in the log files does not match the real time taken
B) it shouldn't take that long to deliver a small file at all

Attached you'll find a screenshot of the tcpdump, the corresponding log entries
as well as the configuration of the system Apache is running on.

Any help is greatly appreciated as this problem severely affects the
performance of the whole website.


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #9 from mb <m-...@nurfuerspam.de>  2009-02-04 02:14:12 PST ---
Hmmm... That doesn't sound very feasible to me, 'cause it would require us
stopping httpd in exactly that moment when any of the hundred parallel requests
hangs for a second or two. However, neither do we know beforehand, when that
will happen nor do we know which request is affected until it is logged. Even
if we tracked it down with wireshark in parallel, it would not be possible to
analyze the data that fast and stop httpd.

Of course, if there is any way to achieve this, we'll try. Any help to
accomplish this task is appreciated.

Another option would be some investigation in the sources. The problem seems to
occur somewhere after the last byte of the previous response is sent, the next
pipelined request is accepted on the connection, but before the log is written
for the first response.


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #1 from mb <m-...@nurfuerspam.de>  2009-01-30 05:56:23 PST ---
Created an attachment (id=23200)
 --> (https://issues.apache.org/bugzilla/attachment.cgi?id=23200)
apache_access.log


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #7 from mb <m-...@nurfuerspam.de>  2009-02-03 09:57:56 PST ---
I've forgot to mention: For the debugging session, we've used the 2.2.10
version of the server.


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634


mb <m-...@nurfuerspam.de> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Priority|P2                          |P3
           Severity|critical                    |normal




--- Comment #14 from mb <m-...@nurfuerspam.de>  2009-02-25 06:50:22 PST ---
Finally, we found the reason for the delay. After switching off logging file
access time in ext3, the values went back to normal. Access time with ext2
seems fine however. So I've lowered the priority of the bug. What remains, is
that the long request is logged for the request _before_ such a delay in a
connection with keep alive, not for the one that is actually slow.

-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #12 from mb <m-...@nurfuerspam.de>  2009-02-20 09:17:20 PST ---
It's getting really weird now. The situation is as follows:

1. The line "rv = apr_bucket_read(e, &str, &n, eblock);" in
ap_core_output_filter (core_filters.c) takes more than a second (1000000µs) to
complete
2. When that happens, the return value of apr_bucket_read is 0 (APR_SUCCESS).
3. After apr_bucket_read returns, the value of e->type->name is always "MMAP".
4. After apr_bucket_read returns, the value of e->type->read is always the
address of mmap_bucket_read (apr_buckets_mmap.c).
5. mmap_bucket_read records time on entry and just before "return APR_SUCCESS"
with apr_time_now().
6. A difference of more than 300000µs is _never_ recorded in that function.

So it looks like, calling apr_bucket_read takes over a second, but the called
function never takes more than a third of a second between first and last
statement.

Is it possible, that a completely different function is called, i.e. the value
of e->type->read changes due to the call? Could it really take so long to
evaluate e->type->read in the macro apr_bucket_read and do some basic logic of
a function call?

-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #13 from mb <m-...@nurfuerspam.de>  2009-02-24 10:05:49 PST ---
Ok, call to "read" DOES seem to replace bucket received as a parameter. With
that in mind, we were able to trace it down to the system call "mmap" called by
a file bucket. However, the problem still persists with "EnableMMAP Off", so
it's somewhere in basic file I/O. We'll keep on looking what could be the
reason for that. To some degree, it seems to depend on the compiler version
used to build Apache and the kernel.

-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634


Ruediger Pluem <rp...@apache.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |NEEDINFO




--- Comment #3 from Ruediger Pluem <rp...@apache.org>  2009-01-30 07:08:19 PST ---
Can you please provide a stacktrace of the httpd process that is stuck for 2
seconds?


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #2 from mb <m-...@nurfuerspam.de>  2009-01-30 05:56:46 PST ---
Created an attachment (id=23201)
 --> (https://issues.apache.org/bugzilla/attachment.cgi?id=23201)
systeminfo.txt


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634

--- Comment #15 from MortenK <mo...@kallesoee.dk> ---
Hi

I am also seeing apache loggin wrong time to serve reqeust in the log.

My TCPdump shows that the reqeust took 51 seconds, but my apache log reports
"14282" microseconds.

In other cases where it takes along time, its spot on, but in some cases its
wrong.
I am not sure how to procede with this finding.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634


mb <m-...@nurfuerspam.de> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEEDINFO                    |ASSIGNED




--- Comment #6 from mb <m-...@nurfuerspam.de>  2009-02-03 09:47:26 PST ---
In the attachment stacktraces.txt you'll find two stacktraces of requests that
were logged as being unusually slow. 

To be able to use conditional breakpoints, we had to make some changes to
mod_log_config.so though:
1) Patched mod_log_config.c:log_request_duration_microseconds to store value in
local variable (as shown in attachment)
2) Changed some compiler options: removed "-O2", added "-g -g3 -ggdb"


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #4 from mb <m-...@nurfuerspam.de>  2009-01-30 09:01:31 PST ---
Ok, we'll see what is possible. Probably need to recompile the server and roll
it out. However that'll take some days. Or is there any other easy way to
capture the dump in exactly that moment?


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #5 from mb <m-...@nurfuerspam.de>  2009-02-03 09:47:00 PST ---
Created an attachment (id=23222)
 --> (https://issues.apache.org/bugzilla/attachment.cgi?id=23222)
stacktraces.txt


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #11 from Jeff Trawick <tr...@apache.org>  2009-02-20 07:16:32 PST ---
Interesting; I don't see any touching of the memory page with the mmap-ed file
either.

It can block for disk I/O at the point where the memory address returned by the
bucket-read is dereferenced a bit later; I don't grok a block at an earlier
point, unless this heap storage representing the mmap is getting paged out.

Help ;)

-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #8 from Ruediger Pluem <rp...@apache.org>  2009-02-03 23:59:50 PST ---
Sorry but the stacktrace doesn't really help as you set a breakpoint in the
logging section. What we need is that once httpd gets stuck you start your
debugging session (which stops httpd) and we see where it is stuck.


-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


DO NOT REPLY [Bug 46634] Requests sometimes take too long, wrong time taken reported in logs

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=46634





--- Comment #10 from mb <m-...@nurfuerspam.de>  2009-02-20 05:51:57 PST ---
There are some news: With some debugging and call tracing we've found the place
where it hangs. It is mmap_bucket_read in
srclib/apr-util/buckets/apr_buckets_mmap.c called from
server/ap_core_output_filter in core_filters.c.

The strange thing is: This function as well as apr_mmap_offset in
srclib/apr/mmap/unix/common.c only does some pointer shuffeling but sometimes
takes over a second to complete.

-- 
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org