Samba 2.0.7 & Transfer speeds

Wed Aug 2 15:17:26 GMT 2000

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