samba - Oct 2008 - high cpu load

I think I have narrowed down the problem why smbd processes are soaking
up so much CPU on our file server. Here are some selected samples from
strace output as I attached to the offending smbd process:

Culprit #1

I took three sample snapshots, each lasted for several seconds, and I  
took them
minutes apart from each other.  I noticed many lines involved stat'ing  
the
a single file in the 'My Documents' subdirectory:

stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
0744, st_size=0, ...}) = 0
utimes("My Documents/The Picture of Dorian Grey.rtf", {1224548572, 0})
= 0

To see the frequency of these I grep'ed and use wc -l to get a line  
count:

# grep 'stat64("My Documents/The Picture of Dorian Grey.rtf"'
/tmp/
qqq.txt | wc -l
462
# grep 'stat64("My Documents/The Picture of Dorian Grey.rtf"'
/tmp/
rrr.txt | wc -l
1065
s# grep 'stat64("My Documents/The Picture of Dorian Grey.rtf"'
/tmp/
ppp.txt | wc -l
429

Thousands of times this file is being stat'ed!?!?

Culprit #2 : some small samples from strace:

read(5, "\0\0\0H", 4)                   = 4
read(5,  
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\4\0\230"..., 72) =
72
stat64(".windows_settings/Application Data/SolidWorks 2008/Scheduler_2/ 
swbo1.mdb", {st_mode=S_IFREG|0744, st_size=974848, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=25416,  
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=25416,  
len=1}, 0xbfa355f4) = 0
write(5, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
gettimeofday({1224788202, 767660}, NULL) = 0
select(30, [5 21 29], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
read(5, "\0\0\0)", 4)                   = 4

tat64("My Documents", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=17928,  
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=17928,  
len=1}, 0xbfa355f4) = 0
write(5, "\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
104) = 104
gettimeofday({1224788207, 113052}, NULL) = 0
select(30, [5 21 29], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
read(5, "\0\0\0f", 4)                   = 4
read(5, "\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\4\0L"...,  
102) = 102
stat64("My Documents", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=17928,  
len=1}, 0xbfa355d4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=17928,  
len=1}, 0xbfa355f4) = 0
write(5, "\0\0\0t\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
120) = 120
gettimeofday({1224788207, 117652}, NULL) = 0
select(30, [5 21 29], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
read(5, "\0\0\0p", 4)                   = 4
read(5, "\377SMB\242\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\4"...,  
112) = 112
stat64("My Documents", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
gettimeofday({1224788207, 120639}, NULL) = 0
fcntl64(13, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=17928,  
len=1}, 0xbfa35ba4) = 0
fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=17928,  
len=1}, 0xbfa35b34) = 0
stat64("My Documents", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
gettimeofday({1224788207, 122416}, NULL) = 0

Why is "My Documents" being stat'ed and read so much!?!?!

Lets see what's in this directory:

# pwd
/home/yongffa/My Documents


Almost a gigabyte of stuff?

# ls -l
total 29380
drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-11 15:05 ??? 
? ?? ??
-rwxr--r-- 1 yongffa Domain Users  3259699 2008-08-14 17:16  
ALZip_eng_632.exe
drwxr-xr-x 2 yongffa Domain Users     4096 2008-01-29 11:38 ansys
drwxr-xr-x 2 yongffa Domain Users     4096 2008-09-29 21:45 conver3k
-rwxr--r-- 1 yongffa Domain Users   109977 2008-09-29 21:45 conver3k.zip
-rwxr--r-- 1 yongffa Domain Users     1658 2008-03-27 16:39 Default.rdp
-rwxr--r-- 1 yongffa Domain Users       78 2008-10-21 10:47 desktop.ini
drwxr-xr-x 3 yongffa Domain Users     4096 2008-04-15 20:06  
fesafe.version.5.3
-rwxr--r-- 1 yongffa Domain Users   824519 2008-09-29 21:35  
free_converter_setup.exe
-rwxr--r-- 1 yongffa Domain Users    32768 2008-06-25 12:31  
helium.vancouver.wsu.edu-00000001.pst
drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-14 18:26 MATLAB
drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-21 10:48 My Music
drwxr-xr-x 3 yongffa Domain Users     4096 2008-10-21 10:48 My Pictures
drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-25 12:46 My Videos
drwxr-xr-x 2 yongffa Domain Users     4096 2008-04-25 17:54  
Our.Finest.Hour.2008.DVDRip.x264.AC3.iNT-DG
-rwxr--r-- 1 yongffa Domain Users    32768 2008-08-04 16:29 outlook.pst
-rwxr--r-- 1 yongffa Domain Users 25739264 2008-06-28 06:01 Personal  
Folders(1).pst
root@queenbee:/home/yongffa/My Documents# du -sk .
971504	.


# ls -lR | more
total 29380
drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-11 15:05 ??? 
? ?? ??
-rwxr--r-- 1 yongffa Domain Users  3259699 2008-08-14 17:16  
ALZip_eng_632.exe
drwxr-xr-x 2 yongffa Domain Users     4096 2008-01-29 11:38 ansys
drwxr-xr-x 2 yongffa Domain Users     4096 2008-09-29 21:45 conver3k
-rwxr--r-- 1 yongffa Domain Users   109977 2008-09-29 21:45 conver3k.zip
-rwxr--r-- 1 yongffa Domain Users     1658 2008-03-27 16:39 Default.rdp
-rwxr--r-- 1 yongffa Domain Users       78 2008-10-21 10:47 desktop.ini
drwxr-xr-x 3 yongffa Domain Users     4096 2008-04-15 20:06  
fesafe.version.5.3
-rwxr--r-- 1 yongffa Domain Users   824519 2008-09-29 21:35  
free_converter_setup.exe
-rwxr--r-- 1 yongffa Domain Users    32768 2008-06-25 12:31  
helium.vancouver.wsu.edu-00000001.pst
drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-14 18:26 MATLAB
drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-21 10:48 My Music
drwxr-xr-x 3 yongffa Domain Users     4096 2008-10-21 10:48 My Pictures
drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-25 12:46 My Videos
drwxr-xr-x 2 yongffa Domain Users     4096 2008-04-25 17:54  
Our.Finest.Hour.2008.DVDRip.x264.AC3.iNT-DG
-rwxr--r-- 1 yongffa Domain Users    32768 2008-08-04 16:29 outlook.pst
-rwxr--r-- 1 yongffa Domain Users 25739264 2008-06-28 06:01 Personal  
Folders(1).pst

./???? ?? ??:
total 848532
-rwxr--r-- 1 yongffa Domain Users   5035651 2008-01-31 15:05  
loding206mpa-relaxation-ellipse-crack-1mm-06mm-Al2024-0114.inp
-rwxr--r-- 1 yongffa Domain Users 862866940 2008-01-31 14:08  
relaxation-ellipse-Al2024-comp-bogang-bojo.odb
-rwxr--r-- 1 yongffa Domain Users    125952 2008-01-31 16:25 SsCx- 
ellipse-1mm-06mm-al2024-jan23.xls

./ansys:
total 4
-rwxr--r-- 1 yongffa Domain Users 818 2008-01-29 11:38 STATUS.lis
<snip>

Is this always being read every friggin' time they log in!?!?!

Any ideas on what is going on here!?!?

--w
Wayne O. Cochran
Clinical Assistant Professor, Computer Science
Washington State University Vancouver
wcochran@vancouver.wsu.edu
http://ezekiel.vancouver.wsu.edu/~wayne

> Why is "My Documents" being stat'ed and read so much!?!?!
>
> Lets see what's in this directory:
>
> # pwd
> /home/yongffa/My Documents
>
>
> Almost a gigabyte of stuff?
>
> # ls -l
> total 29380
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-11 15:05 ³×ÀÌÆ®¿Â ¹ÞÀº
ÆÄÀÏ
> -rwxr--r-- 1 yongffa Domain Users  3259699 2008-08-14 17:16
> ALZip_eng_632.exe
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-01-29 11:38 ansys
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-09-29 21:45 conver3k
> -rwxr--r-- 1 yongffa Domain Users   109977 2008-09-29 21:45 conver3k.zip
> -rwxr--r-- 1 yongffa Domain Users     1658 2008-03-27 16:39 Default.rdp
> -rwxr--r-- 1 yongffa Domain Users       78 2008-10-21 10:47 desktop.ini
> drwxr-xr-x 3 yongffa Domain Users     4096 2008-04-15 20:06
> fesafe.version.5.3
> -rwxr--r-- 1 yongffa Domain Users   824519 2008-09-29 21:35
> free_converter_setup.exe
> -rwxr--r-- 1 yongffa Domain Users    32768 2008-06-25 12:31
> helium.vancouver.wsu.edu-00000001.pst
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-14 18:26 MATLAB
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-21 10:48 My Music
> drwxr-xr-x 3 yongffa Domain Users     4096 2008-10-21 10:48 My Pictures
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-25 12:46 My Videos
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-04-25 17:54
> Our.Finest.Hour.2008.DVDRip.x264.AC3.iNT-DG
> -rwxr--r-- 1 yongffa Domain Users    32768 2008-08-04 16:29 outlook.pst
> -rwxr--r-- 1 yongffa Domain Users 25739264 2008-06-28 06:01 Personal
> Folders(1).pst
> root@queenbee:/home/yongffa/My Documents# du -sk .
> 971504  .
>
>
> # ls -lR | more
> total 29380
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-11 15:05 ³×ÀÌÆ®¿Â ¹ÞÀº
ÆÄÀÏ
> -rwxr--r-- 1 yongffa Domain Users  3259699 2008-08-14 17:16
> ALZip_eng_632.exe
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-01-29 11:38 ansys
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-09-29 21:45 conver3k
> -rwxr--r-- 1 yongffa Domain Users   109977 2008-09-29 21:45 conver3k.zip
> -rwxr--r-- 1 yongffa Domain Users     1658 2008-03-27 16:39 Default.rdp
> -rwxr--r-- 1 yongffa Domain Users       78 2008-10-21 10:47 desktop.ini
> drwxr-xr-x 3 yongffa Domain Users     4096 2008-04-15 20:06
> fesafe.version.5.3
> -rwxr--r-- 1 yongffa Domain Users   824519 2008-09-29 21:35
> free_converter_setup.exe
> -rwxr--r-- 1 yongffa Domain Users    32768 2008-06-25 12:31
> helium.vancouver.wsu.edu-00000001.pst
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-14 18:26 MATLAB
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-10-21 10:48 My Music
> drwxr-xr-x 3 yongffa Domain Users     4096 2008-10-21 10:48 My Pictures
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-06-25 12:46 My Videos
> drwxr-xr-x 2 yongffa Domain Users     4096 2008-04-25 17:54
> Our.Finest.Hour.2008.DVDRip.x264.AC3.iNT-DG
> -rwxr--r-- 1 yongffa Domain Users    32768 2008-08-04 16:29 outlook.pst
> -rwxr--r-- 1 yongffa Domain Users 25739264 2008-06-28 06:01 Personal
> Folders(1).pst
>
> ./³×ÀÌÆ®¿Â ¹ÞÀº ÆÄÀÏ:
> total 848532
> -rwxr--r-- 1 yongffa Domain Users   5035651 2008-01-31 15:05
> loding206mpa-relaxation-ellipse-crack-1mm-06mm-Al2024-0114.inp
> -rwxr--r-- 1 yongffa Domain Users 862866940 2008-01-31 14:08
> relaxation-ellipse-Al2024-comp-bogang-bojo.odb
> -rwxr--r-- 1 yongffa Domain Users    125952 2008-01-31 16:25
> SsCx-ellipse-1mm-06mm-al2024-jan23.xls
>
> ./ansys:
> total 4
> -rwxr--r-- 1 yongffa Domain Users 818 2008-01-29 11:38 STATUS.lis
> <snip>
>
> Is this always being read every friggin' time they log in!?!?!
>
For roaming profiles yes. Unless you set these folders to not sync
(registry or policy settings) the entire 1GB will be transferred when
you logon and logoff.

John

On Thu, Oct 23, 2008 at 02:27:27PM -0700, Wayne Cochran
wrote:
> I think I have narrowed down the problem why smbd processes are soaking
> up so much CPU on our file server. Here are some selected samples from
> strace output as I attached to the offending smbd process:
>
> Culprit #1
>
> I took three sample snapshots, each lasted for several seconds, and I  
> took them
> minutes apart from each other.  I noticed many lines involved stat'ing
> the
> a single file in the 'My Documents' subdirectory:
>
> stat64("My Documents/The Picture of Dorian Grey.rtf",
{st_mode=S_IFREG|
> 0744, st_size=0, ...}) = 0
> utimes("My Documents/The Picture of Dorian Grey.rtf",
{1224548572, 0}) =
> 0
>
> To see the frequency of these I grep'ed and use wc -l to get a line  
> count:
>
> # grep 'stat64("My Documents/The Picture of Dorian
Grey.rtf"' /tmp/
> qqq.txt | wc -l
> 462
> # grep 'stat64("My Documents/The Picture of Dorian
Grey.rtf"' /tmp/
> rrr.txt | wc -l
> 1065
> s# grep 'stat64("My Documents/The Picture of Dorian
Grey.rtf"' /tmp/
> ppp.txt | wc -l
> 429
>
> Thousands of times this file is being stat'ed!?!?
What is the client doing at this point ? It's very possible
that this is what the client is requesting.

Jeremy.

Hello,

just my 2cents.  What about the possibility, that an anti-vir tool scans 
all the files over and over?

~ Martin

Wayne Cochran schrieb:
> I think I have narrowed down the problem why smbd processes are soaking
> up so much CPU on our file server. Here are some selected samples from
> strace output as I attached to the offending smbd process:
> 
[...]
> read(5, "\0\0\0H", 4)                   = 4
> read(5,
"\377SMB2\0\0\0\0\30\7\310\0\0\0\0\0\0\0\0\0\0\0\0\4\0\230"...,
> 72) = 72
> stat64(".windows_settings/Application Data/SolidWorks 
> 2008/Scheduler_2/swbo1.mdb", {st_mode=S_IFREG|0744, st_size=974848, 
> ...}) = 0
> fcntl64(13, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=25416, 
> len=1}, 0xbfa355d4) = 0
> fcntl64(13, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=25416, 
> len=1}, 0xbfa355f4) = 0
> write(5,
"\0\0\0d\377SMB2\0\0\0\0\210A\310\0\0\0\0\0\0\0\0\0\0\0"...,
> 104) = 104
> gettimeofday({1224788202, 767660}, NULL) = 0
> select(30, [5 21 29], [], NULL, {60, 0}) = 1 (in [5], left {60, 0})
> read(5, "\0\0\0)", 4)                   = 4
[...]
> 
> Is this always being read every friggin' time they log in!?!?!
> 
> Any ideas on what is going on here!?!?
> 
> --w
> Wayne O. Cochran
> Clinical Assistant Professor, Computer Science
> Washington State University Vancouver
> wcochran@vancouver.wsu.edu
> http://ezekiel.vancouver.wsu.edu/~wayne
> 
> 
> 
> 

-- 
Martin Zielinski 			mz@seh.de		
Softwareentwicklung			T +49 (0)521 94226 76	

SEH Computertechnik GmbH 		www.seh.de