Recently I got high CPU usage with never-stopping Apache threads. Here is an htop line: PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+ Command 8354 wwwrun 20 0 918M 185M 121M R 66.7 4.7 1h19:19 44060 wwwrun 20 0 988M 198M 138M R 66.7 5.0 1h57:14 45572 wwwrun 20 0 919M 79572 12844 R 33.3 2.0 41h29:29 Command is: /usr/sbin/httpd2-prefork -f /etc/apache2/httpd.conf -DAWSTATS -DSSL -DICINGA -D SYSTEMD -DFOREGROUND -k start GDB backtrace of the last process gives me: #0 ap_core_output_filter (f=0x7fc7bf4f1690, new_bb=0x7fc7bf4f1928) at core_filters.c:512 #1 0x00007fc7ca37cf7d in ap_process_request_after_handler (r=0x7fc7bf4d50a0) at http_request.c:256 #2 0x00007fc7ca37dbf4 in ap_process_request (r=r@entry=0x7fc7bf4d50a0) at http_request.c:363 #3 0x00007fc7ca37a6a2 in ap_process_http_sync_connection (c=0x7fc7bf4f1290) at http_core.c:190 #4 ap_process_http_connection (c=0x7fc7bf4f1290) at http_core.c:231 #5 0x00007fc7ca371fa0 in ap_run_process_connection (c=0x7fc7bf4f1290) at connection.c:41 #6 0x00007fc7ca372388 in ap_process_connection (c=c@entry=0x7fc7bf4f1290, csd=<optimized out>) at connection.c:203 #7 0x00007fc7ca38572e in child_main (child_num_arg=child_num_arg@entry=7) at prefork.c:704 #8 0x00007fc7ca385962 in make_child (s=0x7fc7ca2db448, slot=7) at prefork.c:800 #9 0x00007fc7ca3865ae in perform_idle_server_maintenance (p=<optimized out>) at prefork.c:902 #10 prefork_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1090 #11 0x00007fc7ca34edde in ap_run_mpm (pconf=0x7fc7ca312028, plog=0x7fc7ca2d7028, s=0x7fc7ca2db448) at mpm_common.c:94 #12 0x00007fc7ca348476 in main (argc=11, argv=0x7fffc04e2b58) at main.c:777 Full backtrace: #0 ap_core_output_filter (f=0x7fc7bf4f1690, new_bb=0x7fc7bf4f1928) at core_filters.c:512 c = 0x7fc7bf4f1290 net = 0x7fc7bf4f1648 ctx = 0x7fc7bf4f1748 bb = 0x7fc7bf4f1928 bucket = <optimized out> next = 0x7fc7bf4e9048 flush_upto = 0x7fc7bf4e9048 bytes_in_brigade = 0 non_file_bytes_in_brigade = 0 eor_buckets_in_brigade = 4 morphing_bucket_in_brigade = 0 rv = <optimized out> #1 0x00007fc7ca37cf7d in ap_process_request_after_handler (r=0x7fc7bf4d50a0) at http_request.c:256 bb = 0x7fc7bf4f1928 b = <optimized out> c = 0x7fc7bf4f1290 #2 0x00007fc7ca37dbf4 in ap_process_request (r=r@entry=0x7fc7bf4d50a0) at http_request.c:363 bb = <optimized out> b = <optimized out> c = 0x7fc7bf4f1290 rv = <optimized out> #3 0x00007fc7ca37a6a2 in ap_process_http_sync_connection (c=0x7fc7bf4f1290) at http_core.c:190 r = 0x7fc7bf4d50a0 cs = 0x0 csd = 0x7fc7bf4f10a0 mpm_state = 1 #4 ap_process_http_connection (c=0x7fc7bf4f1290) at http_core.c:231 No locals. #5 0x00007fc7ca371fa0 in ap_run_process_connection (c=0x7fc7bf4f1290) at connection.c:41 pHook = 0x7fc7ca286720 n = 1 rv = -900044032 #6 0x00007fc7ca372388 in ap_process_connection (c=c@entry=0x7fc7bf4f1290, csd=<optimized out>) at connection.c:203 rc = <optimized out> #7 0x00007fc7ca38572e in child_main (child_num_arg=child_num_arg@entry=7) at prefork.c:704 current_conn = 0x7fc7bf4f1290 csd = 0x7fc7bf4f10a0 thd = 0x7fc7bf4f30a0 osthd = 140496067344256 ptrans = 0x7fc7bf4f1028 allocator = 0x7fc7cb242570 status = <optimized out> i = <optimized out> lr = <optimized out> pollset = 0x7fc7bf4f3180 sbh = 0x7fc7bf4f3178 bucket_alloc = 0x7fc7bf4ed028 last_poll_idx = 1 lockfile = <optimized out> #8 0x00007fc7ca385962 in make_child (s=0x7fc7ca2db448, slot=7) at prefork.c:800 pid = 0 #9 0x00007fc7ca3865ae in perform_idle_server_maintenance (p=<optimized out>) at prefork.c:902 i = <optimized out> idle_count = <optimized out> ws = <optimized out> free_length = <optimized out> free_slots = {7, 8, 16, 17, 21, 22, 23, 24, 33, 34, 35, 36, 37, 38, 39, 40, 0 <repeats 16 times>} last_non_dead = <optimized out> total_non_dead = <optimized out> #10 prefork_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1090 status = 11 pid = {pid = -1, in = 0x7fc7c9a525a0 <apr_pool_cleanup_null>, out = 0x0, err = 0x7fc7ca312028} child_slot = <optimized out> exitwhy = APR_PROC_SIGNAL processed_status = <optimized out> index = <optimized out> remaining_children_to_start = 0 rv = <optimized out> #11 0x00007fc7ca34edde in ap_run_mpm (pconf=0x7fc7ca312028, plog=0x7fc7ca2d7028, s=0x7fc7ca2db448) at mpm_common.c:94 pHook = 0x7fc7ca286848 n = 0 rv = -900044032 #12 0x00007fc7ca348476 in main (argc=11, argv=0x7fffc04e2b58) at main.c:777 c = 68 'D' showcompile = 0 showdirectives = 0 confname = 0x7fffc04e2eae "/etc/apache2/httpd.conf" def_server_root = 0x7fc7ca3877e3 "/srv/www" temp_error_log = 0x0 error = <optimized out> process = 0x7fc7ca314118 pconf = 0x7fc7ca312028 plog = 0x7fc7ca2d7028 ptemp = 0x7fc7ca2d9028 pcommands = 0x7fc7ca2e1028 opt = 0x7fc7ca2e1118 rv = <optimized out> mod = 0x7fc7ca5a8b18 <ap_prelinked_modules+56> opt_arg = 0x7fffc04e2eec "FOREGROUND" signal_server = <optimized out> After letting it run for 3 seconds I get the following: #0 ap_core_output_filter (f=0x7fc7bf4f1690, new_bb=0x7fc7bf4f1928) at core_filters.c:509 #1 0x00007fc7ca37cf7d in ap_process_request_after_handler (r=0x7fc7bf4d50a0) at http_request.c:256 #2 0x00007fc7ca37dbf4 in ap_process_request (r=r@entry=0x7fc7bf4d50a0) at http_request.c:363 #3 0x00007fc7ca37a6a2 in ap_process_http_sync_connection (c=0x7fc7bf4f1290) at http_core.c:190 #4 ap_process_http_connection (c=0x7fc7bf4f1290) at http_core.c:231 #5 0x00007fc7ca371fa0 in ap_run_process_connection (c=0x7fc7bf4f1290) at connection.c:41 #6 0x00007fc7ca372388 in ap_process_connection (c=c@entry=0x7fc7bf4f1290, csd=<optimized out>) at connection.c:203 #7 0x00007fc7ca38572e in child_main (child_num_arg=child_num_arg@entry=7) at prefork.c:704 #8 0x00007fc7ca385962 in make_child (s=0x7fc7ca2db448, slot=7) at prefork.c:800 #9 0x00007fc7ca3865ae in perform_idle_server_maintenance (p=<optimized out>) at prefork.c:902 #10 prefork_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1090 #11 0x00007fc7ca34edde in ap_run_mpm (pconf=0x7fc7ca312028, plog=0x7fc7ca2d7028, s=0x7fc7ca2db448) at mpm_common.c:94 #12 0x00007fc7ca348476 in main (argc=11, argv=0x7fffc04e2b58) at main.c:777 And the top function of the backtrace: #0 ap_core_output_filter (f=0x7fc7bf4f1690, new_bb=0x7fc7bf4f1928) at core_filters.c:509 c = 0x7fc7bf4f1290 net = 0x7fc7bf4f1648 ctx = 0x7fc7bf4f1748 bb = 0x7fc7bf4f1928 bucket = <optimized out> next = 0x7fc7bf4e9048 flush_upto = 0x7fc7bf4e9048 bytes_in_brigade = 0 non_file_bytes_in_brigade = 0 eor_buckets_in_brigade = 0 morphing_bucket_in_brigade = 0 rv = <optimized out> An other thread shows the same with a bit different top function call line: #0 0x00007fc7ca3640fa in ap_core_output_filter (f=0x7fc7bf4f1690, new_bb=0x7fc7bf4f1928) at core_filters.c:493 c = 0x7fc7bf4f1290 net = 0x7fc7bf4f1648 ctx = 0x7fc7bf4f1748 bb = 0x7fc7bf4f1928 bucket = <optimized out> next = 0x7fc7bf4e9048 flush_upto = 0x7fc7bf4e9048 bytes_in_brigade = 0 non_file_bytes_in_brigade = 0 eor_buckets_in_brigade = 1 morphing_bucket_in_brigade = 0 rv = <optimized out> There is no significant workload according to netstat -t: Active Internet connections (w/o servers) Proto Recv-Q Send-Q Local Address Foreign Address State tcp 0 0 server-name:www-http al121.albit.fastw:33532 TIME_WAIT tcp 1 0 server-name:www-http 5E1BB7D7.mobile.p:51177 CLOSE_WAIT tcp 0 0 server-name:www-http b110196.yse.yahoo:34908 TIME_WAIT After I restart the server, the workload is OK for some hours and it starts again.
(In reply to szotsaki from comment #0) [..] > > An other thread shows the same with a bit different top function call line: > #0 0x00007fc7ca3640fa in ap_core_output_filter (f=0x7fc7bf4f1690, > new_bb=0x7fc7bf4f1928) at core_filters.c:493 > c = 0x7fc7bf4f1290 > net = 0x7fc7bf4f1648 > ctx = 0x7fc7bf4f1748 > bb = 0x7fc7bf4f1928 > bucket = <optimized out> > next = 0x7fc7bf4e9048 > flush_upto = 0x7fc7bf4e9048 > bytes_in_brigade = 0 > non_file_bytes_in_brigade = 0 > eor_buckets_in_brigade = 1 > morphing_bucket_in_brigade = 0 > rv = <optimized out> Two threads using simultaneously the addresses, really? BTW, next and flush_upto shouldn't hold the same value on a single thread either, that points an infinite loop. Which linux distribution is it? Which compiler (version) was used to build httpd and mainly the lib APR? Which options (CFLAGS) if that's available somewhere (dev package)? Can you disassemble the loop starting at line 489? It looks like APR rings do not play well here.
(In reply to Yann Ylavic from comment #1) > Two threads using simultaneously the addresses, really? Hmm, two processes, that's prefork, makes sense...
It is an openSUSE 13.2 For libapr1 (1.5.1) you can see the applied patches here: https://build.opensuse.org/package/show?project=openSUSE%3A13.2&package=libapr1 If I'm not mistaken, the compiler was GCC 4.8, but the .comment section is unfortunately stripped from /usr/lib64/libapr-1.so. The make process: make %{?_smp_mflags} CFLAGS="%{optflags} -fvisibility=hidden -fPIC" rpm -E %{optflags}: -O2 -g -m64 -fmessage-length=0 -D_FORTIFY_SOURCE=2 -fstack-protector -funwind-tables -fasynchronous-unwind-tables Here is the specfile: https://build.opensuse.org/package/view_file/openSUSE:13.2/libapr1/libapr1.spec The disassembly for core_filters.c 489-539: info line core_filters.c:489 Line 489 of "core_filters.c" starts at address 0x7f283286b0c7 <ap_core_output_filter+231> and ends at 0x7f283286b0cb <ap_core_output_filter+235>. info line core_filters.c:539 Line 539 of "core_filters.c" is at address 0x7f283286b222 <ap_core_output_filter+578> but contains no code. Dump of assembler code from 0x7f283286b0c7 to 0x7f283286b222: 0x00007f283286b0c7 <ap_core_output_filter+231>: mov 0x8(%rbx),%rdx 0x00007f283286b0cb <ap_core_output_filter+235>: xor %ecx,%ecx 0x00007f283286b0cd <ap_core_output_filter+237>: xor %edi,%edi 0x00007f283286b0cf <ap_core_output_filter+239>: xor %r13d,%r13d 0x00007f283286b0d2 <ap_core_output_filter+242>: xor %esi,%esi 0x00007f283286b0d4 <ap_core_output_filter+244>: lea 0x2932c(%rip),%r12 # 0x7f2832894407 0x00007f283286b0db <ap_core_output_filter+251>: mov %rcx,%r8 0x00007f283286b0de <ap_core_output_filter+254>: cmp %r15,%rdx 0x00007f283286b0e1 <ap_core_output_filter+257>: je 0x7f283286b222 <ap_core_output_filter+578> 0x00007f283286b0e7 <ap_core_output_filter+263>: nopw 0x0(%rax,%rax,1) 0x00007f283286b0f0 <ap_core_output_filter+272>: mov 0x10(%rdx),%rax 0x00007f283286b0f4 <ap_core_output_filter+276>: mov (%rdx),%r14 0x00007f283286b0f7 <ap_core_output_filter+279>: mov 0xc(%rax),%ecx 0x00007f283286b0fa <ap_core_output_filter+282>: test %ecx,%ecx 0x00007f283286b0fc <ap_core_output_filter+284>: jne 0x7f283286b3a0 <ap_core_output_filter+960> 0x00007f283286b102 <ap_core_output_filter+290>: mov 0x18(%rdx),%rdx 0x00007f283286b106 <ap_core_output_filter+294>: mov $0x1,%r9d 0x00007f283286b10c <ap_core_output_filter+300>: cmp $0xffffffffffffffff,%rdx 0x00007f283286b110 <ap_core_output_filter+304>: je 0x7f283286b128 <ap_core_output_filter+328> 0x00007f283286b112 <ap_core_output_filter+306>: add %rdx,%r13 0x00007f283286b115 <ap_core_output_filter+309>: cmp 0x242e8c(%rip),%rax # 0x7f2832aadfa8 0x00007f283286b11c <ap_core_output_filter+316>: je 0x7f283286b540 <ap_core_output_filter+1376> 0x00007f283286b122 <ap_core_output_filter+322>: add %rdx,%r8 0x00007f283286b125 <ap_core_output_filter+325>: xor %r9b,%r9b 0x00007f283286b128 <ap_core_output_filter+328>: mov 0x242ea1(%rip),%rdx # 0x7f2832aadfd0 0x00007f283286b12f <ap_core_output_filter+335>: cmp %rdx,%rax 0x00007f283286b132 <ap_core_output_filter+338>: je 0x7f283286b14b <ap_core_output_filter+363> 0x00007f283286b134 <ap_core_output_filter+340>: cmp $0xffff,%r8 0x00007f283286b13b <ap_core_output_filter+347>: ja 0x7f283286b14b <ap_core_output_filter+363> 0x00007f283286b13d <ap_core_output_filter+349>: test %r9d,%r9d 0x00007f283286b140 <ap_core_output_filter+352>: jne 0x7f283286b14b <ap_core_output_filter+363> 0x00007f283286b142 <ap_core_output_filter+354>: cmp $0x5,%edi 0x00007f283286b145 <ap_core_output_filter+357>: jle 0x7f283286b216 <ap_core_output_filter+566> 0x00007f283286b14b <ap_core_output_filter+363>: mov 0xa8(%rbp),%rcx 0x00007f283286b152 <ap_core_output_filter+370>: test %rcx,%rcx 0x00007f283286b155 <ap_core_output_filter+373>: je 0x7f283286b400 <ap_core_output_filter+1056> 0x00007f283286b15b <ap_core_output_filter+379>: mov (%rcx),%rsi 0x00007f283286b15e <ap_core_output_filter+382>: test %rsi,%rsi 0x00007f283286b161 <ap_core_output_filter+385>: je 0x7f283286b3c0 <ap_core_output_filter+992> 0x00007f283286b167 <ap_core_output_filter+391>: movzbl (%rsi),%esi 0x00007f283286b16a <ap_core_output_filter+394>: test %sil,%sil 0x00007f283286b16d <ap_core_output_filter+397>: js 0x7f283286b3c0 <ap_core_output_filter+992> 0x00007f283286b173 <ap_core_output_filter+403>: cmp $0xc,%sil 0x00007f283286b177 <ap_core_output_filter+407>: setg %sil 0x00007f283286b17b <ap_core_output_filter+411>: test %sil,%sil 0x00007f283286b17e <ap_core_output_filter+414>: je 0x7f283286b388 <ap_core_output_filter+936> 0x00007f283286b184 <ap_core_output_filter+420>: cmp %rdx,%rax 0x00007f283286b187 <ap_core_output_filter+423>: lea 0x29253(%rip),%rsi # 0x7f28328943e1 0x00007f283286b18e <ap_core_output_filter+430>: je 0x7f283286b1ae <ap_core_output_filter+462> 0x00007f283286b190 <ap_core_output_filter+432>: cmp $0xffff,%r8 0x00007f283286b197 <ap_core_output_filter+439>: lea 0x2922e(%rip),%rsi # 0x7f28328943cc 0x00007f283286b19e <ap_core_output_filter+446>: ja 0x7f283286b1ae <ap_core_output_filter+462> 0x00007f283286b1a0 <ap_core_output_filter+448>: lea 0x29247(%rip),%rsi # 0x7f28328943ee 0x00007f283286b1a7 <ap_core_output_filter+455>: test %r9d,%r9d 0x00007f283286b1aa <ap_core_output_filter+458>: cmovne %r12,%rsi 0x00007f283286b1ae <ap_core_output_filter+462>: test %rcx,%rcx 0x00007f283286b1b1 <ap_core_output_filter+465>: je 0x7f283286b3d0 <ap_core_output_filter+1008> 0x00007f283286b1b7 <ap_core_output_filter+471>: mov (%rcx),%rax 0x00007f283286b1ba <ap_core_output_filter+474>: test %rax,%rax 0x00007f283286b1bd <ap_core_output_filter+477>: je 0x7f283286b3f0 <ap_core_output_filter+1040> 0x00007f283286b1c3 <ap_core_output_filter+483>: movzbl (%rax),%eax 0x00007f283286b1c6 <ap_core_output_filter+486>: test %al,%al 0x00007f283286b1c8 <ap_core_output_filter+488>: js 0x7f283286b3f0 <ap_core_output_filter+1040> 0x00007f283286b1ce <ap_core_output_filter+494>: cmp $0xc,%al 0x00007f283286b1d0 <ap_core_output_filter+496>: setg %al 0x00007f283286b1d3 <ap_core_output_filter+499>: test %al,%al 0x00007f283286b1d5 <ap_core_output_filter+501>: je 0x7f283286b388 <ap_core_output_filter+936> 0x00007f283286b1db <ap_core_output_filter+507>: lea 0x292ae(%rip),%rax # 0x7f2832894490 0x00007f283286b1e2 <ap_core_output_filter+514>: lea 0x291c5(%rip),%rdi # 0x7f28328943ae 0x00007f283286b1e9 <ap_core_output_filter+521>: mov %rsi,0x8(%rsp) 0x00007f283286b1ee <ap_core_output_filter+526>: xor %r8d,%r8d 0x00007f283286b1f1 <ap_core_output_filter+529>: mov $0x20f,%esi 0x00007f283286b1f6 <ap_core_output_filter+534>: mov %rbp,%r9 0x00007f283286b1f9 <ap_core_output_filter+537>: mov %rax,(%rsp) 0x00007f283286b1fd <ap_core_output_filter+541>: mov $0xd,%ecx 0x00007f283286b202 <ap_core_output_filter+546>: xor %edx,%edx 0x00007f283286b204 <ap_core_output_filter+548>: xor %eax,%eax 0x00007f283286b206 <ap_core_output_filter+550>: xor %r13d,%r13d 0x00007f283286b209 <ap_core_output_filter+553>: callq 0x7f2832876120 <ap_log_cerror_> 0x00007f283286b20e <ap_core_output_filter+558>: mov %r14,%rsi 0x00007f283286b211 <ap_core_output_filter+561>: xor %edi,%edi 0x00007f283286b213 <ap_core_output_filter+563>: xor %r8d,%r8d 0x00007f283286b216 <ap_core_output_filter+566>: mov %r14,%rdx 0x00007f283286b219 <ap_core_output_filter+569>: cmp %r15,%rdx 0x00007f283286b21c <ap_core_output_filter+572>: jne 0x7f283286b0f0 <ap_core_output_filter+272> End of assembler dump. Here is with the /m switch: http://paste.opensuse.org/40629341 (without syntax highlight: http://paste.opensuse.org/view/simple/40629341)