thr3ads.net - samba - [Samba] Also seeing high winbindd CPU usage [Aug 2008]

If this information is useful, please help other people find it:
Share via:

David Eisner

2008-Aug-05 21:01 UTC

[Samba] Also seeing high winbindd CPU usage

I think somebody had a similar problem (also on Solaris), but that
thread seemed to die.

I've compiled (with Sun Studio cc) and installed samba-3.2.1 on a
Solaris 10 x64 box, which is a member of a (Windows Server 2003
controlled) domain.  I previously had samba 3.0.28a running on the
same machine without any problems.  Now winbindd is eating up all of
the CPU (on the CPU it's assigned to).

I configured samba like so:

  ./configure --prefix=/usr/local/samba-3.2.1  --with-ads --with-pam
--with-acl-support \
     --with-shared-modules=idmap_ad  --enable-socket-wrapper
--enable-nss-wrapper --with-krb5=/usr/local/heimdal/heimdal-1.1

I successfully built it, and it passed 'make test', too.  Then I
installed it (into a new location).  Rather than copy over the
secrets.tdb, I repeated the net ads join, which succeeded.  'net ads
testjoin' tells me the 'Join is OK.'

However, when I tried wbinfo -u, it just hung.  Then I noticed
winbindd was eating up CPU.  Actually, it appears to have PANIC'd and
crashed just now.  Here's the winbindd log:

[2008/08/05 16:12:09,  0] winbindd/winbindd.c:(1126)
  winbindd version 3.2.1 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2008
[2008/08/05 16:20:29,  0] winbindd/winbindd.c:(1126)
  winbindd version 3.2.1 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2008
[2008/08/05 16:20:29,  0] winbindd/winbindd_cache.c:(2353)
  initialize_winbindd_cache: clearing cache and re-creating with
version number 1
[2008/08/05 16:21:24,  0] winbindd/winbindd.c:(632)
  request_len_recv: Invalid request size received: 2088 (expected 2096)
[2008/08/05 16:35:42,  0] winbindd/winbindd.c:(632)
  request_len_recv: Invalid request size received: 2088 (expected 2096)
[2008/08/05 16:35:42,  0] winbindd/winbindd.c:(632)
  request_len_recv: Invalid request size received: 2088 (expected 2096)
[2008/08/05 16:35:42,  0] winbindd/winbindd.c:(632)
  request_len_recv: Invalid request size received: 2088 (expected 2096)
[2008/08/05 16:37:42,  0] winbindd/winbindd_dual.c:(272)
  PANIC: assert failed at winbindd/winbindd_dual.c(272):
cache_retrieve_response(state->child_pid, state->response)
[2008/08/05 16:37:42,  0] winbindd/winbindd_util.c:(275)
  Got invalid trustdom response
[2008/08/05 16:40:02,  0] winbindd/winbindd.c:(632)
  request_len_recv: Invalid request size received: 2088 (expected 2096)
[2008/08/05 16:42:42,  0] lib/fault.c:(40)
  ==============================================================[2008/08/05
16:42:42,  0] lib/fault.c:(41)
  INTERNAL ERROR: Signal 6 in pid 20965 (3.2.1)
  Please read the Trouble-Shooting section of the Samba3-HOWTO
[2008/08/05 16:42:42,  0] lib/fault.c:(43)

  From: http://www.samba.org/samba/docs/Samba3-HOWTO.pdf
[2008/08/05 16:42:42,  0] lib/fault.c:(44)
  ==============================================================[2008/08/05
16:42:42,  0] lib/util.c:(1666)
  PANIC (pid 20965): internal error
[2008/08/05 16:42:42,  0] lib/util.c:(1820)
  unable to produce a stack trace on this platform
[2008/08/05 16:42:42,  0] lib/fault.c:(201)
  dumping core in /usr/local/samba-3.2.1/var/cores/winbindd

I restarted winbindd just now, same story.  Here's the truss output.
It looks like this, repeated:

...
time()                                          = 1217969117
pollsys(0x08047710, 4, 0x080477F0, 0x00000000)  = 1
write(16, " 0\b\0\013\0\0\0\0\0\0\0".., 2096)   = 2096
time()                                          = 1217969117
brk(0x0DA3EC28)                                 = 0
brk(0x0DA40C28)                                 = 0
pollsys(0x08047710, 4, 0x080477F0, 0x00000000)  = 1
read(16, "02\0\0\0", 4)                         = 4
fcntl(12, F_SETLKW64, 0x080475E4)               = 0
fcntl(12, F_SETLKW64, 0x08047664)               = 0
fcntl(12, F_SETLKW64, 0x080475E4)               = 0
fcntl(12, F_SETLKW64, 0x08047664)               = 0
fcntl(12, F_SETLKW64, 0x080475F4)               = 0
fcntl(12, F_SETLK64, 0x08047644)                = 0
fcntl(12, F_SETLK64, 0x08047644)                = 0
fcntl(12, F_SETLKW64, 0x08047594)               = 0
fcntl(12, F_SETLKW64, 0x080475D4)               = 0
fcntl(12, F_SETLKW64, 0x08047674)               = 0
fcntl(12, F_SETLKW64, 0x080475F4)               = 0
fcntl(12, F_SETLK64, 0x08047644)                = 0
fcntl(12, F_SETLK64, 0x08047644)                = 0
fcntl(12, F_SETLKW64, 0x08047594)               = 0
fcntl(12, F_SETLKW64, 0x080475D4)               = 0
fcntl(12, F_SETLKW64, 0x08047674)               = 0
fcntl(12, F_SETLKW64, 0x080475E4)               = 0
fcntl(12, F_SETLKW64, 0x08047664)               = 0
time()                                          = 1217969117
pollsys(0x08047710, 4, 0x080477F0, 0x00000000)  = 1
write(16, " 0\b\0\013\0\0\0\0\0\0\0".., 2096)   = 2096
time()                                          = 1217969117
pollsys(0x08047710, 4, 0x080477F0, 0x00000000)  = 1
read(16, "02\0\0\0", 4)                         = 4
fcntl(12, F_SETLKW64, 0x080475E4)               = 0
brk(0x0DA40C28)                                 = 0
brk(0x0DA42C28)                                 = 0
fcntl(12, F_SETLKW64, 0x08047664)               = 0
fcntl(12, F_SETLKW64, 0x080475E4)               = 0
fcntl(12, F_SETLKW64, 0x08047664)               = 0
fcntl(12, F_SETLKW64, 0x080475F4)               = 0
...

Though it's spinning its wheels, so far this is the entirety of the
winbindd log after restarting it just now:

[2008/08/05 16:44:59,  0] winbindd/winbindd.c:(1126)
  winbindd version 3.2.1 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2008
[2008/08/05 16:44:59,  0] winbindd/winbindd_cache.c:(2353)
  initialize_winbindd_cache: clearing cache and re-creating with
version number 1

Finally, here's the setup:

[global]
        unix charset = LOCALE
        workgroup = OURDOMAIN
        realm = OURDOMAIN.UMD.EDU
        server string = OUR Samba Server
        security = ADS
        allow trusted domains = No
        use kerberos keytab = Yes
        log level = 1
        syslog = 0
        log file = /usr/local/samba-current/var/log.%m
        printcap name = CUPS
        dns proxy = No
        idmap domains = OURDOMAIN
        idmap alloc backend = tdb
        template homedir = /home/windows/%D/%U
        template shell = /bin/bash
        winbind cache time = 0
        winbind enum users = Yes
        winbind enum groups = Yes
        winbind use default domain = Yes
        winbind nss info = rfc2307
        idmap alloc config:range = 5000 - 9999
        idmap config OURDOMAIN:range = 10000 - 300000000
        idmap config OURDOMAIN:schema_mode = rfc2307
        idmap config OURDOMAIN:default = yes
        idmap config OURDOMAIN:backend = ad
        hosts allow = XXX.Y., ZZZ.X., 127.
        cups options = raw

[homes]
        comment = Home Directories
        valid users = %D\%U
        read only = No
        browseable = No

[printers]
        comment = All Printers
        path = /var/spool/samba
        printable = Yes
        browseable = No

[voltest]
        comment = DELOS www
        path = /path/to/share/dir
        admin users = OURDOMAIN\administrator
        read only = No
        inherit acls = Yes
        map acl inherit = Yes
        store dos attributes = Yes


Is this potentially a known bug?

-David

-- 
David Eisner http://cradle.brokenglass.com

David Eisner

2008-Aug-08 17:22 UTC

head link

[Samba] Re: Also seeing high winbindd CPU usage

On Tue, Aug 5, 2008 at 5:01 PM, David Eisner <deisner@gmail.com>
wrote:> I've compiled (with Sun Studio cc) and installed samba-3.2.1 on a
> Solaris 10 x64 box, which is a member of a (Windows Server 2003
> controlled) domain.  I previously had samba 3.0.28a running on the
> same machine without any problems.  Now winbindd is eating up all of
> the CPU (on the CPU it's assigned to).
...> Is this potentially a known bug?

Guess not.  Here's some more information.  First, this is what I see with
top:

   PID USERNAME LWP PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
  2005 root       1  20    0  231M  221M cpu/1    2:46 49.96% winbindd
  2006 root       1  54    0   17M 6792K sleep    0:26  3.87% winbindd


First some poor man's profiling: When I attach a debugger to the
parent process (pid 2005), and suspend it, the stack typically looks
like this:

(dbx) where
current thread: t@1
  [1] __pollsys(0x8047550, 0x4, 0x8047630, 0x0), at 0xfe8f51d7
  [2] _pollsys(0x8047550, 0x4, 0x8047630, 0x0), at 0xfe8e98a4
  [3] _pselect(0x11, 0x8047750, 0x80477d0, 0xfe920318, 0x8047630,
0x0), at 0xfe8a317a
  [4] _select(0x11, 0x8047750, 0x80477d0, 0x0, 0x8047850), at 0xfe8a3470
=>[5] sys_select(maxfd = 17, readfds = 0x8047750, writefds 0x80477d0,
errorfds = (nil), tval = 0x8047850), line 93 in "select.c"
  [6] process_loop(), line 911 in "winbindd.c"
  [7] main(argc = 2, argv = 0x8047b60, envp = 0x8047b6c), line 1283 in
"winbindd.c"
(dbx)

[I could only get dbx to work -- gdb complained and dumped core].

And when I attach to the child process, which uses less CPU, I see this:

(dbx) where
current thread: t@1
  [1] __pollsys(0x8045b50, 0x2, 0x0, 0x0), at 0xfe8f51d7
  [2] _pollsys(0x8045b50, 0x2, 0x0, 0x0), at 0xfe8e98a4
  [3] _pselect(0x12, 0x80473a8, 0xfe920318, 0xfe920318, 0x0, 0x0), at
0xfe8a317a
  [4] _select(0x12, 0x80473a8, 0x0, 0x0, 0x0), at 0xfe8a3470
=>[5] sys_select(maxfd = 18, readfds = 0x80473a8, writefds = (nil),
errorfds = (nil), tval = (nil)), line 93 in "select.c"
  [6] fork_domain_child(child = 0x885a2fc), line 1178 in
"winbindd_dual.c"
  [7] schedule_async_request(child = 0x885a2fc), line 297 in
"winbindd_dual.c"
  [8] async_request(mem_ctx = 0x8854a78, child = 0x885a2fc, request 0x88535f0,
response = 0x885b170, continuation = 0x815c810
&`winbindd`winbindd_util.c`init_child_recv(void *private_data, _Bool
success), private_data = 0x8853e58), line 141 in "winbindd_dual.c"
  [9] init_child_connection(domain = 0x8859d38, continuation 0x8193f60 =
&`winbindd`winbindd_dual.c`domain_init_recv(void
*private_data_data, _Bool success), private_data = 0x88596f0), line
573 in "winbindd_util.c"
  [10] async_domain_request(mem_ctx = 0x8856570, domain = 0x8859d38,
request = 0x88524a0, response = 0x885a390, continuation = 0x815b74c
&`winbindd`winbindd_util.c`trustdom_recv(void *private_data, _Bool
success), private_data_data = 0x8856930), line 359 in
"winbindd_dual.c"
  [11] add_trusted_domains(domain = 0x8859d38), line 249 in
"winbindd_util.c"
  [12] rescan_trusted_domains(), line 510 in "winbindd_util.c"
  [13] process_loop(), line 862 in "winbindd.c"
  [14] main(argc = 2, argv = 0x8047b60, envp = 0x8047b6c), line 1283
in "winbindd.c"


By the way, this is with samba recompiled with debugging enabled and
no optimization.

I'll continue slogging through the code, but if anybody can tell from
this where the problem might be, please let me know.  Thanks.

-David

-- 
David Eisner http://cradle.brokenglass.com

Reasonably Related Threads

Search for more apparently analagous threads

samba - Aug 2008 - Also seeing high winbindd CPU usage

[Samba] Also seeing high winbindd CPU usage

[Samba] Re: Also seeing high winbindd CPU usage

Reasonably Related Threads