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:
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
Thanks for the analysis and patch. Reported upstream: http://cups.org/str.php?L2664
Fixed in CVS.
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'
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.