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

Alex Korobkin korobkin+cups at gmail.com
Fri Jan 15 09:16:55 PST 2016


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



More information about the cups mailing list