usb backend hogs cpu

[Graham White]

Binary package hint: cupsys

I have Ubuntu Dapper installed, with cups 1.2.2-0ubuntu0.6.06
I have an Epson Stylus Photo R2400 attached via usb. When
I try to print, the following things happen:
i) Load average goes up to over 3
ii) the usb backend process hogs nearly all of the cpu: most of the
time over 80%, occasionally 99%. This starts happening as soon
as I submit the print job, before rastertogutenprint has even
started, so it's hard to see what cups can have to say to the printer
at that stage.
iii) strace on the usb process reveals some sort of busy loop,
though this must occasionally be interrupted, because
printing does eventually happen,
iv) gs-esp, which usually hogs cpu when printing, manages
to get 0.3% of the cpu (no kidding)
v) printing is extremely slow (20 hours or so to print the test page).
No surprise, given the above.

This printer did work (and work quite well) both under breezy
and under the previous cups package under dapper, though
there were problems (gs-esp used to crash with certain types
of output). But printing wasn't as comprehensively broken as it is now.

I'm attaching configuration files, strace output, etc.

[Pascal De Vuyst (pascal-devuyst)]

Thanks for you bug report.
Could you also provide the cups error_log:
1) change LogLevel in cupsd.conf from warning to debug
2) restart cups: sudo /etc/init.d/cupsys restart
3) print something
4) attach the relevant parts of /var/log/cups/error_log

[Graham White (graham-dcs)]

On Wed, 2006-08-09 at 08:40 +0000, Pascal De Vuyst wrote:
> Thanks for you bug report.
> Could you also provide the cups error_log:
> 1) change LogLevel in cupsd.conf from warning to debug
> 2) restart cups: sudo /etc/init.d/cupsys restart
> 3) print something
> 4) attach the relevant parts of /var/log/cups/error_log
>
> ** Changed in: cupsys (Ubuntu)
> Status: Unconfirmed => Needs Info
>
I've attached an incomplete error log. It's incomplete
because at 12:57 or so cups stopped being able to write to the
error log: syslog from then on has repeated messages saying
cupsd: Unable to open log file "/var/log/cups/error_log" - Permission
denied
and the owner of /var/log/cups/error_log is now root instead of
cupsd. (And what do I do to stop cups from behaving like that?)

Do you want me to send a complete log?

Graham

[Graham White (graham-dcs)]

On Sun, 2006-08-13 at 14:59 +0000, Pascal De Vuyst wrote:
> Can you try if setting up a raw queue printer gives any output.
> In CUPS web interface or gnome-cups-manager: Add Printer, select Manufacturer Raw, select Model queue.
>
I've done that for both printers (the Epson which features in Bug 55656
and the HP in Bug 55663): both print small text files perfectly well.
However, I'm still a bit sceptical about the Epson, because the fault
always used to be a bit sporadic, and, in particular, it would usually
print a page or two after rebooting before it would start misbehaving.

Graham

[Graham White (graham-dcs)]

I have been experimenting with setting the nice value of the runaway usb
process, and it seems to have good effects. There are basically 4
processes involved in cups printing with this processor: cupsd, gs-esp,
rastertogutenprint, and usb. It is the usb process which hogs the cpu.
If I set the nice value of the usb process to 10 (using the command
renice +10 -p<process id of usb process>
then the usb process gets less cpu than rastertogutenprint, and
everything goes much faster (on my print server,
which is admittedly old and slow, about an order of magnitude faster).
Not perfect, but I can print a file in an hour or so
which was taking over a day without the renicing.

So, whatever the usb process is doing when it's hogging the cpu,
it apparently doesn't need to do nearly so much of it.

Graham

[Graham White (graham-dcs)]

I've been doing some profiling. Executive summary:
most of the cpu effort seems to be consumed by two function
calls (uhci_urb_enqueue and uhci_irq) in the uhci-hcd module.
Anyway, profiles attached.

[Graham White (graham-dcs)]

Another attachment: profile broken down by symbol name.
Incidentally, the profiles were done with oprofile.

[Graham White (graham-dcs)]

The callgraph generated by oprofile

[Graham White (graham-dcs)]

And, when I compiled a kernel with debugging symbols
for profiling, I activated usb debugging: here's the output it
generated in the course of one failed printing attempt followed
by switching the printer off then on again. These are the messages
I got from it: some of them are a little startling (and, no, the printer
wasn't on fire).

[Graham White (graham-dcs)]

The profiler seemed to indicate that
a lot of time was being spent in the uhci-hcd module, so
I tried the printer on the same CUPS setup but with a machine with
a USB2 port rather than USB1 (and thus ehci-hcd and not uhci-hcd). Much better:
the usb backend took a reasonable proportion of CPU cycles and
didn't bottleneck everything else. So, I bought a cheap USB pcmcia
card for the original machine: result, again, is that the USB backend
is now behaving normally. So, problem resolved for me, but I
still think this is a bug.

I don't think that this is a bug specifically with uhci-hcd, because
I tested the old USB1 port with a USB hard drive and some file
transfers, and they seemed to be about as fast as you'd expect
(though I didn't do this very systematically). So I think it's maybe some
interaction between cups and the uhci-hcd module. I don't really know much about the testing regime, but does CUPS get tested very much on old hardware? (If not, it sets unexpected traps for people like me
who have an old machine and think "gosh, this would make a good
printer spooler").

[Launchpad Janitor (janitor)]

[Expired for cupsys (Ubuntu) because there has been no activity for 60 days.]