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.
>

Just a quick update on "LogLevel info" without remote.cache:

# timex lpstat -p|wc

real     2:18.04
user     1:27.42
sys         9.66

    2708   29788  167960


And, "LogLevel info" with cache:
# timex lpstat -p|wc

real        3.67
user        2.95
sys         0.09

    2708   29788  167960