CUPS 1.3.6 - performance issue in Solaris

[angelb]

Here are some stats of CUPS 1.3.6 running in Solaris.

First, a brief stats on CUPS 1.3.5 followed by CUPS 1.3.6.

CUPS 1.3.5:

# grep VERSION cups-config
VERSION="1.3.5"
APIVERSION="1.3"

With LogLevel debug2:
# grep LogLevel cupsd.conf
LogLevel debug2

# timex lpstat -p|wc

real       22.88
user        3.07
sys         0.11

    2708   29788  167960

With LogLevel info:
# grep LogLevel cupsd.conf
LogLevel info

# timex lpstat -p|wc

real        3.69
user        2.97
sys         0.09

    2708   29788  167960


CUPS 1.3.6:
# grep VERSION cups-config
VERSION="1.3.6"
APIVERSION="1.3"

With LogLevel debug2:
sapts01f# grep LogLevel cupsd.conf
LogLevel debug2

# timex lpstat -p|wc
Command terminated abnormally.    <---- I've control-break out

real    14:10.63  <---- running for 14minutes
user       18.87
sys         3.75

Executing truss while lpstat is running, it looks like it's stuck in a
loop:

...
brk(0x052E2780)                                 = 0
brk(0x052E4780)                                 = 0
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
brk(0x052E4780)                                 = 0
brk(0x052E6780)                                 = 0
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
time()                                          = 1206482265
recv(5, " I\017 d o c u m e n t -".., 2048, 0)  = 2028
brk(0x052E6780)                                 = 0
brk(0x052E8780)                                 = 0
...


Stop cupsd and then restart to create the remote.cache file,
the lpstat then completed sooner(not faster):

# /etc/abinit.d/cups stop
Stopping the CUPS IPP Print System.

# /etc/abinit.d/cups start
CUPS IPP Print System starting.
#
# timex lpstat -p|wc

real       23.11
user        3.01
sys         0.10


With LogLevel info:
# grep LogLevel cupsd.conf
LogLevel info

# timex lpstat -p|wc

real        3.70
user        2.98
sys         0.09

    2708   29788  167960


Conclusion:
CUPS 1.3.6 appears to have the same issues I've encountered in CUPS
1.3.5. Two unrelated objects appears to affect CUPS 1.3 performance
and they are the remote.cache and LogLevel.

When a client starts for the first time, and LogLevel is set at debug2,
and the client have completed polling server for the printers list,
when running an lpstat, it goes into what appears to be a loop.
However, after stoping and starting cupsd, it creates the remote.cache
file and then the lpstat command comes back after ~23seconds.

Now, when LogLevel is set to info(whether remote.cache exist or not),
the lpstat command comes bakup after ~3seconds.


I have another Solaris system that I'll be testing CUPS 1.3.6 and see
if I can duplicate the issues. I'm not optimistic CUPS 1.3.6 will be
any different since I've installed CUPS 1.3.5 on both Solaris boxes,
they both had the same issues.


Thanks,
Angel