[cups] job submission delay: cupsd responds "Continue" instead of "OK"

Johannes Meixner jsmeix at suse.de
Wed Jan 22 08:14:52 PST 2014


Hello,

we (i.e. SUSE) got the following issue report from a user:

A CUPS 1.3.9 server (the CUPS version we have in SLES11)
gets about 60000 print jobs each day.

Basically it works (it is amazing to get user information
that 60000 print jobs each day work) except the following
performance issue:

Sometimes (not often) the cupsd responds "HTTP/1.1 100 Continue"
instead of "HTTP/1.1 200 OK" to the CUPS 1.3.9 lp command
that submits the job regardless that - as far as I see - the
whole job data was sent.

In this case there is a 10 seconds delay until a timeout happens
where the cupsd waits for more data from the client but the
client cannot send more data.

For 60000 print jobs each day those delays make a difference
regarding the overall performance.

Up to now we have been unable to reproduce the issue so that
I cannot tell if it works better with a newer CUPS version.

Before I now dig into CUPS' IPP implementation to find out
under what excat conditions the cupsd responds with "Continue"
instead of "OK", I would like to know if such an issue is
already known or if it is a new issue.


Details FYI:

Excerpt from strace on the client:

A usual fast job submission (long lines wrapped):
---------------------------------------------------------------------------
lp.strace.17322:09:53:16.484433 sendto(3,
  "%PDF-1.4\n1 0 obj\n<<\n/Creator (Or"..., 22766, 0, NULL, 0) = 22766
lp.strace.17322-09:53:16.484942 read(5, "", 32768)      = 0
lp.strace.17322-09:53:16.485021 recvfrom(3,
  "HTTP/1.1 200 OK\r\nDate: Thu, 19 D"..., 2048, 0, NULL, NULL) = 377
lp.strace.17322-09:53:16.490361 close(5)                = 0
lp.strace.17322-09:53:16.490505 fstat(1,
  {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
lp.strace.17322-09:53:16.490661 mmap(NULL, 4096,
  PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7fd2dff000
lp.strace.17322-09:53:16.490832 write(1,
  "request id is pwoe27741639-36527"..., 47) = 47
lp.strace.17322-09:53:16.490927 exit_group(0)           = ?
---------------------------------------------------------------------------
After the PDF data was sent, the cupsd responds immediately with
"HTTP/1.1 200 OK..." which lets the lp command immediately finish.

In contrast a job submission with 10 seconds delay (long lines wrapped):
---------------------------------------------------------------------------
lp.strace.17661:09:53:28.746820 sendto(3,
  "%PDF-1.4\n1 0 obj\n<<\n/Creator (Or"..., 26236, 0, NULL, 0) = 26236
lp.strace.17661-09:53:28.747314 read(5, "", 32768)      = 0
lp.strace.17661-09:53:28.747350 recvfrom(3,
  "HTTP/1.1 100 Continue\r\n\r\n", 2048, 0, NULL, NULL) = 25
lp.strace.17661-09:53:39.473425 recvfrom(3,
  "HTTP/1.1 200 OK\r\nDate: Thu, 19 D"..., 2048, 0, NULL, NULL) = 196
lp.strace.17661-09:53:39.476511 recvfrom(3,
  "\1\1\0\0\0\0\0\1\1G\0\22attributes-charset\0\5"..., 181, 0, NULL, NULL)
  = 181
lp.strace.17661-09:53:39.516604 close(5)                = 0
lp.strace.17661-09:53:39.516666 fstat(1,
  {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
lp.strace.17661-09:53:39.516696 mmap(NULL, 4096,
  PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7005e4c000
lp.strace.17661-09:53:39.516776 write(1,
  "request id is pwoe25076954-36527"..., 47) = 47
lp.strace.17661-09:53:39.516831 exit_group(0)           = ?
---------------------------------------------------------------------------
After the PDF data was sent, the cupsd responds immediately with
"HTTP/1.1 100 Continue\r\n\r\n" but the lp command does not do
anything here so that the cupsd waits 10 seconds until it sends
"HTTP/1.1 200 OK..." which lets the lp command immediately finish.


Kind Regards
Johannes Meixner
-- 
SUSE LINUX Products GmbH -- Maxfeldstrasse 5 -- 90409 Nuernberg -- Germany
HRB 16746 (AG Nuernberg) GF: Jeff Hawn, Jennifer Guild, Felix Imendoerffer



More information about the cups mailing list