[Samba] Still having trouble with slow opening of printer properties

Wed Mar 2 18:31:12 GMT 2005

List,

I asked a while back about problems with very slow openings of printer
properties windows. This afternoon our main internet link was upgraded
to 6Mb (symmetric) and so I thought I might see some improvements in
response.

But no change. I really don't think it's the pipe that's at fault,
there's something wrong with my samba configuration. When I open the
properties of a printer, I see the following lines in the log trickle
by, always pausing at the line send_file_readX

[2005/03/02 19:16:09, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:09, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:09, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:09, 3] smbd/process.c:process_smb(1092)
  Transaction 3387 of length 63
[2005/03/02 19:16:09, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:09, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:09, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:09, 3] smbd/process.c:process_smb(1092)
  Transaction 3388 of length 63
[2005/03/02 19:16:09, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:09, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:09, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:09, 3] smbd/process.c:process_smb(1092)
  Transaction 3389 of length 63
[2005/03/02 19:16:09, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:09, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:09, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3390 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3391 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3392 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3393 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3394 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3395 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3396 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256
[2005/03/02 19:16:10, 3] smbd/process.c:process_smb(1092)
  Transaction 3397 of length 63
[2005/03/02 19:16:10, 3] smbd/process.c:switch_message(887)
  switch message SMBreadX (pid 6856) conn 0x839a388
[2005/03/02 19:16:10, 3] smbd/sec_ctx.c:set_sec_ctx(288)
  setting sec ctx (0, 103) - sec_ctx_stack_ndx = 0
[2005/03/02 19:16:10, 3] smbd/reply.c:send_file_readX(2154)
  send_file_readX fnum=7066 max=256 nread=256

My globals section looks like

[global]
        unix charset = ISO8859-1
        workgroup = foo
        server string = %h Server
        interfaces = eth0, lo
        bind interfaces only = Yes
        passdb backend = ldapsam:ldap://localhost
        log level = 2
        log file = /var/log/samba/log.%m
        max log size = 4000
        name resolve order = lmhosts wins bcast host
        time server = Yes
        socket options = TCP_NODELAY IPTOS_LOWDELAY SO_KEEPALIVE
SO_RCVBUF=8192 SO_SNDBUF=8192
        printcap cache time = 60
        printcap name = /var/run/cups/printcap
        logon script = login\%U.bat
        logon path =
        logon drive = H:
        logon home = \\%M\%U
        domain logons = Yes
        domain master = No
        dns proxy = No
        wins proxy = Yes
        wins server = 172.17.0.8
        ldap admin dn = cn=Manager,dc=bpinet,dc=com
        ldap group suffix = ou=Group
        ldap machine suffix = ou=Computers
        ldap passwd sync = Yes
        ldap replication sleep = 5000
        ldap suffix = dc=foo,dc=com
        ldap ssl = no
        ldap user suffix = ou=People
        admin users = root, @domadmin
        printer admin = @prtadmin
        printing = cups

I really don't know if the socket options represent Best Practices
these days or not. I have added read raw = yes and write raw = yes
with no visible effect observable.

A one-second tcpdump shows the following activity

19:24:37.076775 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2574:2650(76) ack 12047 win 63377
19:24:37.077323 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12047:12135(88) ack 2650 win 6320
19:24:37.153552 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2650:2726(76) ack 12135 win 63289
19:24:37.154069 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12135:12223(88) ack 2726 win 6320
19:24:37.230150 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2726:2789(63) ack 12223 win 63201
19:24:37.230696 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12223:12326(103) ack 2789 win 6320
19:24:37.308350 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2789:2852(63) ack 12326 win 64464
19:24:37.308762 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12326:12429(103) ack 2852 win 6320
19:24:37.386703 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2852:2915(63) ack 12429 win 64361
19:24:37.387226 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12429:12532(103) ack 2915 win 6320
19:24:37.464865 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2915:2978(63) ack 12532 win 64258
19:24:37.465280 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12532:12635(103) ack 2978 win 6320
19:24:37.543985 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
2978:3041(63) ack 12635 win 64155
19:24:37.544451 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12635:12738(103) ack 3041 win 6320
19:24:37.623606 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
3041:3104(63) ack 12738 win 64052
19:24:37.624127 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
12738:13313(575) ack 3104 win 6320
19:24:37.716564 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
3104:3167(63) ack 13313 win 63477
19:24:37.717030 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
13313:13888(575) ack 3167 win 6320
19:24:37.810234 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
3167:3230(63) ack 13888 win 64464
19:24:37.810907 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
13888:14463(575) ack 3230 win 6320
19:24:37.904402 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
3230:3293(63) ack 14463 win 63889
19:24:37.904881 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
14463:15038(575) ack 3293 win 6320
19:24:37.998721 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
3293:3356(63) ack 15038 win 63314
19:24:37.999225 IP s-ncy.foo.com.microsoft-ds > david.foo.com.2725: P
15038:15613(575) ack 3356 win 6320
19:24:38.093109 IP david.foo.com.2725 > s-ncy.foo.com.microsoft-ds: P
3356:3419(63) ack 15613 win 64464

This seems rather excessive, and I'm wondering if there's a problem
with fragmentation, if I have to fiddle with the MTU, or something
like that. The router for the VPN is configured with an MSS of 1304,
and I wonder if I have to adjust something in Samba as a consequence
to that.

If anyone has an idea, I'm all ears.

Thanks,
David