Bug 246222 - usb backend eats all my CPU
Summary: usb backend eats all my CPU
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
(Show other bugs)
Version: 6
Hardware: i386 Linux
low
low
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Keywords:
Depends On:
Blocks: FC6Update
TreeView+ depends on / blocked
 
Reported: 2007-06-29 11:31 UTC by Marcin Garski
Modified: 2007-11-30 22:12 UTC (History)
0 users

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: ---


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

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.


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