This is on 32 bit x86 on a Dell 1950 After mouting a cifs share we have 5 second hiccups. Typical log output when doing a simple "ls /mnt": Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: For smb_command 50 Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: Sending smb: total_len 118 Sep 4 16:21:43 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate (xid = 258) rc = 0 Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: CIFS VFS: in cifs_lookup as Xid: 263 with uid: 0 Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: parent inode = 0xf58d2e60 name is: AutoWire.bmp and dentry = 0xf5adb63c Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: NULL inode in lookup Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: Full path: \AutoWire.bmp inode = 0x(null) Sep 4 16:21:43 rd-spare kernel: fs/cifs/inode.c: Getting info on \AutoWire.bmp Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: For smb_command 50 Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: Sending smb: total_len 104 ---- 5 second hiccup Sep 4 16:21:48 rd-spare kernel: fs/cifs/connect.c: rfc1002 length 0xce Sep 4 16:21:48 rd-spare kernel: fs/cifs/connect.c: rfc1002 length 0xc0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: inode 0xf5876518 old_time=26000 new_time=32751 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: cifs_revalidate - inode unchanged Sep 4 16:21:48 rd-spare kernel: fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 264 with uid: 0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 264) rc = 0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate (xid = 262) rc = 0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: in cifs_revalidate as Xid: 265 with uid: 0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: Revalidate: \Akamai Headsets.doc inode 0xf5876518 count 2 dentry: 0xf5ada8d0 d_time 260 00 jiffies 32751 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate (xid = 265) rc = 0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: in cifs_revalidate as Xid: 266 with uid: 0 Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: Revalidate: \Akamai Headsets.doc inode 0xf5876518 count 2 dentry: 0xf5ada8d0 d_time 260 00 jiffies 32751 This is happening intermittently on a variety of hosts. cat /proc/fs/cifs/DebugData Display Internal CIFS Data Structures for Debugging --------------------------------------------------- CIFS Version 1.60 Active VFS Requests: 2 Servers: 1) Name: 10.2.4.64 Domain: W2K Uses: 1 OS: Windows Server 2003 R2 3790 Service Pack 2 NOS: Windows Server 2003 R2 5.2 Capability: 0x1f3fd SMB session status: 1 TCP status: 1 Local Users To Server: 1 SecMode: 0x3 Req On Wire: 2 Shares: 1) \\chiprodfs2\company Mounts: 1 Type: NTFS DevInfo: 0x20 Attributes: 0x700ff PathComponentMax: 255 Status: 0x1 type: DISK MIDs: State: 2 com: 50 pid: 5951 tsk: f756d1b0 mid 277 State: 2 com: 50 pid: 6044 tsk: f69d4760 mid 278 cat /proc/fs/cifs/Stats Resources in use CIFS Session: 1 Share (unique mount targets): 1 SMB Request/Response Buffer: 5 Pool size: 5 SMB Small Req/Resp Buffer: 1 Pool size: 30 Operations (MIDs): 2 0 session 0 share reconnects Total vfs operations: 525 maximum at one time: 3 1) \\chiprodfs2\company SMBs: 305 Oplock Breaks: 0 Reads: 0 Bytes: 0 Writes: 0 Bytes: 0 Flushes: 0 Locks: 0 HardLinks: 0 Symlinks: 0 Opens: 0 Closes: 0 Deletes: 0 Posix Opens: 0 Posix Mkdirs: 0 Mkdirs: 0 Rmdirs: 0 Renames: 0 T2 Renames 0 FindFirst: 2 FNext 0 FClose 0 What is this ???
On Fri, 4 Sep 2009 12:27:35 -0400 (EDT) Christoph Lameter <cl at linux-foundation.org> wrote:> This is on 32 bit x86 on a Dell 1950 > > After mouting a cifs share we have 5 second hiccups. Typical log output > when doing a simple "ls /mnt": > > Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: For smb_command 50 > Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: Sending smb: > total_len 118 > Sep 4 16:21:43 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: leaving > cifs_revalidate (xid = 258) rc = 0 > Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: CIFS VFS: in cifs_lookup > as Xid: 263 with uid: 0 > Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: parent inode = 0xf58d2e60 > name is: AutoWire.bmp and dentry = 0xf5adb63c > Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: NULL inode in lookup > Sep 4 16:21:43 rd-spare kernel: fs/cifs/dir.c: Full path: \AutoWire.bmp > inode = 0x(null) > Sep 4 16:21:43 rd-spare kernel: fs/cifs/inode.c: Getting info on \AutoWire.bmp > Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: For smb_command 50 > Sep 4 16:21:43 rd-spare kernel: fs/cifs/transport.c: Sending smb: total_len 104 > > ---- 5 second hiccup > > Sep 4 16:21:48 rd-spare kernel: fs/cifs/connect.c: rfc1002 length 0xce > Sep 4 16:21:48 rd-spare kernel: fs/cifs/connect.c: rfc1002 length 0xc0(adding linux-cifs-client mailing list) It looks like it's just taking 5s for the server to respond here. Do you happen to have a wire capture of one of these events? That may tell us more than cifsFYI info...> Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: inode 0xf5876518 old_time=26000 new_time=32751 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: cifs_revalidate - inode unchanged > Sep 4 16:21:48 rd-spare kernel: fs/cifs/file.c: CIFS VFS: in cifs_writepages as Xid: 264 with uid: 0 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/file.c: CIFS VFS: leaving cifs_writepages (xid = 264) rc = 0 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate (xid = 262) rc = 0 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: in cifs_revalidate as Xid: 265 with uid: 0 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: Revalidate: \Akamai Headsets.doc inode 0xf5876518 count 2 dentry: 0xf5ada8d0 d_time 260 > 00 jiffies 32751 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate (xid = 265) rc = 0 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: CIFS VFS: in cifs_revalidate as Xid: 266 with uid: 0 > Sep 4 16:21:48 rd-spare kernel: fs/cifs/inode.c: Revalidate: \Akamai Headsets.doc inode 0xf5876518 count 2 dentry: 0xf5ada8d0 d_time 260 > 00 jiffies 32751 > > > This is happening intermittently on a variety of hosts. > > cat /proc/fs/cifs/DebugData > > Display Internal CIFS Data Structures for Debugging > --------------------------------------------------- > CIFS Version 1.60 > Active VFS Requests: 2 > Servers: > 1) Name: 10.2.4.64 Domain: W2K Uses: 1 OS: Windows Server 2003 R2 3790 > Service Pack 2 > NOS: Windows Server 2003 R2 5.2 Capability: 0x1f3fd > SMB session status: 1 TCP status: 1 > Local Users To Server: 1 SecMode: 0x3 Req On Wire: 2 > Shares: > 1) \\chiprodfs2\company Mounts: 1 Type: NTFS DevInfo: 0x20 > Attributes: 0x700ff > PathComponentMax: 255 Status: 0x1 type: DISK > > MIDs: > State: 2 com: 50 pid: 5951 tsk: f756d1b0 mid 277 > State: 2 com: 50 pid: 6044 tsk: f69d4760 mid 278 > > cat /proc/fs/cifs/Stats > > Resources in use > CIFS Session: 1 > Share (unique mount targets): 1 > SMB Request/Response Buffer: 5 Pool size: 5 > SMB Small Req/Resp Buffer: 1 Pool size: 30 > Operations (MIDs): 2 > > 0 session 0 share reconnects > Total vfs operations: 525 maximum at one time: 3 > > 1) \\chiprodfs2\company > SMBs: 305 Oplock Breaks: 0 > Reads: 0 Bytes: 0 > Writes: 0 Bytes: 0 > Flushes: 0 > Locks: 0 HardLinks: 0 Symlinks: 0 > Opens: 0 Closes: 0 Deletes: 0 > Posix Opens: 0 Posix Mkdirs: 0 > Mkdirs: 0 Rmdirs: 0 > Renames: 0 T2 Renames 0 > FindFirst: 2 FNext 0 FClose 0 > > > What is this ??? > > -- > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in > the body of a message to majordomo at vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Please read the FAQ at http://www.tux.org/lkml/ >-- Jeff Layton <jlayton at redhat.com>
On Wed, 9 Sep 2009 17:27:57 -0400 (EDT) Christoph Lameter <cl at linux-foundation.org> wrote:> On Wed, 9 Sep 2009, Jeff Layton wrote: > > > That sounds rather strange. Maybe we do have a bug of some sort? The > > thing to do might be to get a binary capture of the 32-bit traffic > > around the time of the stalls. We could then inspect the packets and > > see whether we have something wrong in there. > > Capture attached.Well, I can see the delays in the capture, but the snarflen for the capture is a little too small to tell much else. Can you redo the capture with a larger snarflen (maybe -s 512 or so)? Also, were you able to tell anything from a server-side capture? Is the server issuing oplock breaks at those times? Cheers, Jeff
On Wed, 9 Sep 2009, Jeff Layton wrote:> Well, I can see the delays in the capture, but the snarflen for the > capture is a little too small to tell much else. Can you redo the > capture with a larger snarflen (maybe -s 512 or so)?-s 1000 version attached.> Also, were you able to tell anything from a server-side capture? Is the > server issuing oplock breaks at those times?Thats a pretty busy system. They have not gotten around to do any logging on that end.
Apparently Analagous Threads
- CIFS mount problems
- Assistance needed on using mount.smbfs (cifs) to authenticate to samba server with encrypt passwords = No.
- Still can't mount Samba shares from other Samba server
- System freeze if mount cifs share with option "hard", and samba server is not available
- Question about mount.cifs and smbclient