-----------
[2000/08/01 18:18:47, 3] smbd/reply.c: reply_sesssetup_and_X(805)
Domain=[WORKGROUP] NativeOS=[Windows 4.0] NativeLanMan=[Windows 4.0]
My Notes
--------
The domains are different,
which may interfere. Infernix,
they are really the same machine,
aren't they?
[ Yes, I set my domain to Workgroup in both Windows 98 and Windows 2000.
However, since Windows 2000 cannot login to the Samba domain (This is not
supported in the regular branch of Samba, only in TNG, as you probably know)
the Windows 2000 machine logs in to its own local domain which it calls
INFERNIX, the machinename. ]
[2000/08/01 18:23:11, 2] lib/access.c:check_access(258) Allowed connection
from infernix.ggmc.nl (192.168.0.17) [2000/08/01 18:18:47, 2] lib/access.c:
check_access(258) Allowed connection from
infernix2.ggmc.nl (192.168.0.21)
infernix is the win2k
infernix2 is nt 4.0
[ No, infernix is Windows 98 and infernix2 is Windows 2000. In windows 2000
i use ip address .21 and in Windows 98 i use .17. Mind you, I am still
talking about the same machine here! Both Windows 98 and Windows 2000 run on
the same machine because I dual boot them. ]
[2000/08/01 18:23:39, 3] smbd/process.c:switch_message(448) switch message
SMBntcreateX (pid 1511)
[2000/08/01 18:23:39, 3] lib/util.c:unix_clean_name(522) unix_clean_name
[/Trance/ferry_corsten-live_at_trance_energy-30-04-2000-2db/ferry_corsten-li
ve_at_trance_energy__30-04-2000_2db.mp3]
[2000/08/01 18:19:08, 3] smbd/process.c:switch_message(448) switch message
SMBreadbraw (pid 1435)
Win2k is about to open (create?) the
file, at 28 seconds into the log, NT 4 just
opened it, 21 seconds into the log.
At this point, win2k goes into a loop doing oplocks 4 times:
--
[2000/08/01 18:23:39, 3] smbd/oplock.c:initial_break_processing(702)
initial_break_processing: called for dev = 900, inode = 338018 tv_sec 3986f98b,
tv_usec = 639c5.
Current oplocks_open (exclusive = 1, levelII = 0)
[2000/08/01 18:23:39, 3] lib/doscalls.c:dos_ChDir(342)
dos_ChDir to /var/log
[2000/08/01 18:23:39, 3] smbd/oplock.c:initial_break_processing(702)
initial_break_processing: called for dev = 900, inode = 338018
tv_sec = 3986f98b, tv_usec = 639c5.
Current oplocks_open (exclusive = 1, levelII = 0)
[2000/08/01 18:23:39, 3] smbd/process.c:process_smb(618)
Transaction 244 of length 45
[2000/08/01 18:23:39, 3] smbd/process.c:switch_message(448)
switch message SMBclose (pid 1511)
---
After the 4 tries, it starts reading at 18:23:41, one second later
--
[2000/08/01 18:23:41, 3] smbd/process.c:switch_message(448)
switch message SMBreadX (pid 1511)
[2000/08/01 18:23:41, 3] smbd/reply.c:reply_read_and_X(2322)
readX fnum=4401 min=61440 max=61440 nread=61440
[2000/08/01 18:23:41, 3] smbd/process.c:process_smb(618)
Transaction 255 of length 63
[2000/08/01 18:23:41, 3] smbd/process.c:switch_message(448)
switch message SMBreadX (pid 1511)
---
It transfers in a pattern I don't happen to grok:
---
[2000/08/01 18:23:41, 3] smbd/process.c:process_smb(618)
Transaction 257 of length 63
[2000/08/01 18:23:41, 3] smbd/process.c:switch_message(448)
switch message SMBreadX (pid 1511)
[2000/08/01 18:23:41, 3] smbd/reply.c:reply_read_and_X(2322)
readX fnum=4401 min=61440 max=61440 nread=61440
[2000/08/01 18:23:41, 3] smbd/process.c:process_smb(618)
Transaction 258 of length 63
[2000/08/01 18:23:41, 3] smbd/process.c:switch_message(448)
switch message SMBreadX (pid 1511)
[2000/08/01 18:23:41, 3] smbd/reply.c:reply_read_and_X(2322)
readX fnum=4401 min=16384 max=16384 nread=16384
[2000/08/01 18:23:42, 3] smbd/process.c:process_smb(618)
Transaction 259 of length 63
[2000/08/01 18:23:42, 3] smbd/process.c:switch_message(448)
switch message SMBreadX (pid 1511)
[2000/08/01 18:23:42, 3] smbd/reply.c:reply_read_and_X(2322)
readX fnum=4401 min=45056 max=45056 nread=45056
[2000/08/01 18:23:42, 3] smbd/process.c:process_smb(618)
Transaction 260 of length 63
[2000/08/01 18:23:42, 3] smbd/process.c:switch_message(448)
switch message SMBreadX (pid 1511)
[2000/08/01 18:23:42, 3] smbd/reply.c:reply_read_and_X(2322)
readX fnum=4401 min=61440 max=61440 nread=61440
--
Anyone know if this indicates a problem?
It **looks** like its restarting, but there isn't enough
info to tell me...
NT 4.0 is similar, but the start value keeps increasing,
which isn't a threatening (;-))
--
[2000/08/01 18:19:08, 3] smbd/reply.c:reply_readbraw(2112)
readbraw fnum=4730 start=917504 max=65520 min=0 nread=65520
[2000/08/01 18:19:08, 3] smbd/process.c:process_smb(618)
Transaction 154 of length 49
[2000/08/01 18:19:08, 3] smbd/process.c:switch_message(448)
switch message SMBread (pid 1435)
[2000/08/01 18:19:08, 3] smbd/reply.c:reply_read(2258)
read fnum=4730 num=16 nread=16
[2000/08/01 18:19:08, 3] smbd/process.c:process_smb(618)
Transaction 155 of length 55
[2000/08/01 18:19:08, 3] smbd/process.c:switch_message(448)
switch message SMBreadbraw (pid 1435)
[2000/08/01 18:19:08, 3] smbd/reply.c:reply_readbraw(2112)
readbraw fnum=4730 start=983040 max=65520 min=0 nread=65520
---
Windows 2000 finishes up at 18:27:47, while NT does many
more pages of read-raws, but ends at 18:19:55
---
[2000/08/01 18:27:40, 2] smbd/server.c:exit_server(408)
Closing connections
[2000/08/01 18:27:40, 1] smbd/service.c:close_cnum(583)
infernix (192.168.0.17) closed connection to service mp3
[2000/08/01 , 2] smbd/server.c:exit_server(408)
Closing connections
[2000/08/01 18:19:55, 1] smbd/service.c:close_cnum(583)
infernix (192.168.0.21) closed connection to service mp3
win2k has taken 4 minutes 1 second,
NT 4.0 only 47 seconds to get here.
---
Conclusion: win2k is slow, but I don't yet know why. Anyone here
able to comment?
----------------------------------------------------------------------------
-
All this has not helped much yet. I really think that there is a serious
problem with either how Samba talks to Windows 2000 or how Windows 2000
talks to Samba (which might still be solvable on just the client or just the
server).
I didn't really mind that there was no solid solution yet, but now that I am
experiencing the same slow transfers at work and on my freshly installed
server, I am beginning to wonder what on earth is going on here. Regarding
my smb.conf, here are the options which I think might be relevant:
[global]
socket options = TCP_NODELAY
# using any of IPTOS_NODELAY SO_SNDBUF=8192 SO_RCVBUF=8192 didnt have any
effect.
[mp3]
fstype = "FAT"
oplocks = true
level2 oplocks = true
I have plenty options to test further, by either using tcpdump or more log
dumps. The log dumps are available at
http://www.infernix.nl/samba/sambalogs.infernix.tgz if you need more info.
Please, try to look further into this. I have no idea how or why this is
happening, but for me it has grown out to be a real problem, since we are
planning a migration to Windows 2000 clients at work, and i _really_ can't
tell my boss that this is all the speed we can expect ;(
Thank you in advance.
Yours sincerely,
infernix
