CUPS 1.3 performance observation

[angelb]

> angelb wrote:
> > ...
> > However, when the cupsd daemon has been refreshed, where it creates the
> > remote.cache file, response time from the lpstat or lpr improves
> > dramatically. I'm not certain if there is a direct relation but that
> > appears to be the case.
>
> Hmm, that shouldn't make a difference...

Well, I'm really curious as to why it acts that way and so, I stopped
cupsd, deleted remote.cache, and restarted cupsd once more on both
AIX and Solaris clients. See the following:


Here, I'm monitoring cups and lpstat every two seconds:
while :;
do
ps -ef|grep -v grep|egrep "cups|lpstat"
sleep 2
done

On another session, I've started the lpstat command:
aixclient2:./cups> timex lpstat -p|wc
lpstat: Unknown

real 105.61
user 0.04
sys  0.02

       0       0       0

I've then CTRL-D when cupsd died. See the following:

...
rem 639080 667704   0 16:33:45  pts/4  0:00 lpstat -p
 rem 667704 450650   0 16:33:45  pts/4  0:00 timex lpstat -p
    cups 188600 553036   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    root 553036      1 109 15:46:32      -  1:52 /opt/TWWfsw/cups135/sbin/cupsd -c /etc/opt/TWWfsw/cups135/cupsd.conf
 rem 639080 667704   0 16:33:45  pts/4  0:00 lpstat -p
 rem 667704 450650   0 16:33:45  pts/4  0:00 timex lpstat -p
    cups 188600 553036   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    root 553036      1 114 15:46:32      -  1:54 /opt/TWWfsw/cups135/sbin/cupsd -c /etc/opt/TWWfsw/cups135/cupsd.conf
 rem 639080 667704   0 16:33:45  pts/4  0:00 lpstat -p
 rem 667704 450650   0 16:33:45  pts/4  0:00 timex lpstat -p
    cups 188600 553036   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    root 553036      1 120 15:46:32      -  1:56 /opt/TWWfsw/cups135/sbin/cupsd -c /etc/opt/TWWfsw/cups135/cupsd.conf
 rem 639080 667704   0 16:33:45  pts/4  0:00 lpstat -p
 rem 667704 450650   0 16:33:45  pts/4  0:00 timex lpstat -p
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631
    cups 188600      1   0 15:46:32      -  0:00 cups-polld cupserver1 631 3600 631


>From a 500MB of log, I removed the stuff and came out with the following:

ROOT @ AIXCLIENT2F # egrep -v "add_print|copy_attr|cupsdD|cupsdA" error_log
d [28/Feb/2008:16:33:46 +0600] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
d [28/Feb/2008:16:33:46 +0600] stringpool: 124703 strings, 347040 allocated, 2979144 total bytes
d [28/Feb/2008:16:33:46 +0600] cupsdReadClient: 7, used=0, file=-1 state=0
D [28/Feb/2008:16:33:46 +0600] cupsdReadClient: 7 POST / HTTP/1.1
d [28/Feb/2008:16:33:46 +0600] cupsdFindBest: uri = "/"...
d [28/Feb/2008:16:33:46 +0600] cupsdFindBest: best = NONE
d [28/Feb/2008:16:33:46 +0600] cupsdIsAuthorized: con->uri="/", con->best=0()
d [28/Feb/2008:16:33:46 +0600] POST /
d [28/Feb/2008:16:33:46 +0600] CONTENT_TYPE = application/ipp
d [28/Feb/2008:16:33:46 +0600] cupsdReadClient: 7 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=419, con->file=-1
d [28/Feb/2008:16:33:46 +0600] cupsdProcessIPPRequest(208be418[7]): operation_id = 4002
D [28/Feb/2008:16:33:46 +0600] CUPS-Get-Printers
d [28/Feb/2008:16:33:46 +0600] get_printers(208be418[7], 0)
d [28/Feb/2008:16:33:46 +0600] cupsdFindPolicyOp(p=2000eea8, op=4002(CUPS-Get-Printers))
d [28/Feb/2008:16:33:46 +0600] cupsdFindPolicyOp: Found wildcard match...
d [28/Feb/2008:16:33:46 +0600] cupsdIsAuthorized: con->uri="/", con->best=20012228((null))
d [28/Feb/2008:16:33:46 +0600] cupsdIsAuthorized: level=AUTH_ANON, type=None, satisfy=AUTH_SATISFY_ALL, num_names=0
d [28/Feb/2008:16:33:46 +0600] cupsdIsAuthorized: op=0(unknown-0000)
d [28/Feb/2008:16:33:46 +0600] cupsdIsAuthorized: auth=AUTH_ALLOW...



I also did the same with the Solaris 10 client, stopped cupsd, removed
the remote.cache, restarted cupsd, and then ran lpstat.

It's been 56minutes since I ran it and still going. The cupsd is still
running however.

solarisclient2# ps -ef|grep -i lpstat
    root 19472 19470   1 16:34:59 pts/1       0:56 lpstat -p
    root 19470 14627   0 16:34:59 pts/1       0:00 timex lpstat -p


The clients behaves this way only when remote.cache isn't there. How or
why that is, I don't know.

Anyway, that's all the SPAM I'll be doing today... :)

Thanks,
Angel