Bug 57800

Summary: High CPU usage in ap_core_output_filter
Product: Apache httpd-2 Reporter: szotsaki
Component: CoreAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: NEW ---    
Severity: normal CC: ylavic.dev
Priority: P2    
Version: 2.4.10   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description szotsaki 2015-04-09 07:45:36 UTC
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.
Comment 1 Yann Ylavic 2015-04-10 21:51:58 UTC
(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.
Comment 2 Yann Ylavic 2015-04-10 22:05:09 UTC
(In reply to Yann Ylavic from comment #1)
> Two threads using simultaneously the addresses, really?
Hmm, two processes, that's prefork, makes sense...
Comment 3 szotsaki 2015-04-14 08:12:58 UTC
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)