cupsd accumulate CPU

[angelb]

Hello all;

Here, I'm testing CUPS 1.2.2. The following shows what I've observed
while testing two servers(RedHat and AIX) and a client(AIX).

The client polls the two servers every 15 minutes. And I have about
1168 printer queues.

When cups-polld does its poll, the CPU idle goes from mid-high 90s
to mid-high 80s. During that interval, error_log would log
cupsdNetIFUpdate 10 times(1 entry every minute) and seconds after the
last entry, CPU use will go back to normal. And when polling cycle
starts again, same thing happens; CPU idle goes down and CPU cycle
accumulates.

See the following:

ROOT @ SAPTI02 # ps -ef|grep -i cups
    cups 692374 774144   0 15:32:20      -  0:00 cups-polld occam002 631 900 631

    root 774144      1  10 15:32:19      -  1:12 /opt/TWWfsw/cups122/sbin/cupsd
-c /etc/opt/TWWfsw/cups122/cupsd.conf
    cups 831562 774144   0 15:32:20      -  0:00 cups-polld occam503 631 900 631
 ...

ROOT @ SAPTI02 # ps -ef|grep -i cups
    cups 692374 774144   0 15:32:20      -  0:00 cups-polld occam002 631 900 631

    root 774144      1   7 15:32:19      -  1:22 /opt/TWWfsw/cups122/sbin/cupsd
-c /etc/opt/TWWfsw/cups122/cupsd.conf
    cups 831562 774144   0 15:32:20      -  0:00 cups-polld occam503 631 900 631

Since I restarted cupsd, cupsd has accumulated about 4minutes and
48seconds of CPU time. I'm not quite sure yet if that will have
an impact in production(in production, CPU idles at mid 80s w/o cups).


tail -100 error_log:
...
D [31/Jul/2006:16:19:26 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:20:26 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:21:26 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:22:26 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:28:27 +0600] [cups-polld occam503:631] Found 1168 printers.
D [31/Jul/2006:16:28:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:28:30 +0600] [cups-polld occam002:631] Found 1168 printers.
D [31/Jul/2006:16:29:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:30:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:31:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:32:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:33:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:34:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:35:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:36:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:37:27 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:43:30 +0600] [cups-polld occam503:631] Found 1168 printers.
D [31/Jul/2006:16:43:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:43:33 +0600] [cups-polld occam002:631] Found 1168 printers.
D [31/Jul/2006:16:44:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:45:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:46:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:47:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:48:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:49:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:50:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:51:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:52:30 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:58:32 +0600] [cups-polld occam503:631] Found 1168 printers.
D [31/Jul/2006:16:58:32 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:16:58:35 +0600] [cups-polld occam002:631] Found 1168 printers.
D [31/Jul/2006:16:59:32 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:17:00:32 +0600] cupsdNetIFUpdate: "en4" = sapti02...
D [31/Jul/2006:17:01:32 +0600] cupsdNetIFUpdate: "en4" = sapti02...

ROOT @ SAPTI02 # dbx -a 774144
Waiting to attach to process 774144 ...
Successfully attached to cupsd.
stopped in select at 0xd026d264
0xd026d264 (select+0x90) 80410014        lwz   r2,0x14(r1)
(dbx) where
select(??, ??, ??, ??, ??) at 0xd026d264
main() at 0x10000b68

ROOT @ SAPTI02 # dbx -a 692256
Waiting to attach to process 692256 ...
Successfully attached to cups-polld.
stopped in raise.nsleep [/usr/lib/libc.a] at 0xd01f6d14
0xd01f6d14 (nsleep+0xbc) 80410014        lwz   r2,0x14(r1)
(dbx) where
raise.nsleep(??, ??) at 0xd01f6d14
sleep.sleep(??) at 0xd0201c74
poll_server() at 0x10000b24
main() at 0x100005c8

ROOT @ SAPTI02 # dbx -a 774278
Waiting to attach to process 774278 ...
Successfully attached to cups-polld.
stopped in raise.nsleep [/usr/lib/libc.a] at 0xd01f6d14
0xd01f6d14 (nsleep+0xbc) 80410014        lwz   r2,0x14(r1)
(dbx) where
raise.nsleep(??, ??) at 0xd01f6d14
sleep.sleep(??) at 0xd0201c74
poll_server() at 0x10000b24
main() at 0x100005c8
(dbx) detach

Since the client is only a test system, nothing's really going on
here and so CPU idle is always on the high 90s. The positive side
of this is that the client cups-polld stays alive. While in CUPS
1.2.1, cups-polld crashes.

I would like to know if anyone else has done a simillar testing.
Tomorrow, I will add a Solaris client.

Thanks,
Angel