FS#42666 - [cups] cupsd take 100% CPU
Attached to Project:
Arch Linux
Opened by Olivier (olive) - Monday, 03 November 2014, 14:00 GMT
Last edited by Andreas Radke (AndyRTR) - Sunday, 22 March 2015, 11:14 GMT
Opened by Olivier (olive) - Monday, 03 November 2014, 14:00 GMT
Last edited by Andreas Radke (AndyRTR) - Sunday, 22 March 2015, 11:14 GMT
|
Details
Description:
Each time cupsd is started, it takes 100% CPU (on one of the core, so this may give 40 or 50% CPU in multicore system) and remains at 100% after the job is printed. This bug seems to affect a lot of users, presumably everyone, this has been discussed bin this thread: https://bbs.archlinux.org/viewtopic.php?pid=1472139#p1472139 Additional info: * package version(s) cups 2.0.0-2 The older 1.7.5-1 is not affected. * config and/or log files etc. No error in the log file. Steps to reproduce: |
This task depends upon
Closed by Andreas Radke (AndyRTR)
Sunday, 22 March 2015, 11:14 GMT
Reason for closing: Fixed
Additional comments about closing: 2.0.2-3
Sunday, 22 March 2015, 11:14 GMT
Reason for closing: Fixed
Additional comments about closing: 2.0.2-3
Please enable debug logging in cupsd.conf and check if some error msg pops up.
cupsd on my computer (package cups-2.0.0-2) -- begins use cpu 100% *always* when I go to "http://127.0.0.1:631/admin" and push button "Find New Printers".
then I must do "sudo systemctl restart org.cups.cupsd" to stop 100% cpu using.
my file "cupsd.conf" -- is https://gist.github.com/anonymous/d3b293d712ddf62b1d09
I tryed to view what the operation doing in infinite cycle (via using utility "strace")
[code]
$ sudo systemctl stop org.cups.cupsd org.cups.cupsd.path org.cups.cupsd.socket
$ sudo strace /usr/bin/cupsd -l
### go to "http://127.0.0.1:631/admin" and push button "Find New Printers" ###
... ... ...
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
epoll_wait(4, {{EPOLLHUP, {u32=2683298992, u64=140598437733552}}}, 4096, 1000) = 1
... ... ... (repeat infinite times) ... ... ...
[/code]
I disabled network (disabled WiFi card) on my computer. but no any difference.
no USB-printers connected on my computer.
I have just made a test and I also have a never ending
"epoll_wait(4, {{EPOLLHUP, {u32=842727904, u64=140137035661792}}}, 4096, 1000) = 1"
Remember that there are not error messages in demsg, journal and cups log.
Deleting /etc/cups and /var/cache/cups and reinstalling cups wil not solve the problem.
Note that the "cupsd -l" process just became sane again. But I can trigger another period of 100% CPU usage by clicking the "Find new printers" button on the administration page on localhost:631.
error_log.gz (306.9 KiB)
page_log.gz (0 KiB)
(gnome-control-center:12460): printers-cc-panel-WARNING **: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.fedoraproject.Config.Printing was not provided by any .service files
(gnome-control-center:12460): printers-cc-panel-WARNING **: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.PackageKit was not provided by any .service files
(gnome-control-center:12460): printers-cc-panel-WARNING **: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.fedoraproject.Config.Printing was provided by any .service files
Installed "system-config-printer" and I no longer get high cpu consumption and printing works (pretty sure I didnt have it installed for 1.7.5 and printing worked perfect)
Im having trouble adding the virtual pdf printer (works through web interface so propably a gnome bug)
I had a couple of shared printers. I disabled sharing and changed the cups configuration file disabling Browsing (Browsing Off) but the issue remains. Every time I print and on boot CPU load goes to 100%.
Just to point out: I have gnome-manual-duplex installed from sourceforge and it causes some errors. In the error log I have several lines with "[cups-deviced] Bad line from "gmd":". Also there are warning lines like: "CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'Canon_MP250_series-Gray..' already exists" for every printer I have installed.
Can you please tell us what printers are you using? All IPP or a certain company backend?
You can try to disable str4500.patch if this affects your bug.
If this all doesn't help look for known upstream bugs or file one and leave here the STR cups tracker ID.
Canon MP250 series - CUPS+Gutenprint v5.2.10
GnomeManualDuplex Virtual Printer Generic CUPS-PDF Printer
HP Deskjet 1510 Series hpijs, 3.14.10 Idle
HP LaserJet Professional p1102, hpcups 3.14.10, requires proprietary plugin
Generic CUPS-PDF Printer
How would I disable str4500.patch?
after login to system proccess /usr/bin/cupsd -l take 100% one of core CPU.
after restart cups service (sudo systemctl restart org.cups.cupsd) all is fine.
cups looks for „ServerName /run/cups/cups.sock“
i change the line to „ServerName localhost:631“
edit: i remove „/usr/share/cups/model/foomatic-db-ppds/Kyocera/ReadMe.htm“ before i change client.conf,
maybe its both necessary.
@ Peter Mayr: You're great, thx man! :)
1) High cpu on reboot: fixed
2) High cpu on printing: fixed
3) High cpu on changing configuration at localhost:631 (for example printer defaults): NOT fixed
[110948.082470] usb 3-4: new high-speed USB device number 4 using xhci_hcd
[110948.256955] usb 3-4: ep 0x3 - rounding interval to 8 microframes, ep desc says 10 microframes
[110948.256962] usb 3-4: ep 0x84 - rounding interval to 8 microframes, ep desc says 10 microframes
[110948.256966] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[110948.256970] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[110948.263876] WARNING! power/level is deprecated; use power/control instead
[110948.270885] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[110948.270895] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[110948.271488] usblp 3-4:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04E8 pid 0x342B
[110948.271525] usbcore: registered new interface driver usblp
[110949.437654] usblp0: removed
[110949.438829] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[110949.438837] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[110949.440316] usblp 3-4:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04E8 pid 0x342B
[111009.819386] usblp0: removed
[111018.403335] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.403342] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.403744] usblp 3-4:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04E8 pid 0x342B
[111018.403812] usblp0: removed
[111018.561760] usb 3-4: reset high-speed USB device number 4 using xhci_hcd
[111018.561780] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 3.
[111018.561784] usb 3-4: hub failed to enable device, error -22
[111018.721809] usb 3-4: reset high-speed USB device number 4 using xhci_hcd
[111018.721831] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 3.
[111018.721835] usb 3-4: hub failed to enable device, error -22
[111018.882033] usb 3-4: reset high-speed USB device number 4 using xhci_hcd
[111018.895677] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8800d5735d80
[111018.895681] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8800d5735dc8
[111018.895684] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8800d57353c0
[111018.895686] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8800d5735408
[111018.895693] usb 3-4: ep 0x3 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.895696] usb 3-4: ep 0x84 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.895700] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.895704] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.895828] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.895832] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[111018.896180] usblp 3-4:1.1: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04E8 pid 0x342B
The print was completed OK but the CPU on one of the 4 cores was pegged at 100% for around a minute or two. I have not tried to change the line in /etc/cups/client.conf as in some of the comments. Any chance this is related to problems with multifunction printers connected to usb3 ports when scanning?
In my case I have the socket enabled instead of the service:
$ sudo systemctl status org.cups.cupsd.service
● org.cups.cupsd.service - CUPS Scheduler
Loaded: loaded (/usr/lib/systemd/system/org.cups.cupsd.service; disabled; vendor preset: disabled)
Active: active (running) since Mon 2014-12-22 23:06:43 GMT; 2min 19s ago
Docs: man:cupsd(8)
Main PID: 375 (cupsd)
CGroup: /system.slice/org.cups.cupsd.service
└─375 /usr/bin/cupsd -l
Dec 22 23:06:43 home1 systemd[1]: Started CUPS Scheduler.
$ sudo systemctl status org.cups.cupsd.socket
● org.cups.cupsd.socket - CUPS Scheduler
Loaded: loaded (/usr/lib/systemd/system/org.cups.cupsd.socket; enabled; vendor preset: disabled)
Active: active (running) since Mon 2014-12-22 23:06:42 GMT; 2min 23s ago
Listen: /run/cups/cups.sock (Stream)
Dec 22 23:06:42 home1 systemd[1]: Starting CUPS Scheduler.
Dec 22 23:06:42 home1 systemd[1]: Listening on CUPS Scheduler.
When I changed the /etc/cups/client.conf as suggested above and rebooted then there was a systemd service failure. On returning the config file to the original and rebooting there was 100% CPU load on one processor for a minute or so and then on another CPU for a minute or so before it settled down. On turning off the printer I had another bout of CPU load pegged at 100%. Maybe this needs an upstream fix?
$ cat /var/log/cups/error_log
E [22/Dec/2014:22:47:17 +0000] Missing value on line 1210.
E [22/Dec/2014:22:47:17 +0000] Missing value on line 2350.
E [22/Dec/2014:22:47:17 +0000] Missing value on line 2362.
E [22/Dec/2014:22:47:17 +0000] Missing value on line 2374.
E [22/Dec/2014:23:06:43 +0000] Missing value on line 1210.
E [22/Dec/2014:23:06:43 +0000] Missing value on line 2350.
E [22/Dec/2014:23:06:43 +0000] Missing value on line 2362.
E [22/Dec/2014:23:06:43 +0000] Missing value on line 2374.
E [23/Dec/2014:09:58:49 +0000] Missing value on line 1210.
E [23/Dec/2014:09:58:49 +0000] Missing value on line 2350.
E [23/Dec/2014:09:58:49 +0000] Missing value on line 2362.
E [23/Dec/2014:09:58:49 +0000] Missing value on line 2374.
E [23/Dec/2014:10:21:40 +0000] [Client 11] Returning HTTP Forbidden for CUPS-Delete-Printer (ipp://mike@localhost:631/printers/SCX-4500W-Series) from localhost
E [23/Dec/2014:10:22:32 +0000] [cups-driverd] Bad driver information file "/usr/share/cups/model/foomatic-db-ppds/Kyocera/ReadMe.htm"!
W [23/Dec/2014:10:22:36 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'SCX-4500W-Series-Gray..' already exists
W [23/Dec/2014:10:22:49 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'SCX-4500W-Series-Gray..' already exists
I then printed a mail from Thunderbird which behaved normally, with the print emerging within a few seconds, and no high CPU load. Switching off the printer then gave the CPU pegged at 100% for some minutes again until I used systemctl stop org.cups.cupsd. I also noted from the error log that there was a Bad driver information file, so I deleted it even though I have no Kyocera printer on my system, and never have!
Is there any other diagnostics that I can generate that might be helpful in diagnosing where this bug originates? My dmesg output from the point where I switched off the printer in the sequence above is:
[40255.411712] usb 3-4: USB disconnect, device number 5
[40255.411988] usblp0: removed
[40492.352365] usb 3-4: new high-speed USB device number 7 using xhci_hcd
[40492.526960] usb 3-4: ep 0x3 - rounding interval to 8 microframes, ep desc says 10 microframes
[40492.526966] usb 3-4: ep 0x84 - rounding interval to 8 microframes, ep desc says 10 microframes
[40492.526970] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[40492.526973] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[40492.527230] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[40492.527235] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[40492.527780] usblp 3-4:1.1: usblp0: USB Bidirectional printer dev 7 if 1 alt 0 proto 2 vid 0x04E8 pid 0x342B
[40493.615901] usblp0: removed
[40493.616703] usb 3-4: ep 0x1 - rounding interval to 8 microframes, ep desc says 10 microframes
[40493.616711] usb 3-4: ep 0x82 - rounding interval to 8 microframes, ep desc says 10 microframes
[40493.619412] usblp 3-4:1.1: usblp0: USB Bidirectional printer dev 7 if 1 alt 0 proto 2 vid 0x04E8 pid 0x342B
After then switching off the printer again the CPU also pegged at 100% again for several minutes swapping between CPUs that showed 100%. After waiting a couple of minutes with no sign of the CPU high load terminating I stopped the cups service in order to prevent the CPU load remaining at 100%. At this point an additional line appeared in dmesg:
[43442.945126] perf interrupt took too long (2509 > 2495), lowering kernel.perf_event_max_sample_rate to 50100
Since this bug has been around ever since the update to cups version 2.0 through to the current 2.0.1-1 it would be nice to get this sorted out.
Only then can I get to the printer driver list and install a driver, which is slow because one core still remains at 100%. With Gutenprint installed, both cores are at 100% and even after half an hour nothing happens.
I still have to restart the org.cups.cupsd.service after the installation because one CPU core stays at 100% and only drops to normal after a restart.
This should only be a temporary solution because now I have to use the HP driver for my old HPLaserjet6L, which gives me a poorer quality and accuracy than the Gutenprint driver.
Whether this helps since this points to possible involvement of socket activation I am unsure but if anyone can explore that possibility it might narrow down where the main issue is?
No high load problems when printing, though.