Re: named spinning

[Gary Duzan <gary%duzan.org@localhost>]

In Message <20111007005955.34EB89711D%rebar.astron.com@localhost>,
   christos%zoulas.com@localhost (Christos Zoulas)wrote:

=>On Oct 6,  8:49pm, gary%duzan.org@localhost (Gary Duzan) wrote:
=>-- Subject: Re: named spinning
=>
=>| 
=>| ===================================================================
=>| wheel { /usr/src/external/bsd/bind/lib/libisc } # 
/usr2/obj/external/bsd/bind/bin/named/named -f
=>| <>got: 0 of 1, ident: 5
=>| <>got: 0 of 1, ident: 5
=>| <>got: 0 of 1, ident: 5
=>| <
=>| ===================================================================
=>| 
=>| So it is just staying in kevent(), eating CPU.
=>| 
=>| 14090 root      34    0    86M   33M CPU/1      4:31 83.79% 83.79% named
=>| 
=>| Here is the fstat output:
=>| 
=>| ===================================================================
=>| wheel { /usr/src/external/bsd/bind/dist/lib/isc/unix } # fstat -p `pgrep 
named`
=>| USER     CMD          PID   FD MOUNT       INUM MODE         SZ|DV R/W
=>| root     named      14090   wd /        13992411 drwxr-xr-x     512 r 
=>| root     named      14090    0 /dev/pts       3 crw--w----   ttyp0 rw
=>| root     named      14090    1 /dev/pts       3 crw--w----   ttyp0 rw
=>| root     named      14090    2 /dev/pts       3 crw--w----   ttyp0 rw
=>| root     named      14090    3* unix dgram  <-> ffff80000e244980
=>| root     named      14090    4 /        13647756 crw-rw-rw-   3658,321633 rw
=>| root     named      14090    5* pipe 0xffff8000b8f0b7e0 <- 
0xffff8000948e12b8 rn
=>| root     named      14090    6* pipe 0xffff8000948e12b8 -> 
0xffff8000b8f0b7e0 w
=>| root     named      14090    4* kqueue pending 0
=>| root     named      14090    5* crypto 0xffff80000dc36f18
=>| root     named      14090    9 /        13648392 cr--r--r--   1438,320325 r 
=>| [ and the port 53 sockets ]
=>| ===================================================================
=>| 
=>|    Any more ideas what to look for? I think some of the other things
=>| I was seeing were artifacts of being in the debugger, which the
=>| printfs remove. I could try building a debugging libc on another
=>| box with the same current snapshot, but it wouldn't be my first
=>| choice.
=>
=>Yes 5 is crypto are you using DNSSEC? I don't see crypto on mine...
=>Now I suspect kevent is misbehaving with /dev/crypto. Let me cook
=>a kernel with crypto. In the meantime, can you remove /dev/crypto,
=>restart named, and see if it works?

   Actually, note that 5 is both crypto and pipe here, which is
odd. An fstat bug, maybe; lsof output seems more sane.  With
/dev/crypto renamed I get the same thing as before, with an fstat
of:

===================================================================
USER     CMD          PID   FD MOUNT       INUM MODE         SZ|DV R/W
root     named      18674   wd /        13992411 drwxr-xr-x     512 r
root     named      18674    0 /dev/pts       9 crw-------   ttyp3 rw
root     named      18674    1 /dev/pts       9 crw-------   ttyp3 rw
root     named      18674    2 /dev/pts       9 crw-------   ttyp3 rw
root     named      18674    3* unix dgram  <-> ffff80000e244980
root     named      18674    4 /        13647756 crw-rw-rw-   3674,321743 rw
root     named      18674    5* pipe 0xffff8000b8f0b7e0 <- 0xffff8000577cda18 rn
root     named      18674    6* pipe 0xffff8000577cda18 -> 0xffff8000b8f0b7e0 w
root     named      18674    4* kqueue pending 0
root     named      18674    8 /        13648392 cr--r--r--   1438,320325 r
===================================================================

and an lsof of:

===================================================================
COMMAND   PID USER   FD     TYPE             DEVICE SIZE/OFF     NODE NAME
named   18674 root    0u    VCHR                5,3    0t657        9 /dev/pts/3
named   18674 root    1u    VCHR                5,3    0t657        9 /dev/pts/3
named   18674 root    2u    VCHR                5,3    0t657        9 /dev/pts/3
named   18674 root    3u    unix 0xffff80000e39eb70      0t0          
->0xffff80000e09eb68
named   18674 root    4u    VCHR                2,2      0t0 13647756 /dev/null
named   18674 root    5r    PIPE 0xffff8000b8f0b7e0    16384          
->0xffff8000577cda18
named   18674 root    6w    PIPE 0xffff8000577cda18        0          
->0xffff8000b8f0b7e0
named   18674 root    7u  KQUEUE 0xffff800057944380
named   18674 root    8r    VCHR               46,0      0t0 13648392 
/dev/random
===================================================================

   I'm still getting an ident of 5, so it is definitely talking to
the pipe. No other process has the other end of the pipe, so it is
only talking to itself. And when it goes loopy it clearly isn't
talking to anyone, since there is no read/write activity in the
ktruss output.

===================================================================
wheel { ~ } # ktruss -p `pgrep named` | egrep -v 
'___lwp_park50|__gettimeofday50|_lwp_unpark'
 18674      6 named    emul(netbsd)
===================================================================

   I do get lots of other activity if I run it under ktruss from
the beginning, but nothing with the above filter once it settles
down.

                                        Gary Duzan