Hello together,
please help!!!
I made some more traces and test today.
The logon process from an Windows XP machines needs aprox. 7 Minutes. Then the machine is able to browse through the domain, can open shares e.g.
Wenn I copy a file from a share there happends nothing for round about 1 minute - then windows means that the File could not be copied because the sourcefile or directory could not be read.
In the meantime Strace shows what happens within the smb-process:
After the Strace you can find a tcpdump - but for both, I´m not technical enough to read in detail.
I would be very appreciated to get help from this community-
Regards, Heiko
--------
lx2-rvmo-02:~# cat /tmp/strace.log
2419 select(25, [20 23 24], NULL, NULL, {48, 830000}) = 1 (in [23], left {35, 840000})
2419 read(23, 0x40510008, 4) = -1 ECONNRESET (Connection reset by peer)
2419 time(NULL) = 1095364795
2419 time([1095364795]) = 1095364795
2419 getpid() = 2419
2419 rt_sigaction(SIGPIPE, {0x40262be0, [], 0x4000000}, {SIG_DFL}, 8) = 0
2419 send(4, "<27>Sep 16 21:59:55 smbd[2419]: "..., 95, 0) = 95
2419 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 0] lib/uti"..., 63) = 63
2419 time([1095364795]) = 1095364795
2419 getpid() = 2419
2419 rt_sigaction(SIGPIPE, {0x40262be0, [], 0x4000000}, {SIG_DFL}, 8) = 0
2419 send(4, "<27>Sep 16 21:59:55 smbd[2419]: "..., 105, 0) = 105
2419 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
2419 geteuid32() = 0
2419 write(27, " read_socket_data: recv failure"..., 73) = 73
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/pr"..., 65) = 65
2419 geteuid32() = 0
2419 write(27, " timeout_processing: receive_sm"..., 75) = 75
2419 munmap(0x40505000, 696) = 0
2419 close(14) = 0
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/se"..., 57) = 57
2419 geteuid32() = 0
2419 write(27, " setting sec ctx (0, 0) - sec_c"..., 49) = 49
2419 geteuid32() = 0
2419 getegid32() = 5021
2419 setresgid32(0xffffffff, 0, 0xffffffff) = 0
2419 getegid32() = 0
2419 getegid32() = 0
2419 setgroups32(0, 0) = 0
2419 setresgid32(0xffffffff, 0, 0xffffffff) = 0
2419 getegid32() = 0
2419 setresuid32(0, 0, 0xffffffff) = 0
2419 geteuid32() = 0
2419 time(NULL) = 1095364795
2419 time([1095364795]) = 1095364795
2419 getpid() = 2419
2419 rt_sigaction(SIGPIPE, {0x40262be0, [], 0x4000000}, {SIG_DFL}, 8) = 0
2419 send(4, "<29>Sep 16 21:59:55 smbd[2419]: "..., 88, 0) = 88
2419 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 2] smbd/se"..., 56) = 56
2419 time([1095364795]) = 1095364795
2419 getpid() = 2419
2419 rt_sigaction(SIGPIPE, {0x40262be0, [], 0x4000000}, {SIG_DFL}, 8) = 0
2419 send(4, "<29>Sep 16 21:59:55 smbd[2419]: "..., 54, 0) = 54
2419 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
2419 geteuid32() = 0
2419 write(27, " Closing connections\n", 22) = 22
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/se"..., 57) = 57
2419 geteuid32() = 0
2419 write(27, " setting sec ctx (0, 0) - sec_c"..., 49) = 49
2419 geteuid32() = 0
2419 getegid32() = 0
2419 setgroups32(0, 0) = 0
2419 setresgid32(0xffffffff, 0, 0xffffffff) = 0
2419 getegid32() = 0
2419 setresuid32(0, 0, 0xffffffff) = 0
2419 geteuid32() = 0
2419 time(NULL) = 1095364795
2419 time([1095364795]) = 1095364795
2419 getpid() = 2419
2419 rt_sigaction(SIGPIPE, {0x40262be0, [], 0x4000000}, {SIG_DFL}, 8) = 0
2419 send(4, "<28>Sep 16 21:59:55 smbd[2419]: "..., 88, 0) = 88
2419 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 1] smbd/se"..., 56) = 56
2419 time([1095364795]) = 1095364795
2419 getpid() = 2419
2419 rt_sigaction(SIGPIPE, {0x40262be0, [], 0x4000000}, {SIG_DFL}, 8) = 0
2419 send(4, "<28>Sep 16 21:59:55 smbd[2419]: "..., 96, 0) = 96
2419 rt_sigaction(SIGPIPE, {SIG_DFL}, NULL, 8) = 0
2419 geteuid32() = 0
2419 write(27, " rvmo1018 (192.168.1.54) closed"..., 64) = 64
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/co"..., 64) = 64
2419 geteuid32() = 0
2419 write(27, " Yielding connection to NETLOGO"..., 34) = 34
2419 fcntl64(10, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=352, len=1}, 0xbffff170) = 0
2419 fcntl64(10, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=1944, len=1}, 0xbffff160) = 0
2419 fcntl64(10, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=1944, len=1}, 0xbffff160) = 0
2419 fcntl64(10, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=164, len=1}, 0xbffff0d0) = 0
2419 fcntl64(10, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=164, len=1}, 0xbffff0d0) = 0
2419 fcntl64(10, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=352, len=1}, 0xbffff1b0) = 0
2419 chdir("/") = 0
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/se"..., 57) = 57
2419 geteuid32() = 0
2419 write(27, " setting sec ctx (0, 0) - sec_c"..., 49) = 49
2419 geteuid32() = 0
2419 getegid32() = 0
2419 setgroups32(0, 0) = 0
2419 setresgid32(0xffffffff, 0, 0xffffffff) = 0
2419 getegid32() = 0
2419 setresuid32(0, 0, 0xffffffff) = 0
2419 geteuid32() = 0
2419 fcntl64(9, F_SETLKW64, {type=F_RDLCK, whence=SEEK_SET, start=332, len=1}, 0xbffff480) = 0
2419 fcntl64(9, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=332, len=1}, 0xbffff4c0) = 0
2419 fcntl64(9, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=332, len=1}, 0xbffff480) = 0
2419 fcntl64(9, F_SETLK64, {type=F_WRLCK, whence=SEEK_SET, start=696, len=1}, 0xbffff470) = 0
2419 fcntl64(9, F_SETLK64, {type=F_UNLCK, whence=SEEK_SET, start=696, len=1}, 0xbffff470) = 0
2419 fcntl64(9, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=164, len=1}, 0xbffff3e0) = 0
2419 fcntl64(9, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=164, len=1}, 0xbffff3e0) = 0
2419 fcntl64(9, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=332, len=1}, 0xbffff4c0) = 0
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/co"..., 64) = 64
2419 geteuid32() = 0
2419 write(27, " Yielding connection to \n", 26) = 26
2419 fcntl64(10, F_SETLKW64, {type=F_WRLCK, whence=SEEK_SET, start=340, len=1}, 0xbffff9d0) = 0
2419 fcntl64(10, F_SETLKW64, {type=F_UNLCK, whence=SEEK_SET, start=340, len=1}, 0xbffff9d0) = 0
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/co"..., 64) = 64
2419 geteuid32() = 0
2419 write(27, " yield_connection: tdb_delete f"..., 82) = 82
2419 time(NULL) = 1095364795
2419 select(25, [20 24], NULL, NULL, {0, 1000}) = 0 (Timeout)
2419 munmap(0x40501000, 696) = 0
2419 close(11) = 0
2419 munmap(0x40554000, 8192) = 0
2419 close(12) = 0
2419 time(NULL) = 1095364795
2419 geteuid32() = 0
2419 write(27, "[2004/09/16 21:59:55, 3] smbd/se"..., 56) = 56
2419 geteuid32() = 0
2419 write(27, " Server exit (normal exit)\n", 28) = 28
2419 semget(IPC_PRIVATE, 0, 0) = -1 ENOSYS (Function not implemented)
2419 _exit(0) = ?
The tcpdump is attached to this mail. ------------------------
Heiko Boeringer wrote:
Hello together,
since today morning I have an massive performance issue with samba 2.0.6-3 (Debian - Testing-Tree) in my samba production environment.
Samba responds very slowly within the logon process (2-3 Minutes for each line in the netlogon.cmd). Later during normal operations opening from files works very slowly and often breaks connection.
There is no cpu or memory load on the system. Also the network traffic is low. The network connections between the server and the clients is fine. FTP Transfer works with high speed.
The last thing I´ve done is to install the nagios-mysql package (debian, unstable tree). But I´m not sure if there are dependencies.
I do all the things from DIAGNOSIS.TXT and many others - but I have no mor idea where !
Does anybody has an idea what´s going wrong here. I have atteched a the log.smbd, log.nmdd and from an machine - showing the logon process . Hope that helps by analyzing the issue.
Here some informations regarding the system.
I would be very thankful for all help & support
regards, Heiko
Systemconfiguration ################################################################ - Debian 3.0 (Woody) - Samba with an the samba3.0.6-3.deb from the testing tree (but happends with all other versions too) - Configured als PDC with SMBPASSWD Authentification (no windbind, kerberos, ldap..) - Client: Windows XP Germany, SP1
TOP (means the machine hs nothing to do) ################################################################# 99 processes: 98 sleeping, 1 running, 0 zombie, 0 stopped CPU states: 0.4% user, 0.4% system, 0.0% nice, 99.2% idle Mem: 516100K total, 510616K used, 5484K free, 69040K buffers Swap: 385552K total, 1652K used, 383900K free, 376280K cached
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND 7181 netinsta 16 0 3620 3616 3268 S 0.3 0.7 0:00 smbd 235 root 10 0 592 592 512 S 0.1 0.1 1:37 syslogd 7035 root 12 0 1028 1028 804 R 0.1 0.1 0:00 top 1 root 8 0 496 492 448 S 0.0 0.0 0:00 init
SMB.CONF ################################################################ [global] unix charset = ISO8859-1 display charset = ISO8859-1 workgroup = RVMO.DE server string = %h obey pam restrictions = Yes # unix password sync = false # encrypt passwords = yes passwd program = /usr/bin/passwd %u passwd chat = *Enter\snew\sUNIX\spassword:* %n\n *Retype\snew\sUNIX\spassword:* %n\n . #For verbose debug: 10 #For Standard logging: 3 log level = 3 syslog = 3 # End logging section log file = /var/log/samba/log.%m max log size = 1000 logon script = netlogon.cmd logon path = logon drive = L: logon home = domain logons = Yes # wins support = Yes os level = 40 preferred master = Yes domain master = Yes dns proxy = No ldap ssl = no panic action = /usr/share/samba/panic-action %d idmap uid = 100-20000 idmap gid = 100-20000 admin users = @smb-o-admin-it hosts allow = 127.0.0.1, 192.168.1.0/255.255.0.0 printing = cups printer admin = @smb-o-basisarbeitsplatz printcap name = /etc/printcap.cups # print command = lpr-cups -P %p -o raw %s -r load printers = Yes use client driver = No
[print$] comment = Samba printer drivers path = /home/samba/print valid users = +smb-o-basisarbeitsplatz admin users = @smb-o-admin-it read list = @smb-o-basisarbeitsplatz write list = @smb-o-admin-it force user = nobody force group = nogroup # guest ok = Yes writeable = Yes
[printers] comment = All Printers path = /var/spool/samba valid users = +smb-o-basisarbeitsplatz admin users = @smb-o-admin-it read list = @smb-o-basisarbeitsplatz write list = @smb-o-basisarbeitsplatz force user = nobody force group = nogroup printer admin = @smb-o-basisarbeitsplatz create mask = 0700 printable = Yes browsable = Yes public = Yes guest ok = Yes writeable = Yes
[homes] comment = Home Directories read only = No create mask = 0700 directory mask = 0700 browseable = No csc policy = disable
[NETLOGON] comment = NETLOGON auf LX2-RVMO-02 path = /home/netlogon admin users = @smb-o-admin-it write list = @smb-o-admin-it force user = root force group = smb-o-admin-it guest ok = Yes csc policy = disable
########################################################################
here comes an syslog extract from an example filetransfer (copying from \\server\public to local desktop. Transfer ends with windows message "File could not be copied. From Sourcefile or from Sourcedisk could not be read"
############################################################
[2004/09/15 22:01:57, 5] auth/auth_util.c:debug_nt_user_token(491)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: NT user token of user S-1-5-21-29628934-819234659-1421906636-501
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: contains 6 SIDs
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: SID[ 0]: S-1-5-21-29628934-819234659-1421906636-501
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: SID[ 1]: S-1-5-21-29628934-819234659-1421906636-514
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: SID[ 2]: S-1-1-0
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: SID[ 3]: S-1-5-2
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: SID[ 4]: S-1-5-32-546
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: SID[ 5]: S-1-5-21-29628934-819234659-1421906636-132069
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 5] auth/auth_util.c:debug_unix_user_token(505)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: UNIX token of user 65534
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: Primary group is 65534 and contains 1 supplementary groups
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: Group[ 0]: 65534
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 5] smbd/uid.c:change_to_user(280)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: change_to_user uid=(65534,65534) gid=(0,65534)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 4] smbd/vfs.c:vfs_ChDir(654)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: vfs_ChDir to /tmp
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 4] smbd/nttrans.c:nt_open_pipe(496)
### here starts the interesting thing... ###
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: nt_open_pipe: Opening pipe \browser.
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 3] smbd/error.c:error_packet(129)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: error packet at smbd/nttrans.c(508) cmd=162 (SMBntcreateX) NT_STATUS_OBJECT_NAME_NOT_FOUND
#### connection is crashed... -> Message on the win-box "File could not be copied. From Sourcefile or from Sourcedisk could not be read"
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 5] lib/util.c:show_msg(443)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 5] lib/util.c:show_msg(453)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: size=35
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_com=0xa2
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_rcls=52
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_reh=0
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_err=49152
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_flg=136
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_flg2=51201
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_tid=2
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_pid=1680
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_uid=102
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_mid=19267
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smt_wct=0
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: smb_bcc=0
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 6] lib/util_sock.c:write_socket(449)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: write_socket(23,39)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: [2004/09/15 22:01:57, 6] lib/util_sock.c:write_socket(452)
Sep 15 22:01:57 lx2-rvmo-02 smbd[9780]: write_socket(23,39) wrote 39
Sep 15 22:02:01 lx2-rvmo-02 PAM_unix[10454]: (cron) session opened for user root by (uid=0)
Sep 15 22:02:01 lx2-rvmo-02 /USR/SBIN/CRON[10455]: (root) CMD (test -x /usr/sbin/logcheck && nice -n10 /usr/sbin/logcheck)
Sep 15 22:02:01 lx2-rvmo-02 PAM_unix[10454]: (cron) session closed for user root
Sep 15 22:02:07 lx2-rvmo-02 nmbd[32436]: [2004/09/15 22:02:07, 4] nmbd/nmbd_workgroupdb.c:find_workgroup_on_subnet(162)
Sep 15 22:02:07 lx2-rvmo-02 nmbd[32436]: find_workgroup_on_subnet: workgroup search for RVMO.DE on subnet 192.168.1.2: found.
Sep 15 22:02:07 lx2-rvmo-02 nmbd[32436]: [2004/09/15 22:02:07, 4] nmbd/nmbd_workgroupdb.c:find_workgroup_on_subnet(162)
Sep 15 22:02:07 lx2-rvmo-02 nmbd[32436]: find_workgroup_on_subnet: workgroup search for RVMO.DE on subnet UNICAST_SUBNET: found.
Sep 15 22:02:07 lx2-rvmo-02 nmbd[32436]: [2004/09/15 22:02:07, 4] nmbd/nmbd_workgroupdb.c:find_workgroup_on_subnet(162)
Sep 15 22:02:07 lx2-rvmo-02 nmbd[32436]: find_workgroup_on_subnet: workgroup search for RVMO.DE on subnet UNICAST_SUBNET: found
Attachments (can be delivered directly by mail, are too large ##################################################### - log.nmdb from logon process (logging on from rvmo1018) - log.smdb from logon process (logging on from rvmo1018) - log.rvmo1018 from logon process (logging on from rvmo1018) - syslog from logon process (logging on from rvmo1018)
-- To unsubscribe from this list go to the following URL and read the instructions: http://lists.samba.org/mailman/listinfo/samba
