Samba write performance anomaly

David Collier-Brown David.Collier-Brown at canada.sun.com
Wed May 24 21:37:11 GMT 2000


Steve Snyder wrote:
> Every few months I get sick of the miserable write performance on my
> Samba servers and vow to fix it.  It's that time again.

	And he was kind enough to provide enough information
	to expose some rather **odd** symptoms....


  Steve has Samba v2.0.7 on Linux kernel v2.2.15 on a machine with 
normal ftp performance. Samba read performance approximates that of
ftp.
Alas, Samba write performance is at least 4 times slower than ftp put
performance.  This is reproducible with Win98, OS/2, and Linux
clients, 
so it's server-centric.

  Looking at samba and strace logs, we see something peculiar:
a sequence of read/readraw pairs, thusly (more about this
alternation later):

[slightly edited fort clarity only]
[1999/12/30 14:19:53, 3 smbd/process.c:switch_message(448)
  switch message SMBwrite (pid 459)
  write fnum=4927 num=0 wrote=0

[1999/12/30 14:19:53, 3 smbd/process.c:switch_message(448)
  switch message SMBwritebraw (pid 459)
  writebraw1 fnum=4927 start=0 num=4096 wrote=4096 sync=0
  writebraw2 fnum=4927 start=0 num=60416 wrote=64512

[1999/12/30 14:19:53, 3 smbd/process.c:switch_message(448)
  switch message SMBwrite (pid 459)
  write fnum=4927 num=0 wrote=0

[1999/12/30 14:19:53, 3 smbd/process.c:switch_message(448)
  switch message SMBwritebraw (pid 459)
  writebraw1 fnum=4927 start=64512 num=4096 wrote=4096 sync=0
  writebraw2 fnum=4927 start=64512 num=60416 wrote=64512


Looking at strace, we see a very similar bahavior, in slighty more
detail:
...
geteuid()                               = 500
write(3, "  switch message SMBwrite (pid 4"..., 36) = 36
time(NULL)                              = 946583587
geteuid()                               = 500
write(3, "[1999/12/30 14:53:07, 4] smbd/ui"..., 53) = 53
geteuid()                               = 500
		-- this is the logging code...

send(6, "\0\0\0%\377SMB\v\0\0\0\0\210\1\0"..., 41, 0) = 41
select(7, [5 6], NULL, NULL, {60, 0})   = 1 (in [6], left {60, 0})
recv(6, "\0\0\20<", 4, 0)               = 4
recv(6, "\377SMB\35\0\0\0\0\0\0\0\0\0\0\0"..., 4156, 0) = 4156
		-- the read loop, getting the next packet
		-- from TCP on fd 6, part of the handling
		-- of the SMBwrite packet from the client

		-- I've skipped the logging code from here on.

send(6, "\0\0\0%\377SMB\35\0\0\0\0\200\1\0"..., 41, 0) = 41
select(7, [6], NULL, NULL, {60, 0})     = 1 (in [6], left {60, 0})
recv(6, "\0\0\354\0", 4, 0)             = 4
read(6, "\377u\10\377\25(\343@\0\213\330\353"..., 16384) = 5836
write(8, "\377u\10\377\25(\343@\0\213\330\353"..., 5836) = 5836
read(6, "W\353\3\200\3030\210\36F\205\311"..., 16384) = 5840
write(8, "W\353\3\200\3030\210\36F\205\311"..., 5840) = 5840
read(6, "\355\351\334\0\0\0\200\373*u$\215"..., 16384) = 5840
write(8, "\355\351\334\0\0\0\200\373*u$\215"..., 5840) = 5840
read(6, "\0\0\306D\30\5\n\215D$\30j\0PQR\213"..., 16384) = 5840
write(8, "\0\0\306D\30\5\n\215D$\30j\0PQR\213"..., 5840) = 5840
read(6, "\2\377\320h\377\0\0\0\350\7\0\0\0"..., 16384) = 5840
write(8, "\2\377\320h\377\0\0\0\350\7\0\0\0"..., 5840) = 5840
read(6, "M\20;\376v\f\213\306\3\301;\370\17"..., 16384) = 5840
write(8, "M\20;\376v\f\213\306\3\301;\370\17"..., 5840) = 5840
read(6, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 16384) = 1823
write(8, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1823) = 1823
read(6, "\0\0\0\0\0\204\340\0\0\0\0\0\0\0"..., 16384) = 1460
write(8, "\0\0\0\0\0\204\340\0\0\0\0\0\0\0"..., 1460) = 1460
read(6, "ndowsDirectoryA\0\0KERNEL32.dll\0"..., 16384) = 5840
write(8, "ndowsDirectoryA\0\0KERNEL32.dll\0"..., 5840) = 5840
read(6, "\0s\0.\0 \0D\0o\0 \0y\0o\0u\0 \0"..., 16257) = 5840
write(8, "\0s\0.\0 \0D\0o\0 \0y\0o\0u\0 \0"..., 5840) = 5840
read(6, "PG\34\323\263\261O\315\223\260r\24"..., 10417) = 5840
write(8, "PG\34\323\263\261O\315\223\260r\24"..., 5840) = 5840
read(6, "\r\10\16\n\260%h\201\245L\242\34"..., 4577) = 4577
write(8, "\r\10\16\n\260%h\201\245L\242\34"..., 4577) = 4577
		-- and the code from serviceing the SMBwritebraw
		-- which then writes to the file on fd 8

send(6, "\0\0\0%\377SMB\v\0\0\0\0\210\1\0"..., 41, 0) = 41
select(7, [5 6], NULL, NULL, {60, 0})   = 1 (in [6], left {60, 0})
recv(6, "\0\0\20<", 4, 0)               = 4
recv(6, "\377SMB\35\0\0\0\0\0\0\0\0\0\0\0"..., 4156, 0) = 4156
		-- another SMBwrite

read(6, "\215\30\vi\302\354P\260\263\1\304"..., 16384) = 5836
write(8, "\215\30\vi\302\354P\260\263\1\304"..., 5836) = 5836
read(6, "aGB\304\306@\231\22\4J\22\27D`0\255"..., 16384) = 5840
write(8, "aGB\304\306@\231\22\4J\22\27D`0\255"..., 5840) = 5840
read(6, "\320\216\305:C\216V\226\276R\361"..., 16384) = 5840
write(8, "\320\216\305:C\216V\226\276R\361"..., 5840) = 5840
read(6, "\t at H\236\215(>*\1\f\6\32591\236:"..., 16384) = 5840
		-- and the beginning of the next SMBwritebraw

  I know there are supposed to be read/read-raw alternatiuons
but what looks suspicious to me are:

     1) the size of the reads alternates, bouncing between
	16384 and 5840 (or whatever's left over from the
	last read).  This looks like old DSA code reading
	implied records whose size is floating between 5840
	5836 and 4577... Is there something that limits the
	protocol to such short reads? I'd have expected to
	see a normal TCP stream read cycle, with reads of, say,
	16384 bytes in rapid sucession, followed by only one
	read which gets fewer bytes, at the end of the file.
 
     2) the sizes are much smaller than on my Slolaris box,
	and my machine doesn't alternate sizes:   
  
320.3457        send(4, "\0\004 +FF S M B /\0\0\0".., 1071, 0)  = 1071
320.3489        poll(0xFFBED378, 1, 20000)                      = 1
320.3491        read(4, "\0\0\0 /", 4)                          = 4
320.3494        read(4, "FF S M B /\0\0\0\08801\0".., 47)       = 47
320.3498        read(5, "88 5B2 & v $E9 x fC8C0 .".., 8192)     = 8192
320.3502        read(5, "A014 y83C59F89E414DFB0 T".., 8192)     = 8192
320.3506        read(5, " F069B19B4 1D8C5A093 A17".., 8192)     = 8192
320.3509        read(5, "FBFEE0\0A5CFD3EA 9F2E1 @".., 8192)     = 8192
320.3513        read(5, " _FD f9D I p g 1F9CCE7 4".., 8192)     = 8192
320.3517        read(5, " ' 81E c 4 b\fD51803A5 T".., 8192)     = 8192
320.3521        read(5, "91 IDEFA V 4\f96 ( ? v j".., 8192)     = 8192
320.3525        read(5, " n Y F89 3AC U1505 MDE c".., 8192)     = 8192
320.4046        send(4, "\0\0FC ;FF S M B /\0\0\0".., 64575, 0) =
64575

	Anyone recognize a cause for slow write-to-server performance?

--dave


More information about the samba-technical mailing list