[Samba] Saving files with MS Word to samba3 server is very slow!
Andreas Haumer
andreas at xss.co.at
Fri Dec 2 08:07:43 GMT 2005
Hi!
I'm still hunting this problem and now have some additional
information.
I tried to save an empty Word file from the NT workstation to the
Samba3 server, which takes more than 20 seconds(!), and took a strace
log from the samba process.
I found that the samba process does 19 select(2) system calls which
all time out after a little less than 1 second. This of course sums
up to the long delay I see when saving a file with Word.
These 19 select calls all follow the same pattern:
[...]
0.000050 stat64("test/~WRD0005.tmp", {st_mode=S_IFREG|0744, st_size=23040,
...}) = 0 <0.000015>
0.000074 fcntl64(14, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfffedf0) = 0 <0.000012>
0.000053 fcntl64(15, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffe8c0) = 0 <0.000009>
0.000047 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffe900) = 0 <0.000009>
0.000046 kill(16973, SIG_0) = 0 <0.000008>
0.000040 fcntl64(15, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffece0) = 0 <0.000008>
0.000045 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffed20) = 0 <0.000008>
0.000045 fcntl64(15, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffecd0) = 0 <0.000008>
0.000045 fcntl64(15, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=696,
len=1}, 0xbfffecc0) = 0 <0.000008>
0.000043 fcntl64(15, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=696,
len=1}, 0xbfffecc0) = 0 <0.000009>
0.000045 fcntl64(15, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=164,
len=1}, 0xbfffec30) = 0 <0.000008>
0.000045 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=164,
len=1}, 0xbfffec30) = 0 <0.000009>
0.000044 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffed10) = 0 <0.000009>
0.000075 fcntl64(14, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfffedf0) = 0 <0.000008>
0.000048 write(26,
"\0\0\0#\377SMB\242C\0\0\300\210\1\300\0\0\0\0\0\0\0\0\0"..., 39) = 39 <0.000014>
0.000072 select(27, [5 23 26], NULL, NULL, {60, 0}) = 1 (in [26], left {60,
0}) <0.000286>
0.000332 read(26, "\0\0\0z", 4) = 4 <0.000009>
0.000042 read(26,
"\377SMB\242\0\0\0\0\30\3\200\343\200\0\0\0\0\0\0\0\0\0"..., 122) = 122 <0.000009>
0.000054 gettimeofday({1133509647, 607911}, NULL) = 0 <0.000007>
0.000047 stat64("test/~WRD0005.tmp", {st_mode=S_IFREG|0744, st_size=23040,
...}) = 0 <0.000010>
0.000067 gettimeofday({1133509647, 608025}, NULL) = 0 <0.000005>
0.000038 fcntl64(14, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfffedf0) = 0 <0.000011>
0.000054 kill(16973, SIG_0) = 0 <0.000007>
0.000041 open("test/~WRD0005.tmp", O_RDONLY|O_LARGEFILE) = 31 <0.000016>
0.000055 fcntl64(15, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffe8a0) = 0 <0.000008>
0.000045 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffe8a0) = 0 <0.000008>
0.000047 fcntl64(15, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffeca0) = 0 <0.000008>
0.000044 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffeca0) = 0 <0.000008>
0.000046 fcntl64(15, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffecd0) = 0 <0.000008>
0.000046 fcntl64(15, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=164,
len=1}, 0xbfffec70) = 0 <0.000008>
0.000045 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=164,
len=1}, 0xbfffec70) = 0 <0.000008>
0.000044 fcntl64(15, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=376,
len=1}, 0xbfffecd0) = 0 <0.000008>
0.000045 fcntl64(14, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=436,
len=1}, 0xbfffedf0) = 0 <0.000008>
0.000046 close(31) = 0 <0.000011>
0.000045 gettimeofday({1133509647, 608666}, NULL) = 0 <0.000007>
0.000040 select(27, [5 23 26], NULL, NULL, {0, 949359}) = 0 (Timeout)
<0.947049>
0.947273 time(NULL) = 1133509648 <0.000008>
[...]
This trace was taken with "strace -r -T". The first column shows the
relative time between system calls and at the end of each line the total
time of the system call is printed.
Look at the last select call of this example: it times out and takes
0.947049 seconds to finish. I found 19 of these situations in my test
of saving an empty Word file, resulting in a total time of more than 20
seconds for the operation. This is just too long to be accepted.
# fgrep Timeout samba.trace
0.000041 select(27, [5 23 26], NULL, NULL, {0, 947307}) = 0 (Timeout)
<0.949387>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949308}) = 0 (Timeout)
<0.944988>
0.000044 select(27, [5 23 26], NULL, NULL, {0, 3427}) = 0 (Timeout) <0.009098>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949354}) = 0 (Timeout)
<0.946990>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 1431}) = 0 (Timeout) <0.009054>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949328}) = 0 (Timeout)
<0.947031>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 1409}) = 0 (Timeout) <0.009099>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949356}) = 0 (Timeout)
<0.947086>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 1424}) = 0 (Timeout) <0.009161>
0.000040 select(27, [5 23 26], NULL, NULL, {0, 949359}) = 0 (Timeout)
<0.947049>
0.000044 select(27, [5 23 26], NULL, NULL, {0, 1297}) = 0 (Timeout) <0.008969>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949304}) = 0 (Timeout)
<0.947038>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 1377}) = 0 (Timeout) <0.009113>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949347}) = 0 (Timeout)
<0.947108>
0.000027 select(27, [5 23 26], NULL, NULL, {0, 1555}) = 0 (Timeout) <0.009318>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949335}) = 0 (Timeout)
<0.947003>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 1435}) = 0 (Timeout) <0.009091>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949353}) = 0 (Timeout)
<0.946973>
0.000047 select(27, [5 23 26], NULL, NULL, {0, 1460}) = 0 (Timeout) <0.009078>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 947411}) = 0 (Timeout)
<0.946305>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 251}) = 0 (Timeout) <0.009135>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949367}) = 0 (Timeout)
<0.945354>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 3120}) = 0 (Timeout) <0.009092>
0.000039 select(27, [5 23 26], NULL, NULL, {0, 269781}) = 0 (Timeout)
<0.267443>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 1476}) = 0 (Timeout) <0.009132>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949364}) = 0 (Timeout)
<0.947077>
0.000027 select(27, [5 23 26], NULL, NULL, {0, 1687}) = 0 (Timeout) <0.009420>
0.000023 select(27, [5 23 26], NULL, NULL, {0, 949356}) = 0 (Timeout)
<0.947243>
0.000044 select(27, [5 23 26], NULL, NULL, {0, 1269}) = 0 (Timeout) <0.009125>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949343}) = 0 (Timeout)
<0.946972>
0.000045 select(27, [5 23 26], NULL, NULL, {0, 1448}) = 0 (Timeout) <0.009107>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949352}) = 0 (Timeout)
<0.947065>
0.000046 select(27, [5 23 26], NULL, NULL, {0, 1415}) = 0 (Timeout) <0.009106>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949329}) = 0 (Timeout)
<0.947029>
0.000027 select(27, [5 23 26], NULL, NULL, {0, 1742}) = 0 (Timeout) <0.009449>
0.000042 select(27, [5 23 26], NULL, NULL, {0, 949355}) = 0 (Timeout)
<0.947025>
0.000046 select(27, [5 23 26], NULL, NULL, {0, 1484}) = 0 (Timeout) <0.009140>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 949343}) = 0 (Timeout)
<0.946997>
0.000041 select(27, [5 23 26], NULL, NULL, {0, 1495}) = 0 (Timeout) <0.009133>
What is samba trying to do here?
Why does it spend so much time in so many select(2) calls?
Why does it occur only with Samba3, Windows NT and Word?
How can I change this behaviour and finally increase the file server
performance to an acceptable speed?
I hope someone out there can help me!
Regards,
- andreas
-------------------------------------------------
This mail sent through IMP: http://horde.org/imp/
More information about the samba
mailing list