Good news and bad news:
I've got comparative logs for win2k vs NT 4.0, and win2k is
doing things **very** differently and as much as 8.5 times slower.
The bad news is that the cause of problem hasn't jumped out at me!
Windows 2000 takes 4 minutes 29 seconds to read a file that NT 4.0
reads in 1 minute 10 seconds.
We've narrowed it down to Samba (ftp is fine) and eliminated
obvious hardware/networking problems, so I'm now sitting here
in filemerge (the Sun visual diff) with snippits of two smbd logs...
which I'm about to inflict on you!
>From Win2k
----------
[2000/08/01 18:23:11, 3] smbd/reply.c:reply_sesssetup_and_X(805)
Domain=[INFERNIX] NativeOS=[Windows 2000 2195] NativeLanMan=[Windows
2000 5.0]
From NT 4.0
-----------
[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?
[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
infernex2 is nt 4.0
[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-live_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?
--dave