Bug 246222 - usb backend eats all my CPU
usb backend eats all my CPU
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
6
i386 Linux
low Severity low
: ---
: ---
Assigned To: Tim Waugh
Fedora Extras Quality Assurance
:
Depends On:
Blocks: FC6Update
  Show dependency treegraph
 
Reported: 2007-06-29 07:31 EDT by Marcin Garski
Modified: 2007-11-30 17:12 EST (History)
0 users

See Also:
Fixed In Version: 1.2.11-3.fc7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-07-10 09:50:52 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
strace -tt -p 5514 2>strace.log (138.29 KB, application/octet-stream)
2007-07-03 16:58 EDT, Marcin Garski
no flags Details

  None (edit)
Description Marcin Garski 2007-06-29 07:31:18 EDT
cups-1.2.10-7.fc6

/var/log/cups/error_log says:
E [29/Jun/2007:12:46:09 +0200] [Job 12079] Out of paper!


strace gives endless:
write(5, "\200T\310\300\00516385\370\250R\3014\0\370\242\301`\0\370"..., 8192) =
-1 EAGAIN (Resource temporarily unavailable)

This nonstop repeated write probably eats all CPU.
Comment 1 Tim Waugh 2007-06-29 07:46:22 EDT
Please try the test update:

  yum --enablerepo=updates-testing update 'cups*'

Does that fix the problem?

(This is similar to bug #241589.)
Comment 2 Marcin Garski 2007-07-03 06:57:59 EDT
cups-1.2.10-9.fc6, this fd '5' is /dev/usb/lp0

Nothing has changed, still usb backend eats CPU.
Comment 3 Tim Waugh 2007-07-03 07:12:43 EDT
How are you measuring the CPU usage of the task?

Please attach a strace of the 'usb://...' process while it is using lots of CPU.
Comment 4 Marcin Garski 2007-07-03 07:47:48 EDT
I measuring it with 'top', when "Out of paper!" appears in log top shows "usb"
command with ~95% of CPU usage.
Comment 5 Marcin Garski 2007-07-03 16:56:49 EDT
1. lp -d Lexmark file.pdf
2. ps axf
3. 5514 ? R 0:26 usb:/dev/usb/lp0 .......
4. strace -tt -p 5514 2>strace.log

I have cut strace log because in a few seconds it grown to 45MB :) and it's all
the same messages.

error_log:
I [03/Jul/2007:22:45:06 +0200] Adding start banner page "none" to job 12353.
I [03/Jul/2007:22:45:06 +0200] Adding end banner page "none" to job 12353.
I [03/Jul/2007:22:45:06 +0200] Job 12353 queued on "Lexmark" by "root".
I [03/Jul/2007:22:45:06 +0200] Started backend /usr/lib/cups/backend/usb (PID
5514) for job 12353.
E [03/Jul/2007:22:45:12 +0200] [Job 12353] Out of paper!
Comment 6 Marcin Garski 2007-07-03 16:58:06 EDT
Created attachment 158475 [details]
strace -tt -p 5514 2>strace.log
Comment 7 Tim Waugh 2007-07-04 08:46:19 EDT
Problem understood.  The usb:/dev/usb/...-type URI causes us not to be using
select(), and that path is behaving incorrectly.

A test update package, 1.2.11-1.fc6, will shortly be available (probably later
this week).  When it is, please try it out:

  yum --enablerepo=updates-testing update 'cups*'

or, if you'd like to try out the packages sooner (although they won't be
signed), I've put them here:

  http://cyberelk.net/tim/data/tmp/cups/
Comment 8 Marcin Garski 2007-07-04 12:25:47 EDT
cups-1.2.11-1.fc6. Patch looks ok :)

BTW: Do you plan to send this patch upstream? I am asking because of
"linux_usb_paperout_hack" ;)

Just for info, strace:
18:13:54.510192 write(5,
"\2d\310\230\2534\337\233\213\r\236\350\347\364\253P\255"..., 8192) = -1 EAGAIN
(Resource temporarily unavailable)
18:13:54.510488 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
18:13:54.510674 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
18:13:54.510976 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
18:13:54.511209 nanosleep({1, 0}, {1, 0}) = 0
18:13:55.512969 write(5,
"\2d\310\230\2534\337\233\213\r\236\350\347\364\253P\255"..., 8192) = -1 EAGAIN
(Resource temporarily unavailable)
18:13:55.513267 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
18:13:55.513452 rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
18:13:55.513732 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
18:13:55.513928 nanosleep({1, 0}, {1, 0}) = 0
Comment 9 Tim Waugh 2007-07-04 12:30:37 EDT
Great.

No, I don't plan to send this patch upstream, but a much simpler one once the
kernel is fixed to do this stuff itself (see bug #236736).
Comment 10 Marcin Garski 2007-07-04 16:59:03 EDT
Thanks for info, and for fixing this bug.
Comment 11 Fedora Update System 2007-07-05 15:12:57 EDT
cups-1.2.11-3.fc7 has been pushed to the Fedora 7 testing repository.  If problems still persist, please make note of it in this bug report.
Comment 12 Fedora Update System 2007-07-16 12:50:10 EDT
cups-1.2.12-1.fc7 has been pushed to the Fedora 7 testing repository.  If problems still persist, please make note of it in this bug report.
Comment 13 Fedora Update System 2007-07-19 12:48:10 EDT
cups-1.2.12-1.fc7 has been pushed to the Fedora 7 stable repository.  If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.