Bug 1179596
| Summary: | Cupsd is spinning after system boot | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Zdenek Kabelac <zkabelac> |
| Component: | cups | Assignee: | Tim Waugh <twaugh> |
| Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | unspecified | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 22 | CC: | a.radke, jpopelka, thierry.vignaud, twaugh, zkabelac |
| Target Milestone: | --- | Keywords: | Reopened |
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | cups-2.0.2-5.fc22 | Doc Type: | Bug Fix |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2015-03-21 04:53:12 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
What does 'p *fdptr' say? It looks like EPOLLHUP is set but fdptr->read_cb isn't. 69 if (nfds < 0 && errno != EINTR)
(gdb)
467 nfds = epoll_wait(cupsd_epoll_fd, cupsd_epoll_events, MaxFDs, -1);
(gdb)
469 if (nfds < 0 && errno != EINTR)
(gdb)
476 for (i = nfds, event = cupsd_epoll_events; i > 0; i --, event ++)
(gdb)
478 fdptr = (_cupsd_fd_t *)event->data.ptr;
(gdb) n
480 if (cupsArrayFind(cupsd_inactive_fds, fdptr))
(gdb) print *fdptr
$1 = {fd = 18, use = 1, read_cb = 0x0, write_cb = 0x0, data = 0x7f2ced083490}
This looks a bit suspicious, from upstream commit 6c2b2b194479fd5ace2b48378c13e7421023ac6d:
diff --git a/scheduler/client.c b/scheduler/client.c
index d7491cb..f5150e5 100644
--- a/scheduler/client.c
+++ b/scheduler/client.c
@@ -1979,6 +1979,12 @@ cupsdReadClient(cupsd_client_t *con) /* I - Client to read from */
if (httpGetState(con->http) == HTTP_STATE_POST_SEND)
{
+ /*
+ * Don't listen for activity until we decide to do something with this...
+ */
+
+ cupsdAddSelect(httpGetFd(con->http), NULL, NULL, con);
+
if (con->file >= 0)
{
fstat(con->file, &filestats);
Could you please try with cups-2.0.1-2.fc22? Ok - I'm not CPU being overtaking now by cups for a while. root 608 0.2 0.2 213108 9968 ? Ss 08:45 0:43 /usr/sbin/cupsd -l root 684 1.0 0.2 95476 8064 ? Ss 08:45 2:51 /usr/sbin/cups-browsed So it might have been possible fixed with: cups-2.0.1-2.fc22.x86_64 (Note how 'browsed' consumes quite a lot of CPU considering just 13hour uptime) Thanks. Yes, I'm aware of cups-browsed performance issues and plan to work on those this week. Hmm, I saw this yesterday, exactly the same symptoms. Unfortunately it's no longer happening today. cups-2.0.2-2.fc22.x86_64 cups-2.0.2-3.fc22 has been submitted as an update for Fedora 22. https://admin.fedoraproject.org/updates/cups-2.0.2-3.fc22 Package cups-2.0.2-3.fc22: * should fix your issue, * was pushed to the Fedora 22 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing cups-2.0.2-3.fc22' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2015-3837/cups-2.0.2-3.fc22 then log in and leave karma (feedback). Hmm, this is still happening even with poll():
poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=11, events=POLLIN}, {fd=12, events=POLLIN}, {fd=15, events=0}, {fd=16, events=0}], 6, 1000) = 2 ([{fd=15, revents=POLLHUP}, {fd=16, revents=POLLHUP}])
poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=11, events=POLLIN}, {fd=12, events=POLLIN}, {fd=15, events=0}, {fd=16, events=0}], 6, 1000) = 2 ([{fd=15, revents=POLLHUP}, {fd=16, revents=POLLHUP}])
poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=11, events=POLLIN}, {fd=12, events=POLLIN}, {fd=15, events=0}, {fd=16, events=0}], 6, 1000) = 2 ([{fd=15, revents=POLLHUP}, {fd=16, revents=POLLHUP}])
poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=11, events=POLLIN}, {fd=12, events=POLLIN}, {fd=15, events=0}, {fd=16, events=0}], 6, 1000) = 2 ([{fd=15, revents=POLLHUP}, {fd=16, revents=POLLHUP}])
Package cups-2.0.2-5.fc22: * should fix your issue, * was pushed to the Fedora 22 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing cups-2.0.2-5.fc22' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2015-3837/cups-2.0.2-5.fc22 then log in and leave karma (feedback). cups-2.0.2-5.fc22 has been pushed to the Fedora 22 stable repository. If problems still persist, please make note of it in this bug report. |
Description of problem: When my rawhide machine boots - cupsd seems to be permanently occupying 1 Core (100% CPU usage). (gdb) bt #0 0x00007f90d1e6f213 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81 #1 0x00007f90d4ef9f5c in cupsdDoSelect (timeout=1) at select.c:467 #2 0x00007f90d4ec3fd1 in main (argc=<optimized out>, argv=<optimized out>) at main.c:839 (gdb) list 76 #else 77 78 /* This is a "normal" system call stub: if there is an error, 79 it returns -1 and sets errno. */ 80 81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS) 82 ret 83 T_PSEUDO_END (SYSCALL_SYMBOL) 84 85 #endif (gdb) n cupsdDoSelect (timeout=1) at select.c:469 469 if (nfds < 0 && errno != EINTR) (gdb) 467 nfds = epoll_wait(cupsd_epoll_fd, cupsd_epoll_events, MaxFDs, -1); (gdb) 469 if (nfds < 0 && errno != EINTR) (gdb) print nfds $1 = 64 (gdb) n 476 for (i = nfds, event = cupsd_epoll_events; i > 0; i --, event ++) (gdb) print cupsd_epoll_events $2 = (struct epoll_event *) 0x7f90d6a30f90 (gdb) print *cupsd_epoll_events $3 = {events = 16, data = {ptr = 0x7f90d6adf620, fd = -693242336, u32 = 3601724960, u64 = 140260053743136}} (gdb) n 478 fdptr = (_cupsd_fd_t *)event->data.ptr; (gdb) 480 if (cupsArrayFind(cupsd_inactive_fds, fdptr)) (gdb) 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) 488 if (fdptr->use > 1 && fdptr->write_cb && (gdb) 493 release_fd(fdptr); (gdb) 476 for (i = nfds, event = cupsd_epoll_events; i > 0; i --, event ++) (gdb) 493 release_fd(fdptr); (gdb) 476 for (i = nfds, event = cupsd_epoll_events; i > 0; i --, event ++) (gdb) 478 fdptr = (_cupsd_fd_t *)event->data.ptr; (gdb) 480 if (cupsArrayFind(cupsd_inactive_fds, fdptr)) (gdb) 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) print i $4 = <optimized out> (gdb) n 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) 488 if (fdptr->use > 1 && fdptr->write_cb && (gdb) 493 release_fd(fdptr); (gdb) 476 for (i = nfds, event = cupsd_epoll_events; i > 0; i --, event ++) (gdb) 493 release_fd(fdptr); (gdb) print i $5 = <optimized out> (gdb) n 476 for (i = nfds, event = cupsd_epoll_events; i > 0; i --, event ++) (gdb) 478 fdptr = (_cupsd_fd_t *)event->data.ptr; (gdb) 480 if (cupsArrayFind(cupsd_inactive_fds, fdptr)) (gdb) 483 retain_fd(fdptr); (gdb) 485 if (fdptr->read_cb && (event->events & (EPOLLIN | EPOLLERR | EPOLLHUP))) (gdb) bt full #0 cupsdDoSelect (timeout=<optimized out>) at select.c:485 i = <optimized out> event = 0x7f90d6a30fa8 nfds = 64 fdptr = 0x7f90d6adf650 pfd = <optimized out> count = <optimized out> __func__ = "cupsdDoSelect" #1 0x00007f90d4ec3fd1 in main (argc=<optimized out>, argv=<optimized out>) at main.c:839 i = 2 opt = <optimized out> close_all = <optimized out> disconnect = <optimized out> fg = <optimized out> run_as_child = <optimized out> fds = 64 con = <optimized out> job = <optimized out> lis = <optimized out> current_time = <optimized out> activity = <optimized out> senddoc_time = 1420617386 expire_time = 1420617394 report_time = 0 event_time = 1420617141 timeout = 1 limit = {rlim_cur = 4096, rlim_max = 4096} action = {__sigaction_handler = {sa_handler = 0x7f90d4edd2f0 <sigterm_handler>, sa_sigaction = 0x7f90d4edd2f0 <sigterm_handler>}, sa_mask = {__val = {81920, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x0} failmode = (unknown: 32656) netif_time = 1420617379 service_idle_exit = 0 tmo = <optimized out> tmo_delay = 140734039353880 __func__ = "main" (gdb Version-Release number of selected component (if applicable): cups-2.0.1-1.fc22.x86_64 How reproducible: always Steps to Reproduce: 1. boot rawhide from 2014-01-06 2. 3. Actual results: Expected results: Additional info: