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

Michael Sweet msweet at apple.com
Tue Jan 19 08:04:59 PST 2016 

... and to follow up for people on the list, after looking at Franz's logs (both from a cold start and a restart) it appears that the culprit may be the freeing of old attribute data for each print queue - a restart is about 9 times slower than a cold start.

We are tracking this issue in CUPS STR #4760:

    https://www.cups.org/str.php?L4760


> On Jan 18, 2016, at 12:56 PM, Michael Sweet <msweet at apple.com> wrote:
> 
> Alex,
> 
> Loading PPDs from multiple threads in parallel won't necessarily improve startup speed, and will require additional synchronization.
> 
> In this case it looks like a missing colord service might be to blame...
> 
> 
>> On Jan 15, 2016, at 12:16 PM, Alex Korobkin <korobkin+cups at gmail.com> wrote:
>> 
>> IMO, another bottleneck is CUPS scheduler (cupsd) behaving as a
>> single-threaded app. No matter how many CPUs you throw at it, cupsd would
>> use just one all the time: when it starts, it reads its PPD cache printer
>> by printer, never trying to split the task between multiple threads. It
>> would also be a few times slower, if you restored printers.conf and /ppd
>> from backup, thus invalidating its cache.
>> 
>> And when it finally starts, cupsd would keep using just one CPU for serving
>> clients, which means it gets slower and slower when the number of clients
>> reaches a couple of thousands, because it needs to give them a list of
>> printers from time to time. Filters would use spare CPUs, but cupsd is
>> always using just a single one.
>> 
>> That's just my experience, of course. I wouldn't recommend to have a single
>> printserver serving more than two thousand Linux users. And if your users
>> cannot tolerate a downtime >5 min, keep the number of printers below 500,
>> especially if your CUPS is running on a virtual machine with slower disk
>> IO.
>> 
>> 
>> 
>> On Fri, Jan 15, 2016 at 10:01 AM, Pförtsch, Franz <Franz.Pfoertsch at brose.com
>>> wrote:
>> 
>>> 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)
>>> _______________________________________________
>>> cups mailing list
>>> cups at cups.org
>>> https://www.cups.org/mailman/listinfo/cups
>>> 
>> 
>> 
>> 
>> -- 
>> -Alex
>> _______________________________________________
>> cups mailing list
>> cups at cups.org
>> https://www.cups.org/mailman/listinfo/cups
> 
> _________________________________________________________
> Michael Sweet, Senior Printing System Engineer
> 
> _______________________________________________
> cups mailing list
> cups at cups.org
> https://www.cups.org/mailman/listinfo/cups

_________________________________________________________
Michael Sweet, Senior Printing System Engineer

More information about the cups mailing list