CPU utilization

Fri Mar 27 07:49:00 PDT 2009

Hello all.

I've had CUPS 1.3 running for awhile and have been monitoring it closely.
Although it has improved in many ways, it is still a CPU-intensive process.

We manage every printer queues from the servers. From the client side, we
don't really do anything with the printer queues. Given that fact, is it
really necessary to pass all the other printer attributes to the client; ie,
info, job_sheets, location, make_model, where in fact these attributes are
essential only for the server?

In my case, I don't care about those attributes, not from the client side at
least. So, I've played with cups-polld a little by removing those attributes
and recompiled. That alone cut about %2 percent of CPU use on the client when
polling. We have about 2630 queues.

The polling session still shows high CPU utilization. Looking at the process
from beginning to end, the scheduler writes to printcap with very low CPU use
at the beginning and then very high CPU utilization at near end of the
polling. During my observation, I noticed that at the start of the polling
session, cupsd writes one printer and at near-end of the session, it shows and
keeps a list of writes.

Polling session start with one write for a printer queue with ps showing 0 CPU
use:

# ps -ef|grep -i cups
    root  839822       1   0 11:10:33      -  0:00 /usr/sbin/cupsd
      lp  893068  839822   0 11:10:33      -  0:00 cups-polld stldv504 631 3600 631
      lp 1413258  839822   0 11:10:33      -  0:00 cups-polld stldv503 631 3600 631

nrecvfrom(2, 0x2FF1C710, 1540, 0, 0x2FF1CD20, 0x2FF1E440) = 184
open("/etc/cups/printcap", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH) = 6
kfcntl(6, F_GETFD, 0x00000000)                  = 0
kfcntl(6, F_SETFD, 0x00000001)                  = 0
kwrite(6, " #   T h i s   f i l e  ".., 4059)   = 4059
kwrite(6, " a r 0 m @ s t l d v 5 0".., 182)    = 182
close(6)                                        = 0
kread(3, " I N F O :   [ c u p s -".., 1023)    = 224
_select(65534, 0x20012DC8, 0x20014DD8, 0x00000000, 0x2FF228D0) = 2
nrecvfrom(2, 0x2FF1C710, 1540, 0, 0x2FF1CD20, 0x2FF1E440) = 208
open("/etc/cups/printcap", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH) = 6
kfcntl(6, F_GETFD, 0x00000000)                  = 0
kfcntl(6, F_SETFD, 0x00000001)                  = 0
kwrite(6, " #   T h i s   f i l e  ".., 4059)   = 4059
kwrite(6, " a r 0 m @ s t l d v 5 0".., 330)    = 330
close(6)                                        = 0
...
...
kwrite(6, " #   T h i s   f i l e  ".., 4059)   = 4059
kwrite(6, " a r 0 m @ s t l d v 5 0".., 4085)   = 4085
kwrite(6, " c a 2 3 @ s t l d v 5 0".., 4049)   = 4049
kwrite(6, " c a 4 9 @ s t l d v 5 0".., 4076)   = 4076
kwrite(6, " c a 7 4 | H P L J 4 : r".., 4091)   = 4091
kwrite(6, " c a a 3 @ s t l d v 5 0".., 4007)   = 4007
kwrite(6, " c a a u @ s t l d v 5 0".., 4088)   = 4088
kwrite(6, " c a b q | Z H P 4 2 4 0".., 4081)   = 4081
kwrite(6, " c a c i @ s t l d v 5 0".., 4037)   = 4037
kwrite(6, " c a d 5 @ s t l d v 5 0".., 4045)   = 4045
kwrite(6, " c a d v @ s t l d v 5 0".., 4044)   = 4044
kwrite(6, " c a e n @ s t l d v 5 0".., 4045)   = 4045
kwrite(6, " c a f d @ s t l d v 5 0".., 873)    = 873
...
root  839822       1   7 11:10:33      -  0:00 /usr/sbin/cupsd

As seen from above, writes starts to accumulate and ps showing CPU use at 7.

...

Near the end of the polling session. Every cycle, cupsd keeps and
list the following entries:

kread(3, " I N F O :   [ c u p s -".., 1023)    = 124
_select(65534, 0x20012DC8, 0x20014DD8, 0x00000000, 0x2FF228D0) = 2
nrecvfrom(2, 0x2FF1C710, 1540, 0, 0x2FF1CD20, 0x2FF1E440) = 60
open("/etc/cups/printcap", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH) = 6
kfcntl(6, F_GETFD, 0x00000000)                  = 0
kfcntl(6, F_SETFD, 0x00000001)                  = 0
kwrite(6, " #   T h i s   f i l e  ".., 4071)   = 4071
kwrite(6, " a r 0 f @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a 1 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a 3 1 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a 5 1 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a 7 0 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a 9 1 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a a e @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a a x @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a b k @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a c 8 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a c r @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a d 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a d u @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a e h @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a e z @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a f m @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a g 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a g u @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a h c @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a h y @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c a i g @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c h 0 1 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c k 0 h @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c k 0 y @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c k 1 f @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c o 0 8 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c o 3 0 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c o 3 o @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c o 4 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " c o 4 s @ s t l d v 5 0".., 4071)   = 4071
kwrite(6, " f l 1 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l 3 1 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l 5 3 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l 7 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l 9 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l a h @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l b 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l b s @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l c m @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l d 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l d v @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l e m @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l f 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " f l f n @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 1 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 3 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 5 h @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 6 3 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 6 n @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 7 a @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " g a 7 s @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " i d 0 h @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " i l 0 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m n 0 d @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o 2 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o 4 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o 6 9 @ s t l d v 5 0".., 4053)   = 4053
kwrite(6, " m o 7 o @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o 8 e @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o 8 w @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o 9 p @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o a c @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o b 1 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o b u @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o c h @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o d c @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o d y @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o e f @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o f 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o f w @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o g f @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o g y @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o h m @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o i 3 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o i k @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o j 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o j o @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o k 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o k n @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o l 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o l p @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o m 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o m r @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o n d @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o n u @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o o d @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o o w @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o p g @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o q 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o q m @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o r a @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o r r @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o s 8 @ s t l d v 5 0".., 4068)   = 4068
kwrite(6, " m o s q @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o t a @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m o t y @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " m t 0 r @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n d 0 c @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n h 1 8 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n h 1 y @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n h 2 p @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n h 3 d @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n j 1 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n j 2 j @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n j 3 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n j 3 p @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n j 4 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n j 4 p @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n y 1 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n y 1 s @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n y 2 b @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n y 2 s @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " n y 3 a @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h 1 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h 5 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h 8 8 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h 8 t @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h 9 b @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h 9 u @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h a c @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " o h a u @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " p a 0 1 @ s t l d v 5 0".., 4053)   = 4053
kwrite(6, " s l 0 3 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l 2 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l 3 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l 6 5 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l 8 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l a 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l b 4 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l f 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l i 3 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l m 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l q 3 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l s 6 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l v 0 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " s l y 0 @ s t l d v 5 0".., 4083)   = 4083
kwrite(6, " t n 0 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 0 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 2 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 4 2 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 4 q @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 5 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 5 q @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 6 8 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " t x 6 q @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 1 5 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 3 9 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 5 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 5 t @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 6 f @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 7 7 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 7 p @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " v a 8 8 @ s t l d v 5 0".., 4029)   = 4029
kwrite(6, " w i 0 f @ s t l d v 5 0".., 3855)   = 3855
close(6)                                        = 0
...
root  839822       1  69 11:10:33      -  0:02 /usr/sbin/cupsd

Given that we have two CUPS server and the clients are configured to poll the
servers, I commented the BrowsePoll directives and wrote a small script to
start the cupsd and cups-polld separately. This approach saved about 3% of CPU
use during polling session.

So, I spared the clients from the unecessary attributes and seperated the cupsd
and cups-polld, I managed to cut about 5% off CPU utilization during cups
processing. The change is very visible and apparent when viewing the
performance graph taken before and after the changes were made.

But, what's with cupsd keeping the write sessions? I don't know why that is
happening, probably normal, but I think it's the cause of the high CPU use.

Thanks.