thr3ads.net - samba - [Samba] Saving files with MS Word to samba3 server is very slow! [Dec 2005]

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

Andreas Haumer

2005-Dec-01 16:55 UTC

[Samba] Saving files with MS Word to samba3 server is very slow!

Hi!

I'm currently hunting a strange problem and looking for help!

I have a samba3 fileserver (currently samba-3.0.20b, but problem can
be reproduced with samba-3.0.7, but _not_ with samba2 like 2.2.8a),
and I see performance problems when writing files with MS word 2002 SP3
from a NT4.0 (SP6a) workstation. Saving even the smallest file takes more 
than 10 seconds! Copying files with Windows Explorer takes less than
a second!

Also, from Windows XP clients it takes less than a second when saving
files to the Samba server with Word!

I took various dumps with ethereal and found the following:

Time        Source                Destination           Protocol Info
9.906172    aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      Write AndX
Request, FID: 0x2ed3, 162 bytes at offset 0
9.907359    aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      Write AndX
Response, FID: 0x2ed3, 162 bytes
9.907734    aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      NT Create AndX
Request, Path: \~$stdatei2.doc
9.907901    aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      Locking AndX
Request, FID: 0x2ed3
9.908102    aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      Locking AndX
Request, FID: 0x2ed3
9.938196    aaa.bb.ccc.14         aaa.bb.ccc.130        TCP      netbios-ssn
>
rootd [ACK] Seq=105376 Ack=77857 Win=10220 Len=0
10.858462   aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      NT Create AndX
Response, Error: STATUS_SHARING_VIOLATION
10.858852   aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      Trans2 Request,
FIND_FIRST2, Pattern: \~$stdatei2.doc
10.858858   aaa.bb.ccc.14         aaa.bb.ccc.130        TCP      netbios-ssn
>
rootd [ACK] Seq=105415 Ack=77973 Win=10220 Len=0
10.858983   aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      Trans2
Response, FIND_FIRST2, Files: ~$stdatei2.doc
10.859612   aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      NT Create AndX
Request, Path: \~$stdatei2.doc
10.898195   aaa.bb.ccc.14         aaa.bb.ccc.130        TCP      netbios-ssn
>
rootd [ACK] Seq=105611 Ack=78093 Win=10220 Len=0
11.818364   aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      NT Create AndX
Response, Error: STATUS_SHARING_VIOLATION
11.818717   aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      NT Create AndX
Request, Path: \~$stdatei2.doc
11.818725   aaa.bb.ccc.14         aaa.bb.ccc.130        TCP      netbios-ssn
>
rootd [ACK] Seq=105650 Ack=78213 Win=10220 Len=0
12.500990   aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      Trans2 Request,
QUERY_PATH_INFO, Query File Basic Info, Path: \~WRD0005.tmp
12.501012   aaa.bb.ccc.14         aaa.bb.ccc.130        TCP      netbios-ssn
>
rootd [ACK] Seq=105650 Ack=78319 Win=10220 Len=0
12.501243   aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      Trans2
Response, QUERY_PATH_INFO, Error: STATUS_OBJECT_NAME_NOT_FOUND
12.631008   aaa.bb.ccc.130        aaa.bb.ccc.14         TCP      rootd >
netbios-ssn [ACK] Seq=78319 Ack=105689 Win=8682 Len=0
12.778367   aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      NT Create AndX
Response, Error: STATUS_SHARING_VIOLATION
12.778636   aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      Close Request,
FID: 0x2ed3
12.778797   aaa.bb.ccc.14         aaa.bb.ccc.130        SMB      Close Response
12.780195   aaa.bb.ccc.130        aaa.bb.ccc.14         SMB      Trans2 Request,
QUERY_PATH_INFO, Query File Basic Info, Path: \

aaa.bb.ccc.14 = Samba server, aaa.bb.ccc.130 = Windows NT workstation

As you can see, it takes the samba server always about a second
to respond to the client's request with a STATUS_SHARING_VIOLATION
message. This repeats several times even when saving a very small
file and so this sums up to more that 10 seconds when the file then
finally gets saved. Where does this delay come from? 

In the samba logfile I see many of the following messages:
[...]
[2005/12/01 17:25:40, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:40, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:40, 3] smbd/process.c:process_smb(1114)
  Transaction 566 of length 116
[2005/12/01 17:25:40, 3] smbd/process.c:switch_message(900)
  switch message SMBntcreateX (pid 4632) conn 0x8424c48
[2005/12/01 17:25:40, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (5602, 5600) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:40, 3] smbd/dosmode.c:unix_mode(121)
  unix_mode(~WRD0005.tmp) returning 0744
[2005/12/01 17:25:40, 3] smbd/error.c:error_packet(147)
  error packet at smbd/trans2.c(2589) cmd=162 (SMBntcreateX)
NT_STATUS_SHARING_VIOLATION
[2005/12/01 17:25:40, 3] smbd/process.c:process_smb(1114)
  Transaction 567 of length 116
[2005/12/01 17:25:40, 3] smbd/process.c:switch_message(900)
  switch message SMBntcreateX (pid 4632) conn 0x8424c48
[2005/12/01 17:25:40, 3] smbd/dosmode.c:unix_mode(121)
  unix_mode(~WRD0005.tmp) returning 0744
[2005/12/01 17:25:40, 2] smbd/open.c:open_file(372)
  wunderli opened file ~WRD0005.tmp read=Yes write=No (numopen=4)
[2005/12/01 17:25:41, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:41, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:41, 3] smbd/process.c:process_smb(1114)
  Transaction 568 of length 116
[2005/12/01 17:25:41, 3] smbd/process.c:switch_message(900)
  switch message SMBntcreateX (pid 4632) conn 0x8424c48
[2005/12/01 17:25:41, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (5602, 5600) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:41, 3] smbd/dosmode.c:unix_mode(121)
  unix_mode(~WRD0005.tmp) returning 0744
[2005/12/01 17:25:41, 3] smbd/error.c:error_packet(147)
  error packet at smbd/trans2.c(2589) cmd=162 (SMBntcreateX)
NT_STATUS_SHARING_VIOLATION
[2005/12/01 17:25:41, 3] smbd/process.c:process_smb(1114)
  Transaction 569 of length 116
[2005/12/01 17:25:41, 3] smbd/process.c:switch_message(900)
  switch message SMBntcreateX (pid 4632) conn 0x8424c48
[2005/12/01 17:25:41, 3] smbd/dosmode.c:unix_mode(121)
  unix_mode(~WRD0005.tmp) returning 0744
[2005/12/01 17:25:41, 2] smbd/open.c:open_file(372)
  wunderli opened file ~WRD0005.tmp read=Yes write=No (numopen=4)
[2005/12/01 17:25:42, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:42, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/01 17:25:42, 3] smbd/process.c:process_smb(1114)
  Transaction 570 of length 116
[...]

I already tried to disable oplocks, but this didn't help!

Please note that the problem does only occur with the combination 
of Samba 3, Windows NT and Word.

It does _not_ occur with:

Samba 2 server, Windows NT client, Saving file with Word
Samba 3 server, Windows NT client, Copying file with Explorer
Samba 3 server, Windows XP client, Saving file with Word


Does anyone have any idea how to solve this mystery?

Any help is appreciated!

Regards

- andreas


-------------------------------------------------
This mail sent through IMP: http://horde.org/imp/

Andreas Haumer

2005-Dec-02 08:08 UTC

head link

[Samba] Saving files with MS Word to samba3 server is very slow!

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/

Andreas Haumer

2005-Dec-02 08:39 UTC

head link

[Samba] Saving files with MS Word to samba3 server is very slow!

Hi!

Some more infos:

With a samba debug level of 10 I get the following logs
which IMHO are relevant for the problem:

[...]
[2005/12/02 09:12:00, 3] smbd/process.c:switch_message(900)
  switch message SMBntcreateX (pid 17354) conn 0x8426cb0
[2005/12/02 09:12:00, 4] smbd/uid.c:change_to_user(217)
  change_to_user: Skipping user change - already user
[2005/12/02 09:12:00, 10] smbd/nttrans.c:reply_ntcreate_and_X(506)
  reply_ntcreateX: flags = 0x6, access_mask = 0x20181 file_attributes = 0x80,
share_access = 0x7, create_disposition = 0x1 create_options = 0x140 root_dir_fid
= 0x0
[2005/12/02 09:12:00, 5] smbd/filename.c:unix_convert(108)
  unix_convert called on file "test/~WRD1676.tmp"
[2005/12/02 09:12:00, 10] smbd/statcache.c:stat_cache_lookup(248)
  stat_cache_lookup: lookup succeeded for name [TEST/~WRD1676.TMP] ->
[test/~WRD1676.tmp]
[2005/12/02 09:12:00, 3] smbd/dosmode.c:unix_mode(121)
  unix_mode(test/~WRD1676.tmp) returning 0744
[2005/12/02 09:12:00, 10] smbd/open.c:open_file_ntcreate(1236)
  open_file_ntcreate: fname=test/~WRD1676.tmp, dos_attrs=0x80
access_mask=0x20181 share_access=0x7 create_disposition = 0x1
create_options=0x140 unix mode=0744 oplock_request=3
[2005/12/02 09:12:00, 8] smbd/dosmode.c:dos_mode(294)
  dos_mode: test/~WRD1676.tmp
[2005/12/02 09:12:00, 8] smbd/dosmode.c:dos_mode_from_sbuf(162)
  dos_mode_from_sbuf returning a
[2005/12/02 09:12:00, 8] smbd/dosmode.c:dos_mode(328)
  dos_mode returning a
[2005/12/02 09:12:00, 10] smbd/open.c:open_file_ntcreate(1409)
  open_file_ntcreate: fname=test/~WRD1676.tmp, after mapping access_mask=0x20181
[2005/12/02 09:12:00, 5] smbd/files.c:file_new(139)
  allocated file structure 7559, fnum = 11655 (2 used)
[2005/12/02 09:12:00, 10] locking/locking.c:get_share_modes(491)
  get_share_modes: delete_on_close: 0
[2005/12/02 09:12:00, 10] locking/locking.c:get_share_modes(516)
  get_share_modes: share_mode_entry[0]: pid = 17354, share_access = 0x0,
private_options = 0x40, access_mask = 0x2019f, port = 0x0, type= 0x0, file_id 1,
dev = 0x3a0b, inode = 134217858
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(409)
  share_conflict: entry->access_mask = 0x2019f, entry->share_access = 0x0,
entry->private_options = 0x40
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(412)
  share_conflict: access_mask = 0x20181, share_access = 0x7
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(463)
  share_conflict: [1] am (0x2019f) & right (0x6) = 0x6
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(463)
  share_conflict: [1] sa (0x7) & share (0x2) = 0x2
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(465)
  share_conflict: [2] am (0x20181) & right (0x6) = 0x0
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(465)
  share_conflict: [2] sa (0x0) & share (0x2) = 0x0
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(468)
  share_conflict: [3] am (0x2019f) & right (0x21) = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(468)
  share_conflict: [3] sa (0x7) & share (0x1) = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(470)
  share_conflict: [4] am (0x20181) & right (0x21) = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(470)
  share_conflict: [4] sa (0x0) & share (0x1) = 0x0
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(470)
  share_conflict: check 4 conflict am = 0x20181, right = 0x21, sa = 0x0, share =
0x1
[2005/12/02 09:12:00, 10] smbd/open.c:fd_open(55)
  fd_open: name test/~WRD1676.tmp, flags = 00 mode = 0744, fd = 30. 
[2005/12/02 09:12:00, 2] smbd/open.c:open_file(372)
  wunderli opened file test/~WRD1676.tmp read=Yes write=No (numopen=2)
[2005/12/02 09:12:00, 4] smbd/open.c:open_file_ntcreate(1526)
  open_file_ntcreate : share_mode deny - calling open_file with flags=0x0
flags2=0x0 mode=0744 returned 1
[2005/12/02 09:12:00, 10] smbd/open.c:defer_open_sharing_error(873)
  defer_open_sharing_error: time [1133511120.559863] adding deferred open entry
for mid 3584, file test/~WRD1676.tmp
[2005/12/02 09:12:00, 10]
smbd/process.c:push_sharing_violation_open_smb_message(275)
  push_sharing_violation_open_smb_message: pushing message len 126 mid 3584
timeout time [1133511121.509863]
[2005/12/02 09:12:00, 10] smbd/process.c:push_queued_message(131)
  push_message: pushed message length 126 on queue smb_sharing_violation_queue
[2005/12/02 09:12:00, 10] locking/locking.c:add_deferred_open(1224)
  add_deferred_open: creating entry for file test/~WRD1676.tmp.
num_deferred_open_entries = 1
[2005/12/02 09:12:00, 10] locking/locking.c:print_deferred_open_table(976)
  print_deferred_open_table: deferred_open_entry[0]: pid = 17354, mid = 3584,
dev = 0x3a0b, inode = 134217858, port = 33113, time = [1133511120.559863]
[2005/12/02 09:12:00, 5] smbd/files.c:file_free(459)
  freed files structure 11655 (1 used)
[2005/12/02 09:12:00, 10] smbd/process.c:receive_message_or_smb(403)
  receive_message_or_smb: select with timeout of [0.949586]
[2005/12/02 09:12:01, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_nt_user_token(452)
  NT user token: (NULL)
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_unix_user_token(473)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2005/12/02 09:12:01, 5] smbd/uid.c:change_to_root_user(319)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/12/02 09:12:01, 10] smbd/process.c:receive_message_or_smb(403)
  receive_message_or_smb: select with timeout of [0.003326]
[2005/12/02 09:12:01, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_nt_user_token(452)
  NT user token: (NULL)
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_unix_user_token(473)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2005/12/02 09:12:01, 5] smbd/uid.c:change_to_root_user(319)
  change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/12/02 09:12:01, 10] smbd/process.c:receive_message_or_smb(396)
  receive_message_or_smb: queued message timed out.
[2005/12/02 09:12:01, 5] smbd/process.c:receive_message_or_smb(412)
  receive_message_or_smb: returning deferred open smb message.
[2005/12/02 09:12:01, 6] smbd/process.c:process_smb(1113)
  got message type 0x0 of len 0x7a
[2005/12/02 09:12:01, 3] smbd/process.c:process_smb(1114)
  Transaction 60 of length 126
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(454)
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(464)
  size=122
  smb_com=0xa2
  smb_rcls=0
  smb_reh=0
  smb_err=0
  smb_flg=24
  smb_flg2=32771
  smb_tid=2
  smb_pid=56576
  smb_uid=101
  smb_mid=3584
  smt_wct=24
  smb_vwv[ 0]=  255 (0xFF)
  smb_vwv[ 1]=    0 (0x0)
  smb_vwv[ 2]= 9216 (0x2400)
  smb_vwv[ 3]= 1536 (0x600)
  smb_vwv[ 4]=    0 (0x0)
  smb_vwv[ 5]=    0 (0x0)
  smb_vwv[ 6]=    0 (0x0)
  smb_vwv[ 7]=33024 (0x8100)
  smb_vwv[ 8]=  513 (0x201)
  smb_vwv[ 9]=    0 (0x0)
  smb_vwv[10]=    0 (0x0)
  smb_vwv[11]=    0 (0x0)
  smb_vwv[12]=    0 (0x0)
  smb_vwv[13]=32768 (0x8000)
  smb_vwv[14]=    0 (0x0)
  smb_vwv[15]= 1792 (0x700)
  smb_vwv[16]=    0 (0x0)
  smb_vwv[17]=  256 (0x100)
  smb_vwv[18]=    0 (0x0)
  smb_vwv[19]=16384 (0x4000)
  smb_vwv[20]=    1 (0x1)
  smb_vwv[21]=  512 (0x200)
  smb_vwv[22]=    0 (0x0)
  smb_vwv[23]=    0 (0x0)
  smb_bcc=39
[2005/12/02 09:12:01, 10] lib/util.c:dump_data(2053)
  [000] DD 5C 00 74 00 65 00 73  00 74 00 5C 00 7E 00 57  .\.t.e.s .t.\.~.W
  [010] 00 52 00 44 00 31 00 36  00 37 00 36 00 2E 00 74  .R.D.1.6 .7.6...t
  [020] 00 6D 00 70 00 00 00                              .m.p... 
[2005/12/02 09:12:01, 3] smbd/process.c:switch_message(900)
  switch message SMBntcreateX (pid 17354) conn 0x8426cb0
[2005/12/02 09:12:01, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (5602, 5600) - sec_ctx_stack_ndx = 0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_nt_user_token(457)
  NT user token of user S-1-5-21-4201010128-2403562230-48780307-12204
  contains 10 SIDs
  SID[  0]: S-1-5-21-4201010128-2403562230-48780307-12204
  SID[  1]: S-1-5-21-4201010128-2403562230-48780307-12201
  SID[  2]: S-1-1-0
  SID[  3]: S-1-5-2
  SID[  4]: S-1-5-11
  SID[  5]: S-1-5-21-4201010128-2403562230-48780307-544
  SID[  6]: S-1-5-21-4201010128-2403562230-48780307-2985
  SID[  7]: S-1-5-21-4201010128-2403562230-48780307-12001
  SID[  8]: S-1-5-21-4201010128-2403562230-48780307-12203
  SID[  9]: S-1-5-21-4201010128-2403562230-48780307-12601
  SE_PRIV  0x0 0x0 0x0 0x0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_unix_user_token(473)
  UNIX token of user 5602
  Primary group is 5600 and contains 6 supplementary groups
  Group[  0]: 5600
  Group[  1]: 544
  Group[  2]: 992
  Group[  3]: 5500
  Group[  4]: 5601
  Group[  5]: 5800
[2005/12/02 09:12:01, 5] smbd/uid.c:change_to_user(304)
  change_to_user uid=(5602,5602) gid=(0,5600)
[2005/12/02 09:12:01, 10] smbd/nttrans.c:reply_ntcreate_and_X(506)
  reply_ntcreateX: flags = 0x6, access_mask = 0x20181 file_attributes = 0x80,
share_access = 0x7, create_disposition = 0x1 create_options = 0x140 root_dir_fid
= 0x0
[2005/12/02 09:12:01, 5] smbd/filename.c:unix_convert(108)
  unix_convert called on file "test/~WRD1676.tmp"
[2005/12/02 09:12:01, 10] smbd/statcache.c:stat_cache_lookup(248)
  stat_cache_lookup: lookup succeeded for name [TEST/~WRD1676.TMP] ->
[test/~WRD1676.tmp]
[2005/12/02 09:12:01, 3] smbd/dosmode.c:unix_mode(121)
  unix_mode(test/~WRD1676.tmp) returning 0744
[2005/12/02 09:12:01, 10] smbd/open.c:open_file_ntcreate(1236)
  open_file_ntcreate: fname=test/~WRD1676.tmp, dos_attrs=0x80
access_mask=0x20181 share_access=0x7 create_disposition = 0x1
create_options=0x140 unix mode=0744 oplock_request=3
[2005/12/02 09:12:01, 10]
smbd/process.c:remove_sharing_violation_open_smb_message(166)
  remove_sharing_violation_open_smb_message: deleting mid 3584 len 126
[2005/12/02 09:12:01, 10] locking/locking.c:get_deferred_opens(1044)
  get_deferred_opens: deferred_open_entry[0]: pid = 17354, mid = 3584, dev
0x3a0b, inode = 134217858, port = 33113, time = [1133511120.559863]
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1136)
  delete_deferred_open_entry: num_deferred_open_entries = 1
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1141)
  delete_deferred_open_entry: deleted deferred_open_entry[0]: pid = 17354, mid
3584, dev = 0x3a0b, inode = 134217858, port = 33113, time = [1133511120.559863]
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1150)
  delete_deferred_open_entry: deleting entry 0
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1172)
  delete_deferred_open_entry: Remaining table.
[2005/12/02 09:12:01, 10] smbd/trans2.c:set_bad_path_error(2583)
  set_bad_path_error: err = 2 bad_path = 0
[2005/12/02 09:12:01, 3] smbd/error.c:error_packet(147)
  error packet at smbd/trans2.c(2589) cmd=162 (SMBntcreateX)
NT_STATUS_SHARING_VIOLATION
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(454)
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(464)
  size=35
  smb_com=0xa2
  smb_rcls=67
  smb_reh=0
  smb_err=49152
  smb_flg=136
  smb_flg2=49153
  smb_tid=2
  smb_pid=56576
  smb_uid=101
  smb_mid=3584
  smt_wct=0
  smb_bcc=0
[2005/12/02 09:12:01, 10] lib/util_sock.c:read_smb_length_return_keepalive(615)
[...]

Here you can see the "receive_message_or_smb: select with timeout of
[0.949586]"
message. The whole pattern repeats 19 times when saving an empty Word file.

If I set "share modes = no" for the smaba share in question, saving
the
Word file is completed almost instantly! But this is IMHO not a real solution
as I think we can not live without this feature.

Does this ring a bell? Anyone?

- andreas


-------------------------------------------------
This mail sent through IMP: http://horde.org/imp/

Gerald (Jerry) Carter

2005-Dec-02 13:36 UTC

head link

[Samba] Saving files with MS Word to samba3 server is very slow!

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Andreas Haumer wrote:
| Hi!
|
| I'm currently hunting a strange problem and looking for help!
|
| I have a samba3 fileserver (currently samba-3.0.20b, but
| problem can be reproduced with samba-3.0.7, but
| _not_ with samba2 like 2.2.8a), and I see performance
| problems when writing files with MS word 2002 SP3
| from a NT4.0 (SP6a) workstation. Saving even the
| smallest file takes more  than 10 seconds! Copying
| files with Windows Explorer takes less than a second!

Can yoiu test against the current SAMBA_3_0_RELEASE tree?
Samba 3.0.21 should be out in the next day or so and
the release branch will give you a chance to test prior
to release.



cheers, jerry
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.0 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://enigmail.mozdev.org

iD8DBQFDkE2mIR7qMdg1EfYRAlmHAKDVNZ0CyLqFfqNDt1bQgUj7MDCLFwCgzOIk
sZtO13Iwvzm6F2SPaQgwQWk=0ZOl
-----END PGP SIGNATURE-----

Possibly Parallel Threads

Search for more seemingly similar threads

samba - Dec 2005 - Saving files with MS Word to samba3 server is very slow!

[Samba] Saving files with MS Word to samba3 server is very slow!

[Samba] Saving files with MS Word to samba3 server is very slow!

[Samba] Saving files with MS Word to samba3 server is very slow!

[Samba] Saving files with MS Word to samba3 server is very slow!

Possibly Parallel Threads