Bug 52914 - On keep-alive on, after some time huge process load
Summary: On keep-alive on, after some time huge process load
Status: RESOLVED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_dumpio (show other bugs)
Version: 2.5-HEAD
Hardware: PC All
: P2 critical (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords: FixedInTrunk
Depends on:
Blocks:
 
Reported: 2012-03-15 08:28 UTC by Azat Khuzhin
Modified: 2012-05-06 07:27 UTC (History)
1 user (show)



Attachments
patch (1.06 KB, patch)
2012-03-15 08:28 UTC, Azat Khuzhin
Details | Diff
don't clobber input filter return value in mod_dump_io (410 bytes, patch)
2012-03-15 17:24 UTC, Stefan Fritsch
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Azat Khuzhin 2012-03-15 08:28:15 UTC
Created attachment 28470 [details]
patch

System:
Linux 3.0.0-1-amd64 #1 SMP Sat Aug 27 16:21:11 UTC 2011 x86_64 GNU/Linux
Apache version
Server version: Apache/2.2.22 (Debian)

But I sure that at 2.4.1 the same issue

After turning set next options:
KeepAlive On
MaxKeepAliveRequests 5
KeepAliveTimeout 1

After some time (at last iteration about 2 minutes) some of apache workers eat 60-100% CPU, while must 0-2% CPU (without keep-alive - so)

Gdb:
(gdb) bt
#0  0x00007f61b5bb0cad in apr_table_setn () from /usr/lib/libapr-1.so.0
#1  0x00007f61af75eaca in reqtimeout_filter (f=0x7f61b6275b40, bb=0x7f61b6266170, mode=<optimized out>, block=<optimized out>, readbytes=<optimized out>) at mod_reqtimeout.c:309
#2  0x00007f61b3146322 in dumpio_input_filter (f=0x7f61b6275a68, bb=0x7f61b6266170, mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=6440) at mod_dumpio.c:120
#3  0x00007f61b64b0161 in ap_http_filter (f=0x7f61b6263b10, b=0x7f61b6266170, mode=AP_MODE_READBYTES, block=<optimized out>, readbytes=6440) at http_filters.c:525
#4  0x00007f61b64b1914 in ap_discard_request_body (r=0x7f61b6261758) at http_filters.c:1366
#5  0x00007f61b6491349 in ap_finalize_request_protocol (r=0x7f61b6261758) at protocol.c:1168
#6  0x00007f61af552a05 in handler_redirect (r=0x7f61b62620a0) at mod_rewrite.c:4860
#7  0x00007f61b649f668 in ap_run_handler (r=0x7f61b62620a0) at config.c:159
#8  0x00007f61b649fade in ap_invoke_handler (r=0x7f61b62620a0) at config.c:377
#9  0x00007f61b64af6b0 in ap_process_request (r=0x7f61b62620a0) at http_request.c:282
#10 0x00007f61b64ac4f8 in ap_process_http_connection (c=0x7f61b6275290) at http_core.c:190
#11 0x00007f61b64a60e8 in ap_run_process_connection (c=0x7f61b6275290) at connection.c:43
#12 0x00007f61b64b42c0 in child_main (child_num_arg=<optimized out>) at prefork.c:667
#13 0x00007f61b64b4a2a in make_child (slot=6, s=0x7f61b64407f8) at prefork.c:768
#14 make_child (s=0x7f61b64407f8, slot=6) at prefork.c:696
#15 0x00007f61b64b55df in perform_idle_server_maintenance (p=<optimized out>) at prefork.c:903
#16 ap_mpm_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1107
#17 0x00007f61b648a6a4 in main (argc=3, argv=0x7fff67bcc5e8) at main.c:755
(gdb) quit
A debugging session is active.

        Inferior 1 [process 11587] will be detached.

Quit anyway? (y or n) EOF [assumed Y]
Detaching from program: /usr/lib/apache2/mpm-prefork/apache2, process 11587
root@:/work1/azat/apache_high_percents/cores# ps u 11587
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
www-data 11587 59.0  0.0 381148 14968 ?        R    14:33   0:42 /usr/sbin/apache2 -k start
root@:/work1/azat/apache_high_percents/cores# ps u 11587
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
www-data 11587 60.0  0.0 381148 14968 ?        R    14:33   0:45 /usr/sbin/apache2 -k start
root@:/work1/azat/apache_high_percents/cores# ps u 11587
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
www-data 11587 60.4  0.0 381148 14968 ?        R    14:33   0:45 /usr/sbin/apache2 -k start
root@:/work1/azat/apache_high_percents/cores# ps u 11587
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
www-data 11587 61.5  0.0 381148 14968 ?        R    14:33   0:46 /usr/sbin/apache2 -k start
 
(gdb) bt
#0  0x00007f61b64a980c in ap_get_brigade (next=0x7f61b6263b10, bb=0x7f61b6266170, mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192) at util_filter.c:489
#1  0x00007f61b64b1914 in ap_discard_request_body (r=0x7f61b6261758) at http_filters.c:1366
#2  0x00007f61b6491349 in ap_finalize_request_protocol (r=0x7f61b6261758) at protocol.c:1168
#3  0x00007f61af552a05 in handler_redirect (r=0x7f61b62620a0) at mod_rewrite.c:4860
#4  0x00007f61b649f668 in ap_run_handler (r=0x7f61b62620a0) at config.c:159
#5  0x00007f61b649fade in ap_invoke_handler (r=0x7f61b62620a0) at config.c:377
#6  0x00007f61b64af6b0 in ap_process_request (r=0x7f61b62620a0) at http_request.c:282
#7  0x00007f61b64ac4f8 in ap_process_http_connection (c=0x7f61b6275290) at http_core.c:190
#8  0x00007f61b64a60e8 in ap_run_process_connection (c=0x7f61b6275290) at connection.c:43
#9  0x00007f61b64b42c0 in child_main (child_num_arg=<optimized out>) at prefork.c:667
#10 0x00007f61b64b4a2a in make_child (slot=6, s=0x7f61b64407f8) at prefork.c:768
#11 make_child (s=0x7f61b64407f8, slot=6) at prefork.c:696
#12 0x00007f61b64b55df in perform_idle_server_maintenance (p=<optimized out>) at prefork.c:903
#13 ap_mpm_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1107
#14 0x00007f61b648a6a4 in main (argc=3, argv=0x7fff67bcc5e8) at main.c:755
(gdb) quit
A debugging session is active.

        Inferior 1 [process 11587] will be detached.

Quit anyway? (y or n) EOF [assumed Y]
Detaching from program: /usr/lib/apache2/mpm-prefork/apache2, process 11587
root@:/work1/azat/apache_high_percents/cores# ps u 11587
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
www-data 11587 71.9  0.0 381148 14968 ?        R    14:33   2:11 /usr/sbin/apache2 -k start

Server-status
Srv PID Acc M CPU SS Req Conn Child Slot Client VHost Request
6-0 11587 0/2/17 W 0.03 194 0 0.0 0.00 0.00 {CLIENT_IP} {SERVER_HOST} POST {URL} HTTP/1.1

While here CPU = 0.03

I also think that my patch can fix this problem
There I write verbose comment
Comment 1 Stefan Fritsch 2012-03-15 17:24:08 UTC
Created attachment 28474 [details]
don't clobber input filter return value in mod_dump_io

I don't think your patch is correct. Can you try if my patch helps, too?
Comment 2 Stefan Fritsch 2012-03-15 17:39:42 UTC
(In reply to comment #1)
> Created attachment 28474 [details]
> don't clobber input filter return value in mod_dump_io
> 
> I don't think your patch is correct. Can you try if my patch helps, too?

FWIW, this would mean that not loading mod_dump_io should also fix the issue.
Comment 3 Stefan Fritsch 2012-03-16 18:54:06 UTC
I could reproduce the 100% CPU with POST requests if mod_reqtimeout is enabled for bodies and DumpIOInput is on. This is fixed by my patch

Trunk: r1301111
2.4: r1301686
proposed for 2.2
Comment 4 Azat Khuzhin 2012-03-19 08:22:50 UTC
Thanks, I'll see you commit, and seems that it can fix my problem.
I'll try later, and comment here about what I have
Comment 5 Azat Khuzhin 2012-03-19 13:30:43 UTC
(In reply to comment #3)
> I could reproduce the 100% CPU with POST requests if mod_reqtimeout is enabled
> for bodies and DumpIOInput is on. This is fixed by my patch
> 
> Trunk: r1301111
> 2.4: r1301686
> proposed for 2.2

I try reproduce this bug, on another machine
On both are debian, same version
Apache, have the same version (2.2.22)

But this bug, not reproduced (DumpIOInput on, mod_reqtimeout enabled, keepalive on)
Trying using siege

Can you write here how you reproduce this bug?
Thanks.
Comment 6 Stefan Fritsch 2012-03-19 19:53:17 UTC
(In reply to comment #5)
> Can you write here how you reproduce this bug?
> Thanks.

I did a POST request with a Content-Length header, sent part (but not all) of the request body, and then waited for mod_reqtimeout's body timeout to kick in. Then the child would loop with 100% CPU.

Do you know if you had DumpIOInput enabled when you reported this issue? If you are sure that you didn't have it enabled, you probably have hit a different issue.
Comment 7 Stefan Fritsch 2012-03-19 20:02:11 UTC
(In reply to comment #6)
> Do you know if you had DumpIOInput enabled when you reported this issue? If you
> are sure that you didn't have it enabled, you probably have hit a different
> issue.

Ignore that, that was a stupid question. Your stack trace shows that you had DumpIOInput enabled.
Comment 8 Azat Khuzhin 2012-03-20 09:56:11 UTC
(In reply to comment #6)
> (In reply to comment #5)
> > Can you write here how you reproduce this bug?
> > Thanks.
> 
> I did a POST request with a Content-Length header, sent part (but not all) of
> the request body, and then waited for mod_reqtimeout's body timeout to kick in.
> Then the child would loop with 100% CPU.
> 
> Do you know if you had DumpIOInput enabled when you reported this issue? If you
> are sure that you didn't have it enabled, you probably have hit a different
> issue.

Thanks.
You patch fix problem with huge process load, for me.
Comment 9 Stefan Fritsch 2012-05-06 07:27:59 UTC
The fix is in 2.4.2 and proposed for 2.2.x