Bug 246222

Summary: usb backend eats all my CPU
Product: [Fedora] Fedora Reporter: Marcin Garski <mgarski>
Component: cupsAssignee: Tim Waugh <twaugh>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: low    
Version: 6   
Target Milestone: ---   
Target Release: ---   
Hardware: i386   
OS: Linux   
Whiteboard:
Fixed In Version: 1.2.11-3.fc7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2007-07-10 13:50:52 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 207681    
Attachments:
Description Flags
strace -tt -p 5514 2>strace.log none

Description Marcin Garski 2007-06-29 11:31:18 UTC
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 11:46:22 UTC
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 10:57:59 UTC
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 11:12:43 UTC
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 11:47:48 UTC
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 20:56:49 UTC
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 20:58:06 UTC
Created attachment 158475 [details]
strace -tt -p 5514 2>strace.log

Comment 7 Tim Waugh 2007-07-04 12:46:19 UTC
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 16:25:47 UTC
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 16:30:37 UTC
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 20:59:03 UTC
Thanks for info, and for fixing this bug.

Comment 11 Fedora Update System 2007-07-05 19:12:57 UTC
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 16:50:10 UTC
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 16:48:10 UTC
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.