[cups] How do I add a Managing Operation Policies with out a restart of the cupsd

Pförtsch, Franz Franz.Pfoertsch at brose.com
Fri Jan 15 07:01:40 PST 2016


Hello Johannes,

Thanks a lot for your big analyzis.

I am on sles 12 sp1 cups 1.7.5  with all updates.

My server is running as virtual machine on a ESXi host ( 4GB Ram an 4 vCPU).

In my opinion the bottleneck are access to the status files at /var/cache/cups

Regards and thanks for any help.

Franz Pförtsch


-----Original Message-----
From: cups-bounces at cups.org [mailto:cups-bounces at cups.org] On Behalf Of Johannes Meixner
Sent: Friday, January 15, 2016 12:27 PM
To: The CUPS user discussion list.
Subject: Re: [cups] How do I add a Managing Operation Policies with out a restart of the cupsd


Hello,

On Jan 14 17:50 Pförtsch, Franz wrote (excerpt):
> I am on SuSE

What SLES or openSUSE version and what CUPS version?


Regarding warnings like
> W ... No limit for Validate-Job defined in policy covpadm ...
see "A side note (minor issue)" in
https://www.cups.org/str.php?L4659


>> restart of the hole cupsd take ~ 6minutes
>> 2100 printqueues

I can reproduce that with CUPS 1.7.5 starting cupsd can take some minutes for some thousand print queues compared to CUPS 1.3.9 that needs only a few seconds:

On my slow 32-bit x86 SLES11 system with CUPS 1.3.9
----------------------------------------------------------------------
# time for i in $( seq 1001 3100 ) ; \
   do lpadmin -p testy$i -v file:/dev/null \
   -P /usr/share/cups/model/Postscript.ppd.gz -E ; done

real    4m1.962s
user    0m3.536s
sys     0m6.632s

# time ( rccups stop ; for i in $( seq 600 ) ; \
   do lpstat -r || break ; sleep 1 ; done )
Shutting down cupsd                                 done
lpstat: Unable to connect to server

real    0m0.090s
user    0m0.004s
sys     0m0.008s

# time ( rccups start ; for i in $( seq 600 ) ; \
   do lpstat -r && break ; sleep 1 ; done ) Starting cupsd done
lpstat: Unable to connect to server
lpstat: Unable to connect to server
lpstat: Unable to connect to server
lpstat: Unable to connect to server
lpstat: Unable to connect to server
lpstat: Unable to connect to server
scheduler is running

real    0m6.611s
user    0m0.024s
sys     0m0.044s
----------------------------------------------------------------------

On my medium fast x86_64 SLES12 system with CUPS 1.7.5
----------------------------------------------------------------------
# time for i in $( seq 1001 3100 ) ; \
   do lpadmin -p testy$i -v file:/dev/null \
   -P /usr/share/cups/model/Postscript.ppd.gz -E ; done

real    8m1.270s
user    0m5.992s
sys     0m3.012s

# time ( rccups stop ; for i in $( seq 600 ) ; \
   do lpstat -r | grep 'is not running' && break ; sleep 1 ; done ) scheduler is not running

real    0m0.024s
user    0m0.008s
sys     0m0.000s

# time ( rccups start ; for i in $( seq 600 ) ; do \
   lpstat -r | grep 'is running' && break ; sleep 1 ; done ) scheduler is running

real    2m29.084s
user    0m0.332s
sys     0m0.348s
----------------------------------------------------------------------
Excerpts from /var/log/cups/error_log where CUPS 1.7.5 cupsd spends most of its startup time (with "LogLevel info"):
----------------------------------------------------------------------
I [15/Jan/2016:11:41:41 +0100] Listening to [v1.::1]:631 (IPv6) ...
I [15/Jan/2016:11:41:41 +0100] Loaded MIME database from
  "/usr/share/cups/mime" and "/etc/cups": 44 types, 83 filters...
I [15/Jan/2016:11:43:50 +0100] Loading job cache file
  "/var/cache/cups/job.cache"...
...
W [15/Jan/2016:11:43:50 +0100] CreateProfile failed:
  org.freedesktop.DBus.Error.ServiceUnknown:The name
  org.freedesktop.ColorManager was not provided by any .service files ...
W [15/Jan/2016:11:44:08 +0100] CreateProfile failed:
  org.freedesktop.DBus.Error.ServiceUnknown:The name
  org.freedesktop.ColorManager was not provided by any .service files ...
I [15/Jan/2016:11:44:09 +0100] Saving printers.conf...
----------------------------------------------------------------------
During startup CUPS 1.7.5 cupsd uses 100% CPU.
The observed behaviour is reproducible (i.e. always same time).

On my fast x86_64 openSUSE Leap 42.1 system with CUPS 1.7.5:
----------------------------------------------------------------------
# time for i in $( seq 1001 3100 ) ; do \
   lpadmin -p testy$i -v file:/dev/null \
   -P /usr/share/cups/model/Postscript.ppd.gz -E ; done

real    4m40.390s
user    0m12.164s
sys     0m4.216s

# time ( rccups stop ; for i in $( seq 600 ) ; do \
   lpstat -r | grep 'is not running' && break ; sleep 1 ; done ) scheduler is not running

real    0m0.043s
user    0m0.008s
sys     0m0.000s

# time ( rccups start ; for i in $( seq 600 ) ; do \
   lpstat -r | grep 'is running' && break ; sleep 1 ; done ) scheduler is running

real    1m27.828s
user    0m0.300s
sys     0m0.116s
----------------------------------------------------------------------
Excerpts from /var/log/cups/error_log where CUPS 1.7.5 cupsd spends most of its startup time (with "LogLevel info"):
----------------------------------------------------------------------
I [15/Jan/2016:11:41:34 +0100] Listening to [v1.::1]:631 (IPv6) ...
I [15/Jan/2016:11:41:34 +0100] Loaded MIME database from
  "/usr/share/cups/mime" and "/etc/cups": 39 types, 57 filters...
I [15/Jan/2016:11:42:55 +0100] Loading job cache file
  "/var/cache/cups/job.cache"...
...
W [15/Jan/2016:11:42:55 +0100] CreateProfile failed:
  org.freedesktop.DBus.Error.ServiceUnknown:The name
  org.freedesktop.ColorManager was not provided by any .service files ...
W [15/Jan/2016:11:43:02 +0100] CreateProfile failed:
  org.freedesktop.DBus.Error.ServiceUnknown:The name
  org.freedesktop.ColorManager was not provided by any .service files ...
I [15/Jan/2016:11:43:02 +0100] Saving printers.conf...
---------------------------------------------------------------------
During startup CUPS 1.7.5 cupsd uses 100% CPU.
The observed behaviour is reproducible (i.e. always same time).

Most of the time happens between "Loaded MIME database"
and "Loading job cache file" therefore again excerpts from /var/log/cups/error_log for cupsd start with CUPS 1.7.5 but now with "LogLevel debug" and "MaxLogSize 0":
---------------------------------------------------------------------
I [15/Jan/2016:12:06:40 +0100] Listening to [v1.::1]:631 (IPv6) ...
I [15/Jan/2016:12:06:40 +0100] Loaded MIME database from
  "/usr/share/cups/mime" and "/etc/cups": 39 types, 57 filters...
D [15/Jan/2016:12:06:40 +0100] Loading printer testy1001...
D [15/Jan/2016:12:06:40 +0100] load_ppd: Loading
  /var/cache/cups/testy1001.data...
D [15/Jan/2016:12:06:40 +0100]
  cupsdRegisterPrinter(p=0x55efee116bd0(testy1001))
D [15/Jan/2016:12:06:40 +0100] Loading printer testy1002...
...
D [15/Jan/2016:12:07:56 +0100] Loading printer testy3100...
D [15/Jan/2016:12:07:56 +0100] load_ppd: Loading
  /var/cache/cups/testy3100.data...
D [15/Jan/2016:12:07:57 +0100]
  cupsdRegisterPrinter(p=0x55eff50772d0(testy3100))
I [15/Jan/2016:12:07:57 +0100] Loading job cache file
  "/var/cache/cups/job.cache"...
---------------------------------------------------------------------

I do not see any obvious error here.
From my non-expert point of view it seems new functionality is done during cupsd start that needs its time to be done.
Perhaps something could be optimized here but as far as I currently see there is no real bug here.

Franz Pförtsch,
if on your machine cupsd start needs 6 minutes for 2100 print queues compared to 1.5 minutes on my fast nowadays off-the-shelf workstation (this is not at all a high-end server system) I recommend first and foremost to use more powerful hardware for your production print server.
Otherwise I fear there will be much more severe performance issues in the future when your current hardware is used under real production loads.
In particular because nowadays print job data processing may need even much more resources because nowadays documents can contain much more complex high resolution graphics often stacked in various transparency layers:
"I just wanted to just print that PDF which I just got from
  Mr. John Doe but now the printer is 'busy' since two hours!"
;-)


Kind Regards
Johannes Meixner
--
SUSE LINUX GmbH - GF: Felix Imendoerffer, Jane Smithard, Graham Norton - HRB 21284 (AG Nuernberg)


More information about the cups mailing list