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

Mon Jan 18 09:56:41 PST 2016

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