David Landgren
2005-Mar-02 18:31 UTC
[Samba] Still having trouble with slow opening of printer properties
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