mod_gnutls busy-loops consuming 100% cpu

Bug #1381417 reported by Simon Josefsson
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
mod-gnutls (Ubuntu)
New
Undecided
Unassigned

Bug Description

 We've used libapache2-mod-gnutls on Ubuntu 12.04 but after re-install with Ubuntu 14.04 we noticed that apache is consuming 100% cpu due to mod_gnutls. This is on an Internet-visible machine with moderate traffic, and it happens after a couple of days or so. We've seen the problem on two different freshly installed Ubuntu 14.04 machines. Apache still works, but the stuck process consumes CPU.

Sorry for lack of more useful information such as gdb backtraces, I wanted to open the bug first so further data points can be added it to, and for others to chime in.

/Simon

Revision history for this message
Simon Josefsson (simon-josefsson) wrote :
Download full text (43.3 KiB)

It happened again so I collected some information about it.

top - 06:41:08 up 7 days, 23:05, 1 user, load average: 6.87, 6.31, 6.22
Tasks: 129 total, 1 running, 128 sleeping, 0 stopped, 0 zombie
%Cpu(s): 64.8 us, 0.0 sy, 0.0 ni, 23.9 id, 0.0 wa, 0.0 hi, 0.0 si, 11.3 st
KiB Mem: 1012108 total, 970104 used, 42004 free, 26140 buffers
KiB Swap: 262140 total, 7480 used, 254660 free. 660712 cached Mem

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 7046 www-data 20 0 2041404 29832 5604 S 200.1 2.9 1036:38 /usr/sbin/apache2 -k start
 7230 www-data 20 0 2040752 31604 4932 S 200.1 3.1 3767:03 /usr/sbin/apache2 -k start
17441 www-data 20 0 2036472 20124 4828 S 100.0 2.0 2532:40 /usr/sbin/apache2 -k start
22281 www-data 20 0 2032484 16444 5432 S 100.0 1.6 1067:03 /usr/sbin/apache2 -k start
 5493 root 20 0 24980 3020 2516 R 1.0 0.3 0:00.28 top
    7 root 20 0 0 0 0 S 0.3 0.0 37:09.72 [rcu_sched]
  734 root 20 0 0 0 0 S 0.3 0.0 0:00.14 [kworker/u16:0]
...

Stracing them does not suggest anything:

root@developers:~# strace -p 7046
Process 7046 attached
read(14, ^CProcess 7046 detached
 <detached ...>
root@developers:~# strace -p 7230
Process 7230 attached
futex(0x7f70fa7ec9d0, FUTEX_WAIT, 7257, NULL^CProcess 7230 detached
 <detached ...>
root@developers:~# strace -p 17441
Process 17441 attached
futex(0x7f70fa7ec9d0, FUTEX_WAIT, 17468, NULL^CProcess 17441 detached
 <detached ...>
root@developers:~# strace -p 22281
Process 22281 attached
futex(0x7f70fa7ec9d0, FUTEX_WAIT, 22334, NULL^CProcess 22281 detached
 <detached ...>

I waited 5-10 seconds before doing ^C.

root@developers:~# gdb /usr/sbin/apache2 7046
GNU gdb (Ubuntu 7.7-0ubuntu3.1) 7.7
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/apache2...Reading symbols from /usr/lib/debug//usr/sbin/apache2...done.
done.
Attaching to program: /usr/sbin/apache2, process 7046
Reading symbols from /lib/x86_64-linux-gnu/libpcre.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib/x86_64-linux-gnu/libpcre.so.3
Reading symbols from /usr/lib...

Revision history for this message
Simon Josefsson (simon-josefsson) wrote :
Download full text (9.1 KiB)

Strace -ff shows a bit more. It is stuck in the epoll/gettimeofday loop.

root@developers:~# strace -ff -p 7046
Process 7046 attached with 27 threads
[pid 7072] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7071] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7070] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7073] gettimeofday( <unfinished ...>
[pid 7069] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7067] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7073] <... gettimeofday resumed> {1413529587, 83098}, NULL) = 0
[pid 7052] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7050] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7049] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7046] read(14, <unfinished ...>
[pid 7073] epoll_wait(22, <unfinished ...>
[pid 7066] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7065] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7063] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7062] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7061] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7060] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7059] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7058] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7057] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7056] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7055] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7054] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7053] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7051] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7048] futex(0x7f7111fd5664, FUTEX_WAIT_PRIVATE, 11483, NULL <unfinished ...>
[pid 7073] <... epoll_wait resumed> {}, 50, 100) = 0
[pid 7073] gettimeofday({1413529587, 186946}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 190070}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 190174}, NULL) = 0
[pid 7073] epoll_wait(22, {}, 50, 100) = 0
[pid 7073] gettimeofday({1413529587, 290683}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 290801}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 290902}, NULL) = 0
[pid 7073] epoll_wait(22, {}, 50, 100) = 0
[pid 7073] gettimeofday({1413529587, 391605}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 391981}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 392343}, NULL) = 0
[pid 7073] epoll_wait(22, {}, 50, 100) = 0
[pid 7073] gettimeofday({1413529587, 493283}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 493632}, NULL) = 0
[pid 7073] gettimeofday({1413529587, 493966}, NULL) = 0
[pid 7073] epoll_wait(22, {}, 50, 100) = 0
[pid 7073] gettimeofday({14...

Read more...

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.