Bug 426653

Summary: /usr/lib/cups/backend/usb busy-waits with 100% in select() call
Product: [Fedora] Fedora Reporter: Daniel Berrange <berrange>
Component: cupsAssignee: Tim Waugh <twaugh>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: high    
Version: 8   
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: 1.3.5-2.fc8 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2008-01-27 02:18:45 EST Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Bug Depends On:    
Bug Blocks: 235704    
Attachments:
Description Flags
Fix busy-waiting none

Description Daniel Berrange 2007-12-23 16:45:52 EST
Description of problem:
When printing a very large document it takes a while before the printer driver
is ready to feed data to /usr/lib/cups/backend/usb. During this time the 'usb'
backend busy-waits in select() with 100%.

It is polling on the file descriptor connecting to the USB device for
writability. select() is returning to say it is writable, but the backend has no
data to write, so it goes back into select again which of course immediately
says it is writable. 100% cpu burnt.


The processes running are, as follows, with the last (pid 22337) taking 100% cpu
time:

root     22316  0.4  0.5  17492 10656 ?        Ss   16:37   0:01 cupsd
lp       22335  1.3  0.0   6856  1512 ?        S    16:37   0:03  \_
Canon8x11Borderless 403 berrange sun-fire.ps 1 media=Letter.bl sides=one-sided
finishings=3 number-up=1 job-uuid=urn:uuid:23868aaa-638e-30cf-7437-c0b0eae1c6bf
/var/spool/cups/d00403-001
lp       22336  0.4  0.1   5944  2420 ?        S    16:37   0:01  \_
Canon8x11Borderless 403 berrange sun-fire.ps 1 media=Letter.bl sides=one-sided
finishings=3 number-up=1 job-uuid=urn:uuid:23868aaa-638e-30cf-7437-c0b0eae1c6bf
lp       22339  0.0  0.0   4700  1100 ?        S    16:37   0:00  |   \_ /bin/sh
-c /usr/bin/gs -r600 -g5100x6600 -q -dNOPROMPT -dSAFER -sDEVICE=ppmraw
-sOutputFile=- -| /usr/local/bin/cifip6600d --imageres 600 --borderless 
--papersize letter --media superphoto --paperload switch --quality 2 --gamma 1.8
--balance_c 0 --balance_m 0 --balance_y 0 --balance_k 0 --density 0 --extension
3 --bbox 0,0,612,792 
lp       22340 92.7  0.6  25876 12636 ?        R    16:37   4:30  |       \_
/usr/bin/gs -r600 -g5100x6600 -q -dNOPROMPT -dSAFER -sDEVICE=ppmraw -sOutputFile=- -
lp       22341  0.0  0.0   3172   960 ?        S    16:37   0:00  |       \_
/usr/local/bin/cifip6600d --imageres 600 --borderless --papersize letter --media
superphoto --paperload switch --quality 2 --gamma 1.8 --balance_c 0 --balance_m
0 --balance_y 0 --balance_k 0 --density 0 --extension 3 --bbox 0,0,612,792
lp       22337 54.5  0.0   4772  1216 ?        R    16:37   2:39  \_
usb://Canon/iP6700D 403 berrange sun-fire.ps 1 media=Letter.bl sides=one-sided
finishings=3 number-up=1 job-uuid=urn:uuid:23868aaa-638e-30cf-7437-c0b0eae1c6bf
[root@t60wlan ~]# 


strace -p 22337 shows:


select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])
select(6, [0 4], [5], NULL, NULL)       = 1 (out [5])



# ls -l /proc/22337/exe 
lrwxrwxrwx 1 lp lp 0 2007-12-23 16:38 /proc/22337/exe -> /usr/lib/cups/backend/usb

# ls -l /proc/22337/fd/5
lrwx------ 1 lp lp 64 2007-12-23 16:40 /proc/22337/fd/5 -> /dev/usb/lp0

# gdb
(gdb) attach 22337
Attaching to process 22337
(gdb) bt
#0  0x0012d402 in __kernel_vsyscall ()
#1  0x003565bd in ___newselect_nocancel () from /lib/libc.so.6
#2  0xb7f74f5a in backendRunLoop (print_fd=0, device_fd=5, use_bc=0,
side_cb=0xb7f73bc0 <side_cb>) at runloop.c:224
#3  0xb7f74230 in print_device (uri=0xbfae5f83 "usb://Canon/iP6700D",
hostname=0xbfae4f86 "Canon", resource=0xbfae4b86 "/iP6700D", options=0x0, 
    print_fd=0, copies=0, argc=6, argv=0xbfae5634) at usb-unix.c:184
#4  0xb7f74a0d in main (argc=6, argv=0xbfae5634) at usb.c:254

Version-Release number of selected component (if applicable):


How reproducible:
Always

Steps to Reproduce:
1. Print a huge document (eg a 300 MB photo) which takes a long time for the
printer driver to render
2. Run top
  
Actual results:
'usb' backend is consuming 100% cpu doing nothing

Expected results:
'usb' backend only uses CPU time when its doing something useful

Additional info:
Comment 1 Daniel Berrange 2007-12-23 16:50:49 EST
Created attachment 290311 [details]
Fix busy-waiting

Based on the gdb stack trace the problem is in the 'backend/runloop.c' file and
the backendRunLoop method.

This code fragment sets the file descriptor for writability if 'print_bytes' is
non zero, or  'use_bc' is zero:

    FD_ZERO(&output);
    if (print_bytes || !use_bc)
      FD_SET(device_fd, &output);

    if (use_bc || side_cb)
    {
      if (select(nfds, &input, &output, NULL, NULL) < 0)
      {


The stack trace shows that in the USB backend 'use_bc' is zero, and 'side_cb'
is non-zero, so we enter the select(), with the device monitored for
writability.

We only actually write data if 'print_bytes' is non zero though.

    if (print_bytes && FD_ISSET(device_fd, &output))
    {
      if ((bytes = write(device_fd, print_ptr, print_bytes)) < 0)


So, if use_bc is zero, and side_cb is non-NULL this code will busy-wait.

The solution is to change the initial code where the FD_SET is called

    FD_ZERO(&output);
    if (print_bytes || (!use_bc && !side_cb))
      FD_SET(device_fd, &output);


Attaching a patch which does this
Comment 2 Tim Waugh 2008-01-09 11:07:31 EST
Thanks for the analysis and patch.  Reported upstream:
  http://cups.org/str.php?L2664
Comment 3 Tim Waugh 2008-01-10 04:14:38 EST
Fixed in CVS.
Comment 4 Fedora Update System 2008-01-22 10:31:23 EST
cups-1.3.5-2.fc8 has been pushed to the Fedora 8 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update cups'
Comment 5 Fedora Update System 2008-01-27 02:18:35 EST
cups-1.3.5-2.fc8 has been pushed to the Fedora 8 stable repository.  If problems still persist, please make note of it in this bug report.