Delay before printing in more recent Linux distributions?

[Nick Rahl]

Hi,

There seems to be a delay when printing with CUPS in more recent Linux
distributions, that was not present in older versions. For example, in
Ubuntu 8.04, when a file was added to the print cue, it printed
immediately if the printer was ready. In 10.04, there's a 10-15 second
delay between the start of the job, and when the printer actually starts
printing. From searching the Internet exhaustively, I've found people
using other Linux distros reporting a similar problem, but no solutions
offered.

The problem is present with CUPS 1.4.3 (the Ubuntu 10.04 default), and
also in 1.4.5 when I compiled from source. The same document prints
immediately from an Ubuntu 8.04 system or from Windows.

I was hoping someone might be able to shed some light on the problem. Is
it a CUPS issue, or a change to Linux in general? Are the developers
aware this issue exists? Are there any workarounds?

I'm going to try attaching (I don't know if the list accepts
attachments) a log of what happens when I print a one page document.

You can see that there's a 4 second wait just before
"prtGeneralCurrentLocalization type is 0, expected 2!". I'm not sure
what that message means.

It also does:

I [28/Nov/2010:14:44:19 -0500] [Job 3071] Printing page 1, 0% complete...
D [28/Nov/2010:14:44:19 -0500] Discarding unused job-progress event...
D [28/Nov/2010:14:44:19 -0500] Discarding unused printer-state-changed
event...
I [28/Nov/2010:14:44:19 -0500] [Job 3071] Printing page 1, 1% complete...
I [28/Nov/2010:14:44:19 -0500] [Job 3071] Printing page 1, 2% complete...
I [28/Nov/2010:14:44:19 -0500] [Job 3071] Printing page 1, 3% complete...

Over and over again, for several seconds, and then goes on to:

D [28/Nov/2010:14:44:26 -0500] [Job 3071] Wrote 8192 bytes of print data...
D [28/Nov/2010:14:44:26 -0500] [Job 3071] Read 8192 bytes of print data...

Over and over again, for several more seconds until it finally gets to:

I [28/Nov/2010:14:44:29 -0500] [Job 3071] Print file sent, waiting for
printer to finish...

At which point the document actually prints. In this example it takes a
full 10 seconds before the printer starts printing.

Any suggestions are appreciated!

Thanks,
Nick

[Michael Sweet]

Hi,
There seems to be a delay when printing with CUPS in more recent Linux distributions, that was not present in older versions. For example, in Ubuntu 8.04, when a file was added to the print cue, it printed immediately if the printer was ready. In 10.04, there's a 10-15 second delay between the start of the job, and when the printer actually starts printing. From searching the Internet exhaustively, I've found people using other Linux distros reporting a similar problem, but no solutions offered.
The problem is present with CUPS 1.4.3 (the Ubuntu 10.04 default), and also in 1.4.5 when I compiled from source. The same document prints immediately from an Ubuntu 8.04 system or from Windows.
I was hoping someone might be able to shed some light on the problem. Is it a CUPS issue, or a change to Linux in general? Are the developers aware this issue exists? Are there any workarounds?
I'm going to try attaching (I don't know if the list accepts attachments) a log of what happens when I print a one page document.
You can see that there's a 4 second wait just before "prtGeneralCurrentLocalization type is 0, expected 2!". I'm not sure what that message means.

This is the SNMP code getting the final page count; add "*cupsSNMP: False" to your PPD file and the delay will disappear.

________________________________________________________________________
Michael Sweet, Senior Printing System Engineer, PWG Chair

[Nick Rahl]

This is the SNMP code getting the final page count; add "*cupsSNMP: False" to your PPD file and the delay will disappear.


Thanks Michael,

I added:

*cupsSNMP: False

To the bottom of the PPD file just before:

*% End of ZEBRAEP2.PPD, 67437 bytes.

In /etc/cups/ppd/

...and restarted cups, but the delay is still present, and I'm still
getting the error in my log.

What am I doing wrong?

I'm using CUPS 1.4.5. My printer is a Zebra/Eltron 2844. This
delay/error is also present in 1.4.3, but is NOT present in 1.3.8.

And once the printer light starts blinking (after the SNMP delay), is it
normal for it to take another 5 seconds to download the data before
printing it? It's a one page, 70K .png file. Are there any network
settings that could be tweaked, like compressing the file, changing
packet size, etc?

3 seconds is spent on the loop:

I [02/Dec/2010:15:20:41 -0500] [Job 3195] Printing page 1, 65% complete...
D [02/Dec/2010:15:20:41 -0500] Discarding unused job-progress event...
D [02/Dec/2010:15:20:41 -0500] Discarding unused printer-state-changed
event...
I [02/Dec/2010:15:20:41 -0500] [Job 3195] Printing page 1, 67% complete...

and 3 more seconds on the loop:

D [02/Dec/2010:15:20:43 -0500] [Job 3195] Wrote 8192 bytes of print data...
D [02/Dec/2010:15:20:43 -0500] [Job 3195] Read 8192 bytes of print data...
D [02/Dec/2010:15:20:44 -0500] [Job 3195] Wrote 8192 bytes of print data...
D [02/Dec/2010:15:20:44 -0500] [Job 3195] Read 8192 bytes of print data...

Thanks again,
Nick

[Helge Blischke]

Post by Michael Sweet
This is the SNMP code getting the final page count; add "*cupsSNMP: False"
to your PPD file and the delay will disappear.
Thanks Michael,
*cupsSNMP: False
*% End of ZEBRAEP2.PPD, 67437 bytes.
In /etc/cups/ppd/
...and restarted cups, but the delay is still present, and I'm still
getting the error in my log.
What am I doing wrong?
I'm using CUPS 1.4.5. My printer is a Zebra/Eltron 2844. This
delay/error is also present in 1.4.3, but is NOT present in 1.3.8.
And once the printer light starts blinking (after the SNMP delay), is it
normal for it to take another 5 seconds to download the data before
printing it? It's a one page, 70K .png file. Are there any network
settings that could be tweaked, like compressing the file, changing
packet size, etc?
I [02/Dec/2010:15:20:41 -0500] [Job 3195] Printing page 1, 65% complete...
D [02/Dec/2010:15:20:41 -0500] Discarding unused job-progress event...
D [02/Dec/2010:15:20:41 -0500] Discarding unused printer-state-changed
event...
I [02/Dec/2010:15:20:41 -0500] [Job 3195] Printing page 1, 67% complete...
D [02/Dec/2010:15:20:43 -0500] [Job 3195] Wrote 8192 bytes of print
data... D [02/Dec/2010:15:20:43 -0500] [Job 3195] Read 8192 bytes of print
data... D [02/Dec/2010:15:20:44 -0500] [Job 3195] Wrote 8192 bytes of
print data... D [02/Dec/2010:15:20:44 -0500] [Job 3195] Read 8192 bytes of
print data...
Thanks again,
Nick

greping through the 1.4.5 sources revealed that cupsSNMP appeared nowhere,
but there is some handling of cupsSNMPSupplies. I don't know if that affects
the delay as well.

Helge

[Michael Sweet]

Post by Helge Blischke

Post by Michael Sweet
This is the SNMP code getting the final page count; add "*cupsSNMP: False"
to your PPD file and the delay will disappear.

...
greping through the 1.4.5 sources revealed that cupsSNMP appeared nowhere,
but there is some handling of cupsSNMPSupplies. I don't know if that affects
the delay as well.

D'oh! You're right of course.

Nick, change that line to read:

*cupsSNMPSupplies: False

Sorry about the mixup...

________________________________________________________________________
Michael Sweet, Senior Printing System Engineer, PWG Chair

[Nick Rahl]

Post by Michael Sweet
D'oh! You're right of course.
*cupsSNMPSupplies: False
Sorry about the mixup...

Thanks! The 4 second delay in the log is gone now. I'm still not sure
why it still takes 9 seconds to start printing though.

The file is cued at:
D [02/Dec/2010:20:08:54 -0500] cupsdAcceptClient: 10 from localhost (Domain)

And actually prints at:
I [02/Dec/2010:20:09:03 -0500] [Job 3199] Print file sent, waiting for
printer to finish...

It seems to be transferring data during that time... Is 9 seconds
considered "normal" for data transfer? (1 Page, 70KB) Or is there a
network or configuration problem?

Thanks,
Nick

[Michael Sweet]

Post by Nick Rahl

Post by Michael Sweet
D'oh! You're right of course.
*cupsSNMPSupplies: False
Sorry about the mixup...

Thanks! The 4 second delay in the log is gone now. I'm still not sure
why it still takes 9 seconds to start printing though.
D [02/Dec/2010:20:08:54 -0500] cupsdAcceptClient: 10 from localhost (Domain)
I [02/Dec/2010:20:09:03 -0500] [Job 3199] Print file sent, waiting for
printer to finish...
It seems to be transferring data during that time... Is 9 seconds
considered "normal" for data transfer? (1 Page, 70KB) Or is there a
network or configuration problem?

I wouldn't expect it to take quite that long; I used to print shipping labels on a LP-2844Z in less time than that over USB.

________________________________________________________________________
Michael Sweet, Senior Printing System Engineer, PWG Chair

[Nick Rahl]

Post by Michael Sweet
I wouldn't expect it to take quite that long; I used to print shipping labels on a LP-2844Z in less time than that over USB.

We're using an LP 2844 as well with a network printing adapter that
connects to the parallel port and lets you connect it to a network (very
similar to HP's Jet Direct). From a Windows desktop, it takes about 3
seconds from "click" to printing for an almost identical label. Whereas
from CUPS it's about 10 seconds.

The server that makes the labels is a VPS, so it's impossible to connect
a printer via USB. BUT since Windows does it in 3, the problem is most
likely not a hardware limitation, but rather an issue with Linux, CUPS,
or the network configuration. From the CUPS debug log, most of the time
is spent reading/writing, 8192 bytes at a time.

[Michael Sweet]

Post by Nick Rahl

Post by Michael Sweet
I wouldn't expect it to take quite that long; I used to print shipping labels on a LP-2844Z in less time than that over USB.

We're using an LP 2844 as well with a network printing adapter that
connects to the parallel port and lets you connect it to a network (very
similar to HP's Jet Direct). From a Windows desktop, it takes about 3
seconds from "click" to printing for an almost identical label. Whereas
from CUPS it's about 10 seconds.
The server that makes the labels is a VPS, so it's impossible to connect
a printer via USB. BUT since Windows does it in 3, the problem is most
likely not a hardware limitation, but rather an issue with Linux, CUPS,
or the network configuration. From the CUPS debug log, most of the time
is spent reading/writing, 8192 bytes at a time.

Keep in mind that the CUPS driver will only be sending a full-page/label bitmap, whereas the Windows driver likely is doing some/all as vectors (which results in a smaller print file).

________________________________________________________________________
Michael Sweet, Senior Printing System Engineer, PWG Chair