-----Original Message-----
From: Cochran, Wayne Owen
Sent: Wed 10/22/2008 6:04 PM
To: Jeremy Allison
Cc: Lang, Dick
Subject: Re: [Samba] smbd high cpu load
On Oct 22, 2008, at 4:06 PM, Jeremy Allison wrote:
> On Wed, Oct 22, 2008 at 03:27:10PM -0700, Wayne Cochran wrote:
>> We have a Linux file server for a set of computer science and
>> engineering
>> labs where each lab contains machines running Mac OS X, Ubuntu Linux,
>> or some incarnation of Windows. At times the these machines become
>> almost unusable and I think I have narrowed the problem to smbd
>> processes
>> soaking up all the CPU on the server. Running 'top' on the
server
>> reveals a dozen or so entries like the following:
>>
>> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
>> 18229 millerbr 20 0 12420 3980 2992 R 26 0.1 0:03.85 smbd
>> 18225 tande8 20 0 12380 3564 2660 S 22 0.1 1:00.19 smbd
>> 18861 dhenniga 20 0 12676 4316 3328 R 7 0.1 0:01.86 smbd
>> 18210 samcprui 20 0 12616 4064 3128 S 3 0.1 0:55.84 smbd
>> 18214 mlhorn 20 0 12568 3912 3060 S 3 0.1 0:25.23 smbd
>> 18867 tsze 20 0 12784 4656 3592 S 3 0.1 0:10.28 smbd
>> 18728 daflores 20 0 12684 4560 3516 S 2 0.1 0:35.44 smbd
>> 18678 twharris 20 0 12780 4556 3552 S 1 0.1 0:11.35 smbd
>> ...
>>
>> Looking through the log files reveals nothing obvious at first
>> glance,
>> but of course
>> I am not sure what to look for and there are a lot of log files.
>>
>> What steps should I first take to debug the situation?
>
> What version of Samba are you running on this server ?
# smbd -V
Version 3.0.28a
>
> What is the operating system on the server ?
# uname -a
Linux queenbee 2.6.24-19-server #1 SMP Wed Aug 20 23:54:28 UTC 2008
i686 GNU/Linux
# cat /etc/issue
Ubuntu 8.04.1 \n \l>
>
> What does tracing the smbd execution with strace, or
> ptrace say when smbd is spinning like this ?
>
Excellent idea.
# strace -p20121 >& /tmp/ppp.txt
^C
I ran this just for a few seconds and got *lots* of data:
# wc -l /tmp/ppp.txt
7001 /tmp/ppp.txt
I'll give some (hopefully) interesting samples:
Process 20121 attached - interrupt to quit
read(25, "\0\0\0\252", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\334"..., 170) =
170
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
open("My Documents", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|
0x80000) = 20
fstat64(20, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
close(20) = 0
write(25, "\0\0\0\340\377SMB2\0\0\0\0\210A
\310\0\0\0\0\0\0\0\0\0\0"..., 228) = 228
gettimeofday({1224723309, 946984}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0\244", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\334"..., 164) =
164
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355f4) = 0
write(25, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
gettimeofday({1224723309, 950980}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0\244", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\334"..., 164) =
164
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355f4) = 0
write(25, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
gettimeofday({1224723309, 954923}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0\256", 4) = 4
read(25, "\377SMB\242\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5"...,
174) = 174
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
gettimeofday({1224723309, 957020}, NULL) = 0
fcntl64(13, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa35ba4) = 0
fcntl64(8, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfa35aa4) = 0
fcntl64(8, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfa35aa4) = 0
...
read(25, "\0\0\0\244", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\334"..., 164) =
164
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355f4) = 0
write(25, "\0\0\0T\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
88) = 88
gettimeofday({1224723310, 72216}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0\244", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\334"..., 164) =
164
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355f4) = 0
write(25, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
gettimeofday({1224723310, 83503}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0\256", 4) = 4
read(25, "\377SMB\242\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5"...,
174) = 174
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
gettimeofday({1224723310, 97286}, NULL) = 0
fcntl64(13, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa35ba4) = 0
open("My Documents/The Picture of Dorian Grey.rtf", O_RDONLY|
O_LARGEFILE) = 20
flock(20, 0x60 /* LOCK_??? */) = 0
fcntl64(20, F_SETSIG, 0x23) = 0
fcntl64(20, 0x400 /* F_??? */, 0x1) = -1 EAGAIN (Resource
temporarily unavailable)
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa35b34) = 0
write(25, "\0\0\0\207\377SMB
\242\0\0\0\0\210\1\310\0\0\0\0\0\0\0\0"..., 139) = 139
gettimeofday({1224723310, 105969}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0H", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\334"..., 72) =
72
fstat64(20, {st_mode=S_IFREG|0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355f4) = 0
...
I note the string "My Documents/The Picture of Dorian Grey.rtf" keeps
coming up....
# grep Dorian /tmp/ppp.txt | wc -l
518
...
read(25, "\0\0\0\244", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\310"..., 164) =
164
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
write(25, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
gettimeofday({1224723310, 184355}, NULL) = 0
select(29, [5 25 28], [], NULL, {60, 0}) = 1 (in [25], left {60, 0})
read(25, "\0\0\0\244", 4) = 4
read(25,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\5\0\310"..., 164) =
164
stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa355d4) = 0
write(25, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
...
tat64("My Documents/The Picture of Dorian Grey.rtf", {st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
gettimeofday({1224723310, 637525}, NULL) = 0
fcntl64(13, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=37704,
len=1}, 0xbfa35ba4) = 0
fcntl64(8, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfa35aa4) = 0
fcntl64(8, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfa35aa4) = 0
geteuid32() = 30056
getuid32() = 30056
geteuid32() = 30056
setresuid32(0, 0, -1) = 0
geteuid32() = 0
kill(20121, SIGUSR1) = 0
--- SIGUSR1 (User defined signal 1) @ 0 (0) ---
write(21, "\n", 1) = 1
sigreturn() = ? (mask now [FPE USR2 PIPE])
setresuid32(30056, 30056, -1) = 0
geteuid32() = 30056
getuid32() = 30056
**lots** more where that came from -- you probably don't want we to
paste it all
Any ideas of where to from here....
-THANKS!
> Jeremy.
Wayne O. Cochran
Clinical Assistant Professor, Computer Science
Washington State University Vancouver
wcochran@vancouver.wsu.edu
http://ezekiel.vancouver.wsu.edu/~wayne